From unknown Fri Aug 15 18:15:39 2025 X-Loop: help-debbugs@gnu.org Subject: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Resent-From: Christopher Allan Webber Original-Sender: "Debbugs-submit" Resent-CC: bug-guile@gnu.org Resent-Date: Fri, 18 Sep 2015 18:28:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: report 21514 X-GNU-PR-Package: guile X-GNU-PR-Keywords: To: 21514@debbugs.gnu.org X-Debbugs-Original-To: bug-guile@gnu.org Received: via spool by submit@debbugs.gnu.org id=B.144260084210637 (code B ref -1); Fri, 18 Sep 2015 18:28:02 +0000 Received: (at submit) by debbugs.gnu.org; 18 Sep 2015 18:27:22 +0000 Received: from localhost ([127.0.0.1]:37217 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1Zd0NV-0002lT-H2 for submit@debbugs.gnu.org; Fri, 18 Sep 2015 14:27:22 -0400 Received: from eggs.gnu.org ([208.118.235.92]:53279) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1Zcy1R-0007Qa-5r for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:26 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zcy1P-00044S-C6 for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:24 -0400 X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on eggs.gnu.org X-Spam-Level: X-Spam-Status: No, score=0.8 required=5.0 tests=BAYES_50 autolearn=disabled version=3.3.2 Received: from lists.gnu.org ([2001:4830:134:3::11]:46768) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zcy1P-00044J-9h for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:23 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:35003) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zcy1N-00073q-Tu for bug-guile@gnu.org; Fri, 18 Sep 2015 11:56:23 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zcy1K-0003zF-KP for bug-guile@gnu.org; Fri, 18 Sep 2015 11:56:21 -0400 Received: from dustycloud.org ([50.116.34.160]:51877) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ZcxcC-0001b4-3h for bug-guile@gnu.org; Fri, 18 Sep 2015 11:30:20 -0400 Received: from earlgrey (localhost [127.0.0.1]) by dustycloud.org (Postfix) with ESMTPS id 3AD0126701 for ; Fri, 18 Sep 2015 11:30:17 -0400 (EDT) From: Christopher Allan Webber Date: Fri, 18 Sep 2015 10:19:56 -0500 Message-ID: <874mirbv8x.fsf@dustycloud.org> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-detected-operating-system: by eggs.gnu.org: Error: Malformed IPv6 address (bad octet value). X-Received-From: 2001:4830:134:3::11 X-Spam-Score: -4.0 (----) X-Mailman-Approved-At: Fri, 18 Sep 2015 14:27:19 -0400 X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -4.0 (----) 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 =20 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/activitys= tuff/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: | (# #(# #f = #f # =E2=80=A6)) trace: | #(# guile (guile) make-promis= e (=E2=80=A6) #) trace: (#:1:0 ()>) trace: | (# =E2=80=A6) trace: | | (nested-ref-module # (guile)) trace: | | | (module-ref-submodule # guile) trace: | | | | (# #) trace: | | | | # trace: | | | | (hashq-ref # guile) trace: | | | | # trace: | | | # trace: | | # trace: | | (# = #) trace: | | | (# #<=E2=80=A6>) trace: | | | # trace: | | # trace: | # trace: (make-promise #:1:0 ()>) trace: | (#) trace: | (() ((0 0 . 0)) ((2 5 0))) trace: #:1:0 ()>> In guile 2.2, it begins like this: scheme@(activitystuff json-ld)> ,trace (delay (+ 1 2 3)) trace: (# (guile) #:ensure #f) trace: | (nested-ref-module # (guile)) trace: | | (module-ref-submodule # guile) trace: | | | (# #) trace: | | | # trace: | | | (hashq-ref # guile) trace: | | | # trace: | | # trace: | # trace: | (# #) trace: | # trace: # trace: | | | | | | | | | | | | | | | | | | | | | |= | | | | | | | | -1> (make-promise #) trace: | | | | | | | | | | | | | | | | | | | | | |= | | | | | | | | -1> (program-minimum-arity #) trace: (program-code #: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=3D> #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 =20 ... 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 From unknown Fri Aug 15 18:15:39 2025 X-Loop: help-debbugs@gnu.org Subject: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Resent-From: Christopher Allan Webber Original-Sender: "Debbugs-submit" Resent-CC: bug-guile@gnu.org Resent-Date: Sat, 14 Nov 2015 03:05:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 21514 X-GNU-PR-Package: guile X-GNU-PR-Keywords: To: 21514@debbugs.gnu.org X-Debbugs-Original-To: bug-guile@gnu.org Received: via spool by submit@debbugs.gnu.org id=B.144747028626957 (code B ref -1); Sat, 14 Nov 2015 03:05:02 +0000 Received: (at submit) by debbugs.gnu.org; 14 Nov 2015 03:04:46 +0000 Received: from localhost ([127.0.0.1]:37612 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1ZxR8v-00070j-Rc for submit@debbugs.gnu.org; Fri, 13 Nov 2015 22:04:46 -0500 Received: from eggs.gnu.org ([208.118.235.92]:48429) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1ZxR8b-00070J-5u for submit@debbugs.gnu.org; Fri, 13 Nov 2015 22:04:43 -0500 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1ZxR8a-0002ls-2o for submit@debbugs.gnu.org; Fri, 13 Nov 2015 22:04:24 -0500 X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on eggs.gnu.org X-Spam-Level: X-Spam-Status: No, score=0.8 required=5.0 tests=BAYES_50 autolearn=disabled version=3.3.2 Received: from lists.gnu.org ([2001:4830:134:3::11]:50239) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ZxR8Z-0002lg-W4 for submit@debbugs.gnu.org; Fri, 13 Nov 2015 22:04:24 -0500 Received: from eggs.gnu.org ([2001:4830:134:3::10]:58433) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ZxR8Y-0001bd-Um for bug-guile@gnu.org; Fri, 13 Nov 2015 22:04:23 -0500 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1ZxR8U-0002e7-5L for bug-guile@gnu.org; Fri, 13 Nov 2015 22:04:22 -0500 Received: from dustycloud.org ([50.116.34.160]:36087) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ZxR8U-0002dX-10 for bug-guile@gnu.org; Fri, 13 Nov 2015 22:04:18 -0500 Received: from earlgrey (localhost [127.0.0.1]) by dustycloud.org (Postfix) with ESMTPS id BF4B7265F6 for ; Fri, 13 Nov 2015 22:04:13 -0500 (EST) References: <874mirbv8x.fsf@dustycloud.org> From: Christopher Allan Webber Date: Fri, 13 Nov 2015 20:54:43 -0600 In-reply-to: <874mirbv8x.fsf@dustycloud.org> Message-ID: <871tbt7047.fsf@dustycloud.org> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-detected-operating-system: by eggs.gnu.org: Error: Malformed IPv6 address (bad octet value). X-Received-From: 2001:4830:134:3::11 X-Spam-Score: -4.0 (----) X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -4.0 (----) --=-=-= Content-Type: text/plain 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! --=-=-= Content-Type: text/x-diff Content-Disposition: inline; filename=0001-Remove-thunk-arity-check-in-make-promise.patch >From 79e3b5286a2699f9b302bd3abf8a6b884b13a4f4 Mon Sep 17 00:00:00 2001 From: Christopher Allan Webber 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 --=-=-=-- From unknown Fri Aug 15 18:15:39 2025 X-Loop: help-debbugs@gnu.org Subject: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Resent-From: Andy Wingo Original-Sender: "Debbugs-submit" Resent-CC: bug-guile@gnu.org Resent-Date: Fri, 24 Jun 2016 11:38:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 21514 X-GNU-PR-Package: guile X-GNU-PR-Keywords: To: Christopher Allan Webber Cc: 21514@debbugs.gnu.org Received: via spool by 21514-submit@debbugs.gnu.org id=B21514.146676824432439 (code B ref 21514); Fri, 24 Jun 2016 11:38:01 +0000 Received: (at 21514) by debbugs.gnu.org; 24 Jun 2016 11:37:24 +0000 Received: from localhost ([127.0.0.1]:53463 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1bGPQK-0008R8-AD for submit@debbugs.gnu.org; Fri, 24 Jun 2016 07:37:24 -0400 Received: from pb-sasl1.pobox.com ([64.147.108.66]:50509 helo=sasl.smtp.pobox.com) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1bGPQG-0008Qy-EN for 21514@debbugs.gnu.org; Fri, 24 Jun 2016 07:37:23 -0400 Received: from sasl.smtp.pobox.com (unknown [127.0.0.1]) by pb-sasl1.pobox.com (Postfix) with ESMTP id D5A8E1CE92; Fri, 24 Jun 2016 07:37:19 -0400 (EDT) DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=pobox.com; h=from:to:cc :subject:references:date:in-reply-to:message-id:mime-version :content-type; s=sasl; bh=jdvNHq6TxDfuH+v3Sw03j49OEzQ=; b=iM1rCE 0j1uiARatPnrT0eUGAc1WziiATbNQB1oNLrFn61fAedH1fyx5meQ0TCuEL0kVZmu bcGE6ZpTjdkk+TXE1A4s4ykTuAIMnlh5VYkruBYk+NZP3OS3/nmAIciWyqa8e92U NW/UlnJhPmxlDKuP5O6N8md1UPH6iXkHyOtlk= DomainKey-Signature: a=rsa-sha1; c=nofws; d=pobox.com; h=from:to:cc :subject:references:date:in-reply-to:message-id:mime-version :content-type; q=dns; s=sasl; b=BjSr71sVYDVCsIfXP+HZOobA4chGNXqG VqQEfP0qRjMXWr069Iax1tTKJOeQFAUxhI7JkXIx+/x7HpsU9ddmEl6zsS0Qt0p+ 9gabAHID19voT78A9rBBklyyP+EyqyifrX2HnfvD5t0IgaBFZ3f2/UQKuDfqDUxX Q0AsuYLVvxc= Received: from pb-sasl1.nyi.icgroup.com (unknown [127.0.0.1]) by pb-sasl1.pobox.com (Postfix) with ESMTP id CC5051CE91; Fri, 24 Jun 2016 07:37:19 -0400 (EDT) Received: from clucks (unknown [88.160.190.192]) (using TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by pb-sasl1.pobox.com (Postfix) with ESMTPSA id 1C2051CE90; Fri, 24 Jun 2016 07:37:19 -0400 (EDT) From: Andy Wingo References: <874mirbv8x.fsf@dustycloud.org> <871tbt7047.fsf@dustycloud.org> Date: Fri, 24 Jun 2016 13:37:11 +0200 In-Reply-To: <871tbt7047.fsf@dustycloud.org> (Christopher Allan Webber's message of "Fri, 13 Nov 2015 20:54:43 -0600") Message-ID: <87por6g6mw.fsf@pobox.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.5 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain X-Pobox-Relay-ID: 022E775E-3A00-11E6-97DB-C1836462E9F6-02397024!pb-sasl1.pobox.com X-Spam-Score: -1.4 (-) X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -1.4 (-) 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 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 > 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 ())); From unknown Fri Aug 15 18:15:39 2025 MIME-Version: 1.0 X-Mailer: MIME-tools 5.505 (Entity 5.505) X-Loop: help-debbugs@gnu.org From: help-debbugs@gnu.org (GNU bug Tracking System) To: Christopher Allan Webber Subject: bug#21514: closed (Re: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof) Message-ID: References: <87lh1ug4fu.fsf@pobox.com> <874mirbv8x.fsf@dustycloud.org> X-Gnu-PR-Message: they-closed 21514 X-Gnu-PR-Package: guile Reply-To: 21514@debbugs.gnu.org Date: Fri, 24 Jun 2016 12:25:02 +0000 Content-Type: multipart/mixed; boundary="----------=_1466771102-4567-1" This is a multi-part message in MIME format... ------------=_1466771102-4567-1 Content-Disposition: inline Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" Your bug report #21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statpr= of which was filed against the guile package, has been closed. The explanation is attached below, along with your original report. If you require more details, please reply to 21514@debbugs.gnu.org. --=20 21514: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=3D21514 GNU Bug Tracking System Contact help-debbugs@gnu.org with problems ------------=_1466771102-4567-1 Content-Type: message/rfc822 Content-Disposition: inline Content-Transfer-Encoding: 7bit Received: (at 21514-done) by debbugs.gnu.org; 24 Jun 2016 12:24:48 +0000 Received: from localhost ([127.0.0.1]:53487 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1bGQAB-0001B8-VS for submit@debbugs.gnu.org; Fri, 24 Jun 2016 08:24:48 -0400 Received: from pb-sasl1.pobox.com ([64.147.108.66]:55096 helo=sasl.smtp.pobox.com) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1bGQAA-0001B0-VU for 21514-done@debbugs.gnu.org; Fri, 24 Jun 2016 08:24:47 -0400 Received: from sasl.smtp.pobox.com (unknown [127.0.0.1]) by pb-sasl1.pobox.com (Postfix) with ESMTP id 4A1E0202C6; Fri, 24 Jun 2016 08:24:45 -0400 (EDT) DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=pobox.com; h=from:to:cc :subject:references:date:in-reply-to:message-id:mime-version :content-type; s=sasl; bh=iqVSisTKdarzXNC71EOkS/sdgLc=; b=ZRwzM6 4oSm2T7L4k3JXcoIkMU0fVyRGsoMre1TcdCEMd4qNYajKdjLWuiYBv4bN2gQHXSq 01xVrhfxrDVttxvOoRDDxccmUP/kt8lB3KT66OY/v9j0o8y0YR1BZ0qUP9hXWDeR yLLoGqL0FpVhMP411HcwmQzIq3G5MPDyj/5QM= DomainKey-Signature: a=rsa-sha1; c=nofws; d=pobox.com; h=from:to:cc :subject:references:date:in-reply-to:message-id:mime-version :content-type; q=dns; s=sasl; b=BJTpCLjpqZMlqZdNojyuh4vNEVgPUnw6 emxQk09ykf0bKIeG/8urehv+HBvo6bPRwaiKkjTE0y8s6ljzWgRYoftXKtoVFO55 7dbPmIdlyXKFzDt5tTLk4vBH1tAIkX/KRVgbDe9dUP8XJYDRKokP3q7P2wKBsdkG IQqUm3HPNzY= Received: from pb-sasl1.nyi.icgroup.com (unknown [127.0.0.1]) by pb-sasl1.pobox.com (Postfix) with ESMTP id 428C2202C5; Fri, 24 Jun 2016 08:24:45 -0400 (EDT) Received: from clucks (unknown [88.160.190.192]) (using TLSv1 with cipher ECDHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by pb-sasl1.pobox.com (Postfix) with ESMTPSA id 88E44202C4; Fri, 24 Jun 2016 08:24:44 -0400 (EDT) From: Andy Wingo To: Christopher Allan Webber Subject: Re: bug#21514: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof References: <874mirbv8x.fsf@dustycloud.org> Date: Fri, 24 Jun 2016 14:24:37 +0200 In-Reply-To: <874mirbv8x.fsf@dustycloud.org> (Christopher Allan Webber's message of "Fri, 18 Sep 2015 10:19:56 -0500") Message-ID: <87lh1ug4fu.fsf@pobox.com> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.5 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain X-Pobox-Relay-ID: A24C0F52-3A06-11E6-A271-C1836462E9F6-02397024!pb-sasl1.pobox.com X-Spam-Score: -1.4 (-) X-Debbugs-Envelope-To: 21514-done Cc: 21514-done@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -1.4 (-) On Fri 18 Sep 2015 17:19, Christopher Allan Webber 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 ------------=_1466771102-4567-1 Content-Type: message/rfc822 Content-Disposition: inline Content-Transfer-Encoding: 7bit Received: (at submit) by debbugs.gnu.org; 18 Sep 2015 18:27:22 +0000 Received: from localhost ([127.0.0.1]:37217 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1Zd0NV-0002lT-H2 for submit@debbugs.gnu.org; Fri, 18 Sep 2015 14:27:22 -0400 Received: from eggs.gnu.org ([208.118.235.92]:53279) by debbugs.gnu.org with esmtp (Exim 4.80) (envelope-from ) id 1Zcy1R-0007Qa-5r for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:26 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zcy1P-00044S-C6 for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:24 -0400 X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on eggs.gnu.org X-Spam-Level: X-Spam-Status: No, score=0.8 required=5.0 tests=BAYES_50 autolearn=disabled version=3.3.2 Received: from lists.gnu.org ([2001:4830:134:3::11]:46768) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zcy1P-00044J-9h for submit@debbugs.gnu.org; Fri, 18 Sep 2015 11:56:23 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:35003) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zcy1N-00073q-Tu for bug-guile@gnu.org; Fri, 18 Sep 2015 11:56:23 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zcy1K-0003zF-KP for bug-guile@gnu.org; Fri, 18 Sep 2015 11:56:21 -0400 Received: from dustycloud.org ([50.116.34.160]:51877) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ZcxcC-0001b4-3h for bug-guile@gnu.org; Fri, 18 Sep 2015 11:30:20 -0400 Received: from earlgrey (localhost [127.0.0.1]) by dustycloud.org (Postfix) with ESMTPS id 3AD0126701 for ; Fri, 18 Sep 2015 11:30:17 -0400 (EDT) From: Christopher Allan Webber To: bug-guile@gnu.org Subject: Guile 2.2: Sluggish elf calls, esp around arity / promises / statprof Date: Fri, 18 Sep 2015 10:19:56 -0500 Message-ID: <874mirbv8x.fsf@dustycloud.org> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-detected-operating-system: by eggs.gnu.org: Error: Malformed IPv6 address (bad octet value). X-Received-From: 2001:4830:134:3::11 X-Spam-Score: -4.0 (----) X-Debbugs-Envelope-To: submit X-Mailman-Approved-At: Fri, 18 Sep 2015 14:27:19 -0400 X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -4.0 (----) 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 =20 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/activitys= tuff/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: | (# #(# #f = #f # =E2=80=A6)) trace: | #(# guile (guile) make-promis= e (=E2=80=A6) #) trace: (#:1:0 ()>) trace: | (# =E2=80=A6) trace: | | (nested-ref-module # (guile)) trace: | | | (module-ref-submodule # guile) trace: | | | | (# #) trace: | | | | # trace: | | | | (hashq-ref # guile) trace: | | | | # trace: | | | # trace: | | # trace: | | (# = #) trace: | | | (# #<=E2=80=A6>) trace: | | | # trace: | | # trace: | # trace: (make-promise #:1:0 ()>) trace: | (#) trace: | (() ((0 0 . 0)) ((2 5 0))) trace: #:1:0 ()>> In guile 2.2, it begins like this: scheme@(activitystuff json-ld)> ,trace (delay (+ 1 2 3)) trace: (# (guile) #:ensure #f) trace: | (nested-ref-module # (guile)) trace: | | (module-ref-submodule # guile) trace: | | | (# #) trace: | | | # trace: | | | (hashq-ref # guile) trace: | | | # trace: | | # trace: | # trace: | (# #) trace: | # trace: # trace: | | | | | | | | | | | | | | | | | | | | | |= | | | | | | | | -1> (make-promise #) trace: | | | | | | | | | | | | | | | | | | | | | |= | | | | | | | | -1> (program-minimum-arity #) trace: (program-code #: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=3D> #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 =20 ... 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 ------------=_1466771102-4567-1--