expensive backtraces.

[Han-Wen Nienhuys]

Hi there,

On some occasions, printing a backtrace from GUILE takes an
extraordinary amount of time. Example

        blauw:~/usr/src/lilypond$ time lilypond ki.ly
        lstat(/home/hanwen/bin/usr) failed ...
        /home/hanwen/bin/usr: Onbekend bestand of map
        GNU LilyPond 1.7.12
        Now processing: `ki.ly'
        Parsing...Backtrace:
        In ki.ly:
           1: 0* [sequential-music-to-chord-exceptions #]
        In unknown file:
           ?: 1  (letrec (# #) (let* # #))
        In /home/hanwen/usr/src/lilypond/scm/double-plus-new-chord-name.scm:
         337: 2  (let* ((elts #) (alist #)) (filter-list (lambda # #) alist))
         339: 3* [filter-list #<procedure is-req-chord? (m)> ...
         339: 4*  (ly:get-music-property seq (quote elements))

        
/home/hanwen/usr/src/lilypond/scm/double-plus-new-chord-name.scm:339:39: In 
expression (ly:get-music-property seq (quote elements)):
        
/home/hanwen/usr/src/lilypond/scm/double-plus-new-chord-name.scm:339:39: 
Unbound variable: ly:get-music-property

        real    0m9.369s
        user    0m9.200s
        sys     0m0.080s


between printing

        1: 0*

and the rest, is approximately 8 seconds.  I think this is exorbitant
on a 400mhz machine.  When tracing this with GDB, it seems that a lot
of memory is filled and GC-ed again for printing enormous structures,
which are later folded into '#' marks again.

        Now processing: `ki.ly'
        Parsing...Backtrace:
        In ki.ly:
           1: 0* 
        Program received signal SIGINT, Interrupt.
        0x40049023 in scm_i_sweep_card (p=0x40a76ab0, free_list=0xbfffdaf8, 
            seg=0x40a76aa0) at gc-card.c:104
        warning: Source file is more recent than executable.
        (gdb) fin

Lots of "finish"

        st_resize_port (pt=0x83393c0, new_size=18960) at strports.c:109
        warning: Source file is more recent than executable.

        Value returned is $4 = (struct scm_unused_struct *) 0x4041c7f8
        (gdb)  

        0x4007b16a in st_flush (port=0x83bb960) at strports.c:136
        (gdb) p pt->write_buf
        $5 = (
            unsigned char *) 0x83b6ff0 "[sequential-music-to-chord-exceptions 
#<Music Transposed_musicelement = #<Music Sequential_musicorigin = #<location 
ki.ly:61:14>\nelements = (#<Music Simultaneous_musicelements = (#<Music 
Eventduration"...
        (gdb) p pt->write_buf_size
        $6 = 18960
        (gdb) p pt->address@hidden
        $7 = "[sequential-music-to-chord-exceptions #<Music 
Transposed_musicelement = #<Music Sequential_musicorigin = #<location 
ki.ly:61:14>\nelements = (#<Music Simultaneous_musicelements = (#<Music 
Eventduration"...
        (gdb) p pt->write_buf+ 100
        [more enormously long string]

Other than trimming my "print_smob()" routines, does anyone see a
solution to this problem from the GUILE side? Ideally, the printing of
a large structure should be interrupted once the length of its output
exceeds a certain size. It seems that right now, first the entire
object is printed (taking a lot of time), and then all that printout
is replaced by "#" if too large.

In the short-run, it would be nice to mention something about this in
the manual; I'm not sure about the correct wording though.  Maybe
something like:

      One of the uses of the print-method is in printing expressions
      during stack traces.  Therefore, make sure that this method
      prints only a limited amount of data. Excessively long print out
      will be discarded, and will lead to long delays during
      debugging.

-- 
Han-Wen Nienhuys   |   address@hidden   |   http://www.cs.uu.nl/~hanwen