From: Christopher Allan Webber <cwebber@dustycloud.org>
To: 21514@debbugs.gnu.org
Subject: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof
Date: Fri, 18 Sep 2015 10:19:56 -0500 [thread overview]
Message-ID: <874mirbv8x.fsf@dustycloud.org> (raw)
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
next reply other threads:[~2015-09-18 15:19 UTC|newest]
Thread overview: 4+ messages / expand[flat|nested] mbox.gz Atom feed top
2015-09-18 15:19 Christopher Allan Webber [this message]
2015-11-14 2:54 ` bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Christopher Allan Webber
2016-06-24 11:37 ` Andy Wingo
2016-06-24 12:24 ` Andy Wingo
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
List information: https://www.gnu.org/software/guile/
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=874mirbv8x.fsf@dustycloud.org \
--to=cwebber@dustycloud.org \
--cc=21514@debbugs.gnu.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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).