bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof

bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof

[Christopher Allan Webber]

I was testing a program of mine under Guile 2.2, and was surprised to
find things slower than in Guile 2.0, surprising given all the various
optimizations I've heard about!  However, I think I've found good clues
as to what's going on.

The tl;dr: there are a lot of calls to bytevector-u64-ref being called
by the various elf utilities, and anything that checks debugging
information, including anything checking arity (like promises!) gets
slowed dramatically.

First I ran statprof, and a number of procedure calls jumped to the top
as most expensive, even though they hadn't in Guile 2.0.

  scheme@(activitystuff json-ld)> (statprof (lambda () (expand fjson-test-2)) #:loop 2000)
  %     cumulative   self             
  time   seconds     seconds  procedure
   20.88      1.96      1.94  bytevector-u64-ref
   15.79      3.72      1.47  system/vm/elf.scm:675:0:parse-elf64-section-header
    8.25      1.19      0.77  system/vm/elf.scm:820:0:string-table-ref
    5.44      6.25      0.51  system/vm/elf.scm:828:0:elf-section-by-name
    5.09      0.47      0.47  system/vm/elf.scm:702:0:elf-section
    3.86      0.36      0.36  utf8->string
    3.33      0.38      0.31  /home/cwebber/devel/activitystuff/activitystuff/contrib/fash.scm:196:0:fash-ref
    2.98      0.29      0.28  make-bytevector
    2.63      0.24      0.24  bytevector-u32-ref
    2.63      0.24      0.24  equal?
    1.93      0.18      0.18  hash
    1.40      0.13      0.13  bytevector-copy!

Hm, that's a lot of calls to bytevector and elf things!  Those weren't
there before... where did they come from?

I won't reproduce it here, but

  scheme@(activitystuff json-ld)> (statprof (lambda () (expand fjson-test-2)) #:loop 2000)

led to an explosion of thousands of elf/bytevector references, not only
at the top where some debugging checks might be expected, but much
further on too.  I noticed however that (make-promise) and checks to
arity seem to be coming up a lot, so I decided to check that.  In guile
2.0, here is what a simple (delay foo) looks like:

  scheme@(guile-user)> ,trace (delay (+ 1 2 3))
  trace: |  (#<procedure 2bbf820> #(#<directory (guile-user) 25b7c60> #f #f # …))
  trace: |  #(#<directory (guile-user) 25b7c60> guile (guile) make-promise (…) #)
  trace: (#<procedure 2bd53c0 at <current input>:1:0 ()>)
  trace: |  (#<procedure 25567e0 at ice-9/boot-9.scm:2777:4 (name #:optional …> …)
  trace: |  |  (nested-ref-module #<module () 2532990> (guile))
  trace: |  |  |  (module-ref-submodule #<module () 2532990> guile)
  trace: |  |  |  |  (#<procedure 25523a0 at ice-9/boot-9.scm:2004:2 (module)> #)
  trace: |  |  |  |  #<hash-table 2556880 90/113>
  trace: |  |  |  |  (hashq-ref #<hash-table 2556880 90/113> guile)
  trace: |  |  |  |  #<module (guile) 2532b40>
  trace: |  |  |  #<module (guile) 2532b40>
  trace: |  |  #<module (guile) 2532b40>
  trace: |  |  (#<procedure 258f460 at ice-9/deprecated.scm:415:8 (mod)> #<mod…>)
  trace: |  |  |  (#<procedure 25521a0 at ice-9/boot-9.scm:2004:2 (module)> #<…>)
  trace: |  |  |  #<interface (guile) 2532ab0>
  trace: |  |  #<interface (guile) 2532ab0>
  trace: |  #<module (guile) 2532b40>
  trace: (make-promise #<procedure 2c41d60 at <current input>:1:0 ()>)
  trace: |  (#<procedure 2c48b80>)
  trace: |  (() ((0 0 . 0)) ((2 5 0)))
  trace: #<promise #<procedure 2c41d60 at <current input>:1:0 ()>>

In guile 2.2, it begins like this:

  scheme@(activitystuff json-ld)> ,trace (delay (+ 1 2 3))
  trace: (#<procedure dfc620 at ice-9/boot-9.scm:2987:4 (name #:optional autoload version #:key ensure)> (guile) #:ensure #f)
  trace: |  (nested-ref-module #<module () e06e10> (guile))
  trace: |  |  (module-ref-submodule #<module () e06e10> guile)
  trace: |  |  |  (#<procedure dfc8a0 at ice-9/boot-9.scm:2245:2 (module)> #<module () e06e10>)
  trace: |  |  |  #<hash-table dfe2c0 139/223>
  trace: |  |  |  (hashq-ref #<hash-table dfe2c0 139/223> guile)
  trace: |  |  |  #<module (guile) e06f30>
  trace: |  |  #<module (guile) e06f30>
  trace: |  #<module (guile) e06f30>
  trace: |  (#<procedure dfc820 at ice-9/boot-9.scm:2245:2 (module)> #<module (guile) e06f30>)
  trace: |  #<interface (guile) e06ea0>
  trace: #<module (guile) e06f30>
  trace: |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  -1> (make-promise #<procedure ?>)
  trace: |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  -1> (program-minimum-arity #<p?>)
  trace: (program-code #<procedure 7f7c94290a50 at <unknown port>:38:7 ()>)
  trace: 140173038389440
  trace: |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  |  -1> (find-program-minimum-arity ?)
  trace: (find-debug-context 140173038389440)
  trace: |  (find-mapped-elf-image 140173038389440)
  trace: |  #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 176 2 0 0 0 0 0 0 0 0 0 0 ?)
  trace: (and=> #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 176 2 0 0 0 0 0 0 ?) #)
  trace: (debug-context-from-image #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 ?))
  trace: |  (parse-elf #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 176 2 0 0 0 ?))
  trace: |  |  (has-elf-header? #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 176 ?))
  trace: |  |  |  (bytevector-length #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 ?))
  trace: |  |  |  2523
  trace: |  |  |  (bytevector-length #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 ?))
  trace: |  |  |  2523
  trace: |  |  |  (bytevector-u32-ref #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 ?) ?)
  trace: |  |  |  1
  trace: |  |  #t
  trace: |  (parse-elf64 #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 176 2 0 0 ?) ?)
  trace: |  |  (bytevector-u16-ref #vu8(127 69 76 70 2 1 1 255 0 0 0 0 0 0 0 0 3 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 64 0 0 0 0 0 0 0 ?) ?)
  trace: |  |  3
  
... and continues for nearly a thousand lines!

I suspect this is slowing Guile down a lot!  Maybe this will be helpful
in making Guile 2.2 fast for code like this?

Thanks!
 - Chris

bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof

[Christopher Allan Webber]

[-- Attachment #1: Type: text/plain, Size: 159 bytes --]

Here's a fix to this bug.  Tests pass, and performance appears to be
back here.

I've assigned copyright to the FSF for Guile so it should be fine to
commit!


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-Remove-thunk-arity-check-in-make-promise.patch --]
[-- Type: text/x-diff, Size: 1403 bytes --]

From 79e3b5286a2699f9b302bd3abf8a6b884b13a4f4 Mon Sep 17 00:00:00 2001
From: Christopher Allan Webber <cwebber@dustycloud.org>
Date: Fri, 13 Nov 2015 20:42:31 -0600
Subject: [PATCH] Remove thunk / arity check in make-promise

* libguile/promises.c (s_scm_make_promise): Remove arity check in
  make-promise.  This was causing considerably slowdown with the new elf
  code, causing considerable number of bytevector reading calls on
  every call to (make-promise).  Removing this check fixes a performance
  regression in the new compiler.
---
 libguile/promises.c | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/libguile/promises.c b/libguile/promises.c
index dcd0ac3..858b6f3 100644
--- a/libguile/promises.c
+++ b/libguile/promises.c
@@ -1,4 +1,4 @@
-/* Copyright (C) 1995,1996,1997,1998,1999,2000,2001,2002,2003,2004,2005,2006,2007,2008,2009,2010,2011
+/* Copyright (C) 1995,1996,1997,1998,1999,2000,2001,2002,2003,2004,2005,2006,2007,2008,2009,2010,2011,2015
  * Free Software Foundation, Inc.
  * 
  * This library is free software; you can redistribute it and/or
@@ -77,7 +77,6 @@ SCM_DEFINE (scm_make_promise, "make-promise", 1, 0, 0,
             "@end lisp\n")
 #define FUNC_NAME s_scm_make_promise
 {
-  SCM_VALIDATE_THUNK (1, thunk);
   SCM_RETURN_NEWSMOB2 (scm_tc16_promise,
 		       SCM_UNPACK (thunk),
 		       SCM_UNPACK (scm_make_recursive_mutex ()));
-- 
2.1.4

bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof

[Andy Wingo]

I'm happy with this fix!  However I think I would like to see if I can
just speed up thunk? and other arity accessors.  Do you have a test
case that you can use to show the speed problem?

Andy

On Sat 14 Nov 2015 03:54, Christopher Allan Webber <cwebber@dustycloud.org> writes:

> Here's a fix to this bug.  Tests pass, and performance appears to be
> back here.
>
> I've assigned copyright to the FSF for Guile so it should be fine to
> commit!
>
>
>>From 79e3b5286a2699f9b302bd3abf8a6b884b13a4f4 Mon Sep 17 00:00:00 2001
> From: Christopher Allan Webber <cwebber@dustycloud.org>
> Date: Fri, 13 Nov 2015 20:42:31 -0600
> Subject: [PATCH] Remove thunk / arity check in make-promise
>
> * libguile/promises.c (s_scm_make_promise): Remove arity check in
>   make-promise.  This was causing considerably slowdown with the new elf
>   code, causing considerable number of bytevector reading calls on
>   every call to (make-promise).  Removing this check fixes a performance
>   regression in the new compiler.
> ---
>  libguile/promises.c | 3 +--
>  1 file changed, 1 insertion(+), 2 deletions(-)
>
> diff --git a/libguile/promises.c b/libguile/promises.c
> index dcd0ac3..858b6f3 100644
> --- a/libguile/promises.c
> +++ b/libguile/promises.c
> @@ -1,4 +1,4 @@
> -/* Copyright (C) 1995,1996,1997,1998,1999,2000,2001,2002,2003,2004,2005,2006,2007,2008,2009,2010,2011
> +/* Copyright (C) 1995,1996,1997,1998,1999,2000,2001,2002,2003,2004,2005,2006,2007,2008,2009,2010,2011,2015
>   * Free Software Foundation, Inc.
>   * 
>   * This library is free software; you can redistribute it and/or
> @@ -77,7 +77,6 @@ SCM_DEFINE (scm_make_promise, "make-promise", 1, 0, 0,
>              "@end lisp\n")
>  #define FUNC_NAME s_scm_make_promise
>  {
> -  SCM_VALIDATE_THUNK (1, thunk);
>    SCM_RETURN_NEWSMOB2 (scm_tc16_promise,
>  		       SCM_UNPACK (thunk),
>  		       SCM_UNPACK (scm_make_recursive_mutex ()));

bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof

[Andy Wingo]

On Fri 18 Sep 2015 17:19, Christopher Allan Webber <cwebber@dustycloud.org> writes:

> I was testing a program of mine under Guile 2.2, and was surprised to
> find things slower than in Guile 2.0, surprising given all the various
> optimizations I've heard about!  However, I think I've found good clues
> as to what's going on.

(Summary: procedure-minimum-arity, called via `thunk?' when making
promises, was doing a lot of work, grovelling debuginfo to answer simple
questions.)

I fixed procedure-minimum-arity to be quicker, which should fix this
bug.  Please let me know if you see thunk? as a perf problem in your use
case.

In the meantime I seem to have broken ,trace :/  I'll see what the deal
is there.

Andy