Subject: combinatorial explosion in elided stack trace

From: Zefram <[email-masked]>
Date: Sun, 5 Jan 2014 23:02:38 +0000

In guile 2.0.9, if an error is signalled in the interpreter, and the
stack contains in a certain position an object whose unabbreviated print
representation is very large, then the process of displaying the stack
trace will take a huge amount of time and memory, pausing in the middle
of output, even though the displayed stack trace doesn't actually show
the object at all.  Test case:

$ cat t6
(define bs (let aaa ((n 100) (v '())) (if (= n 0) v (aaa (- n 1) (cons v v)))))
(write (list bs (error "wibble")))
$ guile-2.0 --no-auto-compile t6
Backtrace:
In ice-9/boot-9.scm:
 157: 11 [catch #t #<catch-closure e6a400> ...]
In unknown file:
   ?: 10 [apply-smob/1 #<catch-closure e6a400>]
In ice-9/boot-9.scm:
  63: 9 [call-with-prompt prompt0 ...]
In ice-9/eval.scm:
 432: 8 [eval # #]
In ice-9/boot-9.scm:
2320: 7 [save-module-excursion #<procedure e9bcc0 at ice-9/boot-9.scm:3961:3 ()>]
3968: 6 [#<procedure e9bcc0 at ice-9/boot-9.scm:3961:3 ()>]
1645: 5 [%start-stack load-stack #<procedure e9c980 at ice-9/boot-9.scm:3957:10 ()>]
1650: 4 [#<procedure e9a060 ()>]
In unknown file:
   ?: 3 [primitive-load "/home/zefram/usr/guile/t6"]
In ice-9/eval.scm:
 387: 2 ^Z
zsh: suspended  guile-2.0 --no-auto-compile t6
$ jobs -l
[1]  + 32574 suspended  guile-2.0 --no-auto-compile t6
$ ps vw 32574
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
32574 pts/5    T      0:36      0     3 2266300 1634556  9.9 guile-2.0 --no-auto-compile t6

With the test's size parameter at 100 as above, there is no realistic
prospect of actually completing generation of the stack trace.  For some
range of values (about 25 on my machine) there will be a noticeable pause,
after which the stack trace completes:

...
 387: 2 [eval # ()]
 387: 1 [eval # ()]
In unknown file:
   ?: 0 [scm-error misc-error #f "~A" ("wibble") #f]

It appears that it's generating the entire print representation of
the object behind the scenes, though it then obviously throws it away.
Experimentation with customising print methods for SRFI-9 record types
shows that the delay and memory usage depend on the print representation
per se, rather than on the amount of structure beneath the object.
(A record-based cons-like type produces similar behaviour to the
cons test when using the default print method that shows the content.
Replacing it with a print method that emits a fixed string and doesn't
recurse eliminates the delay entirely.)

If my test program is run in compiled form (via auto-compilation) then
it doesn't exhibit the pause.  Actually it gets optimised such that the
problem object isn't anywhere near what the stack trace displays, so for
a fair test the program needs to be tweaked.  It can be arranged for the
problem object to be directly mentioned in the stack trace, and there is
still no pause: the object appears in a highly abbreviated form, such as

   2: 1 [vv ((# # # # ...) (# # # # ...) (# # # # ...) (# # # # ...) ...)]

For comparison, guile-1.8 never exhibits this problem.  By default
it doesn't emit a stack trace for a script, but it can be asked to do
so via --debug.  It then behaves like the compiled form of guile-2.0:
there is no delay, and the object is shown in very abbreviated form.

Debian incarnation of this bug report:
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=734132

-zefram