Re: Serious performance issues with 1.9.0

[Andy Wingo]

Hi Martin,

On Fri 17 Jul 2009 19:27, Martin Ward <address@hidden> writes:

> Now here's something totally wierd with Guile 1.8.7:
>
> echo '(load "ALL.scm")(load "prog_to_spec_TEST.scx")(exit)' | /usr/bin/time 
> guile
>
> takes 139 seconds CPU time.
>
> /usr/bin/time guile -l ALL.scm -s prog_to_spec_TEST.scx
>
> takes only 56 seconds CPU time.
>
> You read that right: if I pass the files on the command line
> it takes less than half the time to process, compared to typing "load"
> commands at the prompt, or sending them to standard input.
>
> The same thing happens with Guile 1.9.1:
>
> Echo load commands to stdin: 301 seconds CPU time
> Pass the files on the command line: 150 seconds CPU time.

And pulling up some other numbers you mentioned in another mail:

> Testing prog_to_spec_TEST.scx:
>
> Guile 1.9.1:     260.9 secs
> Guile 1.8.7:     135.9 secs
> Gambit v4.4.4:    88.3 secs
> SCM version 5e5:  29.4 secs
> Hobbit compiled:   1.3 secs

The difference between the two Guile times in both cases is the
lengthier runs use the debugging evaluator, which gives you nice
backtraces among other things.

Guile 1.9.1 is slower than 1.8.7 because the interpreter receives more
"primitive" code -- many of the speed special-cases don't have a chance
to work in 1.9.1.

However the good news, or perhaps just "better" news, is that Guile from
git can compile your code now. Compiling ALL.scm takes a good long time
-- it could be 3 minutes or so, I didn't measure -- but once it's
compiled it loads instantly, and you don't have to compile it again
unless ALL.scm changes. (As Ludovic mentioned, in the future we should
support autocompilation for files passed on the command line.)

Compiling prog_to_spec_TEST takes just a couple of seconds. Running
that, I got:

scheme@(guile-user)> (use-modules (system base compile))
scheme@(guile-user)> (compile-file "/tmp/ALL.scm")
$1 = "/home/wingo/.cache/guile/ccache/1.9/tmp/ALL.scm.go"
scheme@(guile-user)> (load-compiled $1)
scheme@(guile-user)> (compile-file "/tmp/prog_to_spec_TEST.scx")
$2 = "/home/wingo/.cache/guile/ccache/1.9/tmp/prog_to_spec_TEST.scx.go"
scheme@(guile-user)> ,t (load-compiled $2)
 1st test of `Prog_To_Spec'  was OK.
 2nd test of `Prog_To_Spec'  was OK.
 3rd test of `Prog_To_Spec'  was OK.
 4th test of `Prog_To_Spec'  was OK.
 5th test of `Prog_To_Spec'  was OK.
 6th test of `Prog_To_Spec'  was OK.
 7th test of `Prog_To_Spec'  was OK.
 8th test of `Prog_To_Spec'  was OK.
 9th test of `Prog_To_Spec'  was OK.
10th test of `Prog_To_Spec'  was OK.
11th test of `Prog_To_Spec'  was OK.
12th test of `Prog_To_Spec'  was OK.
13th test of `Prog_To_Spec'  was OK.
#t
clock utime stime cutime cstime gctime
30.09 29.64  0.09   0.00   0.00   0.24

So, 30 seconds. Note that that's with full debugging information --
which takes up a fair amount of the 4.5 MB compiled version of ALL.scm.
Also, it's with the debugging version of the VM, which performs many
safety checks. I suspect we could get it faster with the VM, but big
further improvements should involve native code compilation, I think,
and will take some time.

Thanks for the bug report, it found some interesting issues.

Andy
-- 
http://wingolog.org/