GNU bug report logs -
#21514
Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof
Previous Next
To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 21514 in the body.
You can then email your comments to 21514 AT debbugs.gnu.org in the normal way.
Toggle the display of automated, internal messages from the tracker.
Report forwarded
to
bug-guile <at> gnu.org:
bug#21514; Package
guile.
(Fri, 18 Sep 2015 18:28:02 GMT)
Full text and
rfc822 format available.
Acknowledgement sent
to
Christopher Allan Webber <cwebber <at> dustycloud.org>:
New bug report received and forwarded. Copy sent to
bug-guile <at> gnu.org.
(Fri, 18 Sep 2015 18:28:02 GMT)
Full text and
rfc822 format available.
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
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
Information forwarded
to
bug-guile <at> gnu.org:
bug#21514; Package
guile.
(Sat, 14 Nov 2015 03:05:02 GMT)
Full text and
rfc822 format available.
Message #8 received at submit <at> debbugs.gnu.org (full text, mbox):
[Message part 1 (text/plain, inline)]
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!
[0001-Remove-thunk-arity-check-in-make-promise.patch (text/x-diff, inline)]
From 79e3b5286a2699f9b302bd3abf8a6b884b13a4f4 Mon Sep 17 00:00:00 2001
From: Christopher Allan Webber <cwebber <at> 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
Information forwarded
to
bug-guile <at> gnu.org:
bug#21514; Package
guile.
(Fri, 24 Jun 2016 11:38:01 GMT)
Full text and
rfc822 format available.
Message #11 received at 21514 <at> debbugs.gnu.org (full text, mbox):
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 <at> 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 <at> 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 ()));
Reply sent
to
Andy Wingo <wingo <at> pobox.com>:
You have taken responsibility.
(Fri, 24 Jun 2016 12:25:02 GMT)
Full text and
rfc822 format available.
Notification sent
to
Christopher Allan Webber <cwebber <at> dustycloud.org>:
bug acknowledged by developer.
(Fri, 24 Jun 2016 12:25:02 GMT)
Full text and
rfc822 format available.
Message #16 received at 21514-done <at> debbugs.gnu.org (full text, mbox):
On Fri 18 Sep 2015 17:19, Christopher Allan Webber <cwebber <at> 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
bug archived.
Request was from
Debbugs Internal Request <help-debbugs <at> gnu.org>
to
internal_control <at> debbugs.gnu.org.
(Sat, 23 Jul 2016 11:24:03 GMT)
Full text and
rfc822 format available.
This bug report was last modified 9 years and 19 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.