* bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof @ 2015-09-18 15:19 Christopher Allan Webber 2015-11-14 2:54 ` Christopher Allan Webber 2016-06-24 12:24 ` Andy Wingo 0 siblings, 2 replies; 4+ messages in thread From: Christopher Allan Webber @ 2015-09-18 15:19 UTC (permalink / raw) To: 21514 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
* bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof 2015-09-18 15:19 bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Christopher Allan Webber @ 2015-11-14 2:54 ` Christopher Allan Webber 2016-06-24 11:37 ` Andy Wingo 2016-06-24 12:24 ` Andy Wingo 1 sibling, 1 reply; 4+ messages in thread From: Christopher Allan Webber @ 2015-11-14 2:54 UTC (permalink / raw) To: 21514 [-- 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 ^ permalink raw reply related [flat|nested] 4+ messages in thread
* bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof 2015-11-14 2:54 ` Christopher Allan Webber @ 2016-06-24 11:37 ` Andy Wingo 0 siblings, 0 replies; 4+ messages in thread From: Andy Wingo @ 2016-06-24 11:37 UTC (permalink / raw) To: Christopher Allan Webber; +Cc: 21514 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 ())); ^ permalink raw reply [flat|nested] 4+ messages in thread
* bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof 2015-09-18 15:19 bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Christopher Allan Webber 2015-11-14 2:54 ` Christopher Allan Webber @ 2016-06-24 12:24 ` Andy Wingo 1 sibling, 0 replies; 4+ messages in thread From: Andy Wingo @ 2016-06-24 12:24 UTC (permalink / raw) To: Christopher Allan Webber; +Cc: 21514-done 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 ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2016-06-24 12:24 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2015-09-18 15:19 bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Christopher Allan Webber 2015-11-14 2:54 ` Christopher Allan Webber 2016-06-24 11:37 ` Andy Wingo 2016-06-24 12:24 ` Andy Wingo
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).