bug#16358: combinatorial explosion in elided stack trace

bug#16358: combinatorial explosion in elided stack trace

[Zefram]

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

bug#16358: combinatorial explosion in elided stack trace

[Andy Wingo]

Hi Zefram,

Thanks for the great report!

I believe this is fixed in v2.1.3.  Reproducing the bug is a little
different there but I think I did get it so that Guile should try to
print out the value.  I don't know if we would be able to fix this in
2.0 though :/  I am closing because I believe it to be fixed, albeit in
the next release series.

Regards,

Andy

On Mon 06 Jan 2014 00:02, Zefram <zefram@fysh.org> writes:

> 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