Serious performance issues with 1.9.0

Serious performance issues with 1.9.0

[Martin Ward]

Running a test program on Guile 1.8.7 takes 100 seconds CPU time.
On Guile 1.9.0 (beta) the same program takes 237 seconds CPU time!

For comparison:

Gambit v4.4.4 takes 60 seconds.
SCM version 5e5 takes 20.7 seconds.
Hobbit compiled code running under SCM takes 1.1 seconds!

There was some talk a few years ago about integrating the Hobbit
compiler with Guile: but nothing seems to have come of it.

I can send you the code if you like (its the FermaT Transformation System
which is released under the GPL) its about 7.7MB of Scheme source,
so I didn't want to include it in this message :-)

-- 
			Martin

martin@gkc.org.uk http://www.cse.dmu.ac.uk/~mward/ Erdos number: 4
G.K.Chesterton web site: http://www.cse.dmu.ac.uk/~mward/gkc/

Re: Serious performance issues with 1.9.0

[Neil Jerram]

Martin Ward <martin@gkc.org.uk> writes:

> Running a test program on Guile 1.8.7 takes 100 seconds CPU time.
> On Guile 1.9.0 (beta) the same program takes 237 seconds CPU time!

I wonder if that's because the code is being auto-compiled?  Do you
get a better result if you set environment variable GUILE_AUTO_COMPILE
to 0 ?

> For comparison:
>
> Gambit v4.4.4 takes 60 seconds.
> SCM version 5e5 takes 20.7 seconds.

We're working on it!

> Hobbit compiled code running under SCM takes 1.1 seconds!
>
> There was some talk a few years ago about integrating the Hobbit
> compiler with Guile: but nothing seems to have come of it.

No, that line of work fizzled out.  It may come back again in the more
general compilation and language transformation framework that we now
have.

Regards,
        Neil

Re: Serious performance issues with 1.9.0

[Neil Jerram]

Neil Jerram <neil@ossau.uklinux.net> writes:

> Martin Ward <martin@gkc.org.uk> writes:
>
>> Running a test program on Guile 1.8.7 takes 100 seconds CPU time.
>> On Guile 1.9.0 (beta) the same program takes 237 seconds CPU time!
>
> I wonder if that's because the code is being auto-compiled?  Do you
> get a better result if you set environment variable GUILE_AUTO_COMPILE
> to 0 ?

Or if you run your program a second time?  (In which case it should
pick up and use the compiled code.)

     Neil

Re: Serious performance issues with 1.9.0

[Martin Ward]

On Thursday 16 Jul 2009 08:59, Neil Jerram wrote:
> Martin Ward <martin@gkc.org.uk> writes:
> > Running a test program on Guile 1.8.7 takes 100 seconds CPU time.
> > On Guile 1.9.0 (beta) the same program takes 237 seconds CPU time!
>
> I wonder if that's because the code is being auto-compiled?  Do you
> get a better result if you set environment variable GUILE_AUTO_COMPILE
> to 0 ?

This is with Guile 1.9.1, running on a slightly different program:

GUILE_AUTO_COMPILE 1 takes 204 seconds
GUILE_AUTO_COMPILE 0 takes 213 seconds

The only file in ~/.cache is guile-1.9.1/test-suite/lib.scm.go

Guile 1.8.7 takes 81 seconds on this example.

SCM 5e5 takes 18 seconds.
Hobbit-compiled code: less than 1 second.

> > For comparison:
> >
> > Gambit v4.4.4 takes 60 seconds.
> > SCM version 5e5 takes 20.7 seconds.
>
> We're working on it!
>
> > Hobbit compiled code running under SCM takes 1.1 seconds!
> >
> > There was some talk a few years ago about integrating the Hobbit
> > compiler with Guile: but nothing seems to have come of it.
>
> No, that line of work fizzled out.  It may come back again in the more
> general compilation and language transformation framework that we now
> have.

If guile is intended to be a "proper" language: suitable for production use
and not just for playing with toy programs, then a decent compiler
is essential.

I had to hack hobbit just to get separate compilation to work!

-- 
			Martin

