expensive backtraces.

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->write_buf[0]@18960
	$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   |   hanwen@cs.uu.nl   |   http://www.cs.uu.nl/~hanwen 


_______________________________________________
Guile-devel mailing list
Guile-devel@gnu.org
http://mail.gnu.org/mailman/listinfo/guile-devel

Re: expensive backtraces.

[Lynn Winebarger]

On Saturday 15 February 2003 13:41, Han-Wen Nienhuys wrote:
> 
> 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.
>  [...]
> 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.
> 

    There is a standard solution.  First keep track of how deep in the
structure you are and allow (not require) a limit on the recursion depth.
The second is to then notice that lists should be treated like arrays
and not as nested datastructures, and allow a limit on the length of both
of them.  
   If you try to determine both those limits to constrain the actual total
output length, you will find yourself backtracking.
   There's also now an extra bit in cons cells that could be used to tell
if the printer has seen it already.  Or not.  It's not clear some better
use wouldn't come along.

Lynn



_______________________________________________
Guile-devel mailing list
Guile-devel@gnu.org
http://mail.gnu.org/mailman/listinfo/guile-devel