martin@gkc.org.uk http://www.cse.dmu.ac.uk/~mward/ Erdos number: 4
G.K.Chesterton web site: http://www.cse.dmu.ac.uk/~mward/gkc/

Re: Serious performance issues with 1.9.0

[Ludovic Courtès]

Hi,

Martin Ward <martin@gkc.org.uk> writes:

> The only file in ~/.cache is guile-1.9.1/test-suite/lib.scm.go

Then there must be something wrong.

If you unset GUILE_AUTO_COMPILE, Guile should automatically compile all
source files not already compiled and store them under ~/.cache.  When
it does, it prints lines telling which files it auto-compiled, possibly
with an error message if it failed to do so.

Can you double-check what happens exactly?

> Guile 1.8.7 takes 81 seconds on this example.
>
> SCM 5e5 takes 18 seconds.

Now, *this* is bad news for 1.8.  I suppose 1.8.7 compiled
`--without-threads' would yield better performance.  It would be
interesting to try that.

Thanks,
Ludo'.

Re: Serious performance issues with 1.9.0

[Martin Ward]

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.

Still nothing appearing in ~/.cache though.

This problem seems to apply to all files:
for example, the file below takes 140 seconds CPU time
when run via echo '("load file.scm")' | guile
and only 46 seconds when run via guile -s file.scm

For Guile 1.8.7 the times are 75 seconds and 31 seconds respectively.

Here is the code I used for the second test:


(define (force-output) #t)
(define /i '())
(define (@fib /n)
  (if (<= /n 1)
    1
    (+ (@fib (- /n 1)) (@fib (- /n 2)))))

(let ((var-save /i) (for-step 1) (for-end 35))
  (set! /i 1)
  (let for-loop ()
    (cond ((or (and (> 1 0) (<= /i for-end))
               (and (< 1 0) (>= /i for-end)))
           (begin
             (display "fib(")
             (begin
               (display /i)
               (begin
                 (display ") = ")
                 (begin
                   (display (@fib /i))
                   (newline)
                   (force-output)))))
           (set! /i (+ /i for-step))
           (for-loop))
          (#t #t)))
  (set! /i var-save))

(exit)




-- 
			Martin

martin@gkc.org.uk http://www.cse.dmu.ac.uk/~mward/ Erdos number: 4
G.K.Chesterton web site: http://www.cse.dmu.ac.uk/~mward/gkc/

Re: Serious performance issues with 1.9.0

[Ludovic Courtès]

Hi,

Martin Ward <martin@gkc.org.uk> 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.

That's expected: in the first case, Guile uses the debugging evaluator,
whereas in the latter it uses the normal (faster) evaluator.

Adding `--no-debug' to the command line of the first one should yield
the same timings as the second one.

> 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.
>
> Still nothing appearing in ~/.cache though.

Oh, that's right: it doesn't auto-compile files passed on the
command-line, only modules that are use-module'd it seems.

Not sure whether this is intended, though.  Andy?

You can work around it by manually compiling your source files:

  guile-tools compile -o ALL.go ALL.scm
  ...

The compiled version can then be run with something like:

  guile -c '(load-compiled "ALL.go")'

Can you try this?

Thanks for your perseverance!

Ludo'.

Re: Serious performance issues with 1.9.0

[Martin Ward]

On Friday 17 Jul 2009 19:10, Ludovic Courtès wrote:
> You can work around it by manually compiling your source files:
>
>   guile-tools compile -o ALL.go ALL.scm
>   ...
>
> The compiled version can then be run with something like:
>
>   guile -c '(load-compiled "ALL.go")'
>
> Can you try this?

This is what I get:

% guile-tools compile -o ALL.go ALL.scm
ERROR: Value out of range 0 to 255: 633
89.725u 7.472s 1:37.29 99.8%    0+0k 0+0io 4pf+0w


Just for fun, I tried out a Fibonacci numbers benchmark (see below).
Here are the results:

Guile 1.9.1:     128.8 secs (compiled)
SCM version 5e5: 126.5 secs (interpreted)
Hobbit compiled:   2.2 secs (compiled)

Its a pity that you decided to write your own compiler instead
of continuing development with Hobbit :-(

Here is the test program:

(define /i '())
(define (@fib /n)
  (if (<= /n 1)
    1
    (+ (@fib (- /n 1)) (@fib (- /n 2)))))

(let ((var-save /i) (for-step 1) (for-end 40))
  (set! /i 1)
  (let for-loop ()
    (cond ((or (and (> 1 0) (<= /i for-end))
               (and (< 1 0) (>= /i for-end)))
           (begin
             (display "fib(")
             (begin
               (display /i)
               (begin
                 (display ") = ")
                 (begin
                   (display (@fib /i))
                   (newline)
                   (force-output)))))
           (set! /i (+ /i for-step))
           (for-loop))
          (#t #t)))
  (set! /i var-save))

(exit)




-- 
			Martin

martin@gkc.org.uk http://www.cse.dmu.ac.uk/~mward/ Erdos number: 4
G.K.Chesterton web site: http://www.cse.dmu.ac.uk/~mward/gkc/

Re: Serious performance issues with 1.9.0

[Andy Wingo]

Hello,

On Sun 19 Jul 2009 15:56, Martin Ward <martin@gkc.org.uk> writes:

> On Friday 17 Jul 2009 19:10, Ludovic Courtès wrote:
>> You can work around it by manually compiling your source files:
>>
>>   guile-tools compile -o ALL.go ALL.scm
>>   ...
>>
>> The compiled version can then be run with something like:
>>
>>   guile -c '(load-compiled "ALL.go")'
>>
>> Can you try this?
>
> This is what I get:
>
> % guile-tools compile -o ALL.go ALL.scm
> ERROR: Value out of range 0 to 255: 633
> 89.725u 7.472s 1:37.29 99.8%    0+0k 0+0io 4pf+0w

Discussed here:

  http://article.gmane.org/gmane.lisp.guile.devel/8882

I'm working on a fix, hopefully within a couple of days.

> Its a pity that you decided to write your own compiler instead
> of continuing development with Hobbit :-(

Hobbit is a whole-program compiler. Guile needs an incremental,
embeddable compiler, with source information, and a repl, etc etc.
Apples and oranges, to a rough approximation.

Guile will be fast, but it will take a couple more years. In the
meantime, it is getting better, but if you are in a hurry for some
reason, perhaps some other scheme would suit your needs better.

Cheers,

Andy
-- 
http://wingolog.org/

Re: Serious performance issues with 1.9.0

[Martin Ward]

On Sunday 19 Jul 2009 23:03, Andy Wingo wrote:
> Discussed here:
>
>   http://article.gmane.org/gmane.lisp.guile.devel/8882
>
> I'm working on a fix, hopefully within a couple of days.

Great! Let me know when it is ready, and I'll put it through
its paces for you.

> > Its a pity that you decided to write your own compiler instead
> > of continuing development with Hobbit :-(
>
> Hobbit is a whole-program compiler. Guile needs an incremental,
> embeddable compiler, with source information, and a repl, etc etc.
> Apples and oranges, to a rough approximation.

I needed to persuade Hobbit to compile files separately,
and found a couple of ways to do it:

Slow Solution: Ensure everything is defined as an OBJT by adding the line:
(define compile-new-proc-redefined #t) to one of the files in each Hobbit
compiler call. This ensures all new procs are typed as OBJT, which causes
some loss of efficiency.

Fast Solution: Add the names of all the procs defined in compiled files
to the list *special-scm->c-functions* after loading hobbit.scm but before
calling hobbit. These will then be treated as simple functions, even when they
are defined externally.

Compiling the whole of FermaT in a single file still gives a performance
boost of about 18%, but compilation takes a long time!

> Guile will be fast, but it will take a couple more years. In the
> meantime, it is getting better, but if you are in a hurry for some
> reason, perhaps some other scheme would suit your needs better.

For performance runs, speed is top priority. But if there is a bug
somewhere then the Hobbit compiled code just crashes with a segfault.
In this case, I re-run the failed process with FermaT debugging turned on:
this creates lots of checkpoints. I can then run the program from 
the last checkpoint under a Scheme interpreter with good debugging facilities.
This is where implementations such as Guile are useful.

But I don't see why the latest version of Guile has to be half as fast
as the previous version!

-- 
			Martin

martin@gkc.org.uk http://www.cse.dmu.ac.uk/~mward/ Erdos number: 4
G.K.Chesterton web site: http://www.cse.dmu.ac.uk/~mward/gkc/

Re: Serious performance issues with 1.9.0

[Andy Wingo]

On Mon 20 Jul 2009 14:48, Martin Ward <martin@gkc.org.uk> writes:

> On Sunday 19 Jul 2009 23:03, Andy Wingo wrote:
>> Discussed here:
>>
>>   http://article.gmane.org/gmane.lisp.guile.devel/8882
>>
>> I'm working on a fix, hopefully within a couple of days.
>
> Great! Let me know when it is ready, and I'll put it through
> its paces for you.

Well! Your code brought to light three limitations in the current code,
and two bugs.

The first limitation was that before, we allocated all set! variables in
a linear list within a function. Now they are allocated in boxes on the
stack. I increased the number of possible stack variables from 255 to
64K, but that turned out not to be necessary, since your set! variables
were often in ephemeral lexical scopes, so the local variable slots
could be reused in different parts of the function.

Then the first bug: sometimes the alpha-renamed variables from psyntax
were not globally unique. The algorithm was, "variable stem +
monotonically increasing integer". Obviously that doesn't necessarily
work if the variable stem ended in an integer. I was aware of this, but
somehow it hadn't bitten anyone until compiling your code. Now it is
fixed.

At this point I could compile ALL.scm.

Then the second limitation: the default VM stack is too small, and we
have no overflow handler to increase it. So I raised the default VM
stack size. We'll lower it back down again, perhaps, once we implement
overflow handlers.

Then the second bug: ALL.scm compiled, and the first could
prog_to_spec_TEST tests passed, but then I got an "invalid instruction"
error. But the function that produced the error disassembled fine...
then I noticed the function was around 70K bytes in length, close to
another limit: that jumps are encoded in a 16-bit value. It didn't take
too much more poking to find out that a forward jump of 64823 bytes was
being interpreted as a backwards jump, because it's a signed 16-bit
value. I added some more checks in the assembler to catch this at
compile-time.

Which brings us to now. ALL.scm doesn't compile any more because of that
16-bit limit, which is now caught correctly. I am afraid we will have to
move to 32-bit words as Ludovic has suggested all along, because the
proliferation of short and long addressing modes is getting too much. I
guess that's the next thing on my plate, then...

Regards,

Andy
-- 
http://wingolog.org/

Re: Serious performance issues with 1.9.0

[Ludovic Courtès]

Andy Wingo <wingo@pobox.com> writes:

[...]

> Discussed here:
>
>   http://article.gmane.org/gmane.lisp.guile.devel/8882

Oops, sorry for repeating what you had already said.

Thanks,
Ludo'.

Re: Serious performance issues with 1.9.0

[Andy Wingo]

Hi Martin,

On Fri 17 Jul 2009 19:27, Martin Ward <martin@gkc.org.uk> 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/

Re: Serious performance issues with 1.9.0

[Andy Wingo]

Hi,

On Sun 26 Jul 2009 14:01, Andy Wingo <wingo@pobox.com> writes:

> On Fri 17 Jul 2009 19:27, Martin Ward <martin@gkc.org.uk> writes:
>
>> 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
>
> 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)
> clock utime stime cutime cstime gctime
> 30.09 29.64  0.09   0.00   0.00   0.24

Now with current Guile I get the following:

scheme@(guile-user)> (compile-file "/tmp/prog_to_spec_TEST.scx")
$2 = "/home/wingo/.cache/guile/ccache/1.9-0.A-LE-4/tmp/prog_to_spec_TEST.scx.go"
scheme@(guile-user)> ,t (load-compiled $2)
clock utime stime cutime cstime gctime
23.21 22.90  0.00   0.00   0.00   0.28

23 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.

This is still the case.

Regards,

Andy
-- 
http://wingolog.org/