From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.ciao.gmane.io!not-for-mail From: =?utf-8?Q?Ludovic_Court=C3=A8s?= Newsgroups: gmane.lisp.guile.devel Subject: Re: compile-file execution time driven by `reap-pipes' Date: Sun, 17 May 2020 23:39:14 +0200 Message-ID: <87eerinsvx.fsf@gnu.org> References: <65448df1-5fd7-c0c3-852c-432c093915b2@gmail.com> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" Injection-Info: ciao.gmane.io; posting-host="ciao.gmane.io:159.69.161.202"; logging-data="58199"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.3 (gnu/linux) Cc: Guile Devel To: Matt Wette Original-X-From: guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org Sun May 17 23:40:56 2020 Return-path: Envelope-to: guile-devel@m.gmane-mx.org Original-Received: from lists.gnu.org ([209.51.188.17]) by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1jaR1j-000F33-81 for guile-devel@m.gmane-mx.org; Sun, 17 May 2020 23:40:55 +0200 Original-Received: from localhost ([::1]:33528 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1jaR1i-0003jy-80 for guile-devel@m.gmane-mx.org; Sun, 17 May 2020 17:40:54 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]:59662) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1jaR0F-0003c3-B4 for guile-devel@gnu.org; Sun, 17 May 2020 17:39:23 -0400 Original-Received: from fencepost.gnu.org ([2001:470:142:3::e]:40428) by eggs.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1jaR0F-000136-1M; Sun, 17 May 2020 17:39:23 -0400 Original-Received: from [2a01:e0a:1d:7270:af76:b9b:ca24:c465] (port=35906 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:RSA_AES_256_CBC_SHA1:256) (Exim 4.82) (envelope-from ) id 1jaR0A-00023s-E5; Sun, 17 May 2020 17:39:21 -0400 X-URL: http://www.fdn.fr/~lcourtes/ X-Revolutionary-Date: 29 =?utf-8?Q?Flor=C3=A9al?= an 228 de la =?utf-8?Q?R?= =?utf-8?Q?=C3=A9volution?= X-PGP-Key-ID: 0x090B11993D9AEBB5 X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4 0CFB 090B 1199 3D9A EBB5 X-OS: x86_64-pc-linux-gnu In-Reply-To: <65448df1-5fd7-c0c3-852c-432c093915b2@gmail.com> (Matt Wette's message of "Mon, 6 Apr 2020 19:50:13 -0700") X-BeenThere: guile-devel@gnu.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "Developers list for Guile, the GNU extensibility library" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: guile-devel-bounces+guile-devel=m.gmane-mx.org@gnu.org Original-Sender: "guile-devel" Xref: news.gmane.io gmane.lisp.guile.devel:20523 Archived-At: --=-=-= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hi Matt, Matt Wette skribis: > I'm wanted to trace down why some of my "compile-file" w/ no optimization > was tasking time. I was able to turn compile-file under statprof for one > of the moderate sized .scm files, which has about 45,000 lines of code. > It was interesting that the major execution time consumer was reap-pipes. > I'm curious where that fits in. Does anyone know how compile-file could > be banging on reap-pipes so much? Below is the top output from statprof. > The results are for a run using guile 3.0.2 on Ubunu 18.04/x86_64. > > > % cumulative self calls > time seconds seconds procedure > 12.67 190.96 154.99 ice-9/popen.scm:145:0:reap-pipes > 12.30 363.41 150.49 language/cps/intset.scm:270:2:adjoin > 11.23 270.27 137.34 anon #x55befcb4c430 > 10.89 186.95 133.18 language/cps/slot-allocation.scm:843:19 > 10.58 129.40 129.40 language/cps/intmap.scm:396:0:intmap-ref > 5.31 1279.35 64.90 language/cps/intmap.scm:247:2:adjoin > 3.81 228.54 46.66 language/cps/intset.scm:269:0:intset-add > 3.48 4695.90 42.60 language/cps/intset.scm:470:5:visit-branch > 3.28 40.14 40.14 language/cps/intset.scm:349:0:intset-ref > 2.98 567.14 36.46 language/cps/intmap.scm:246:0:intmap-add I don=E2=80=99t remember noticing it before but I see the same now. The compiler is GC-intensive, so after-GC hooks such as =E2=80=98reap-pipes=E2= =80=99 are called quite frequently. On this 19K line file, it doesn=E2=80=99t come fi= rst though: --8<---------------cut here---------------start------------->8--- scheme@(guile-user)> ,pr (compile-file "gnu/packages/python-xyz.scm") GC Warning: Repeated allocation of very large block (appr. size 13246464): May lead to memory leak and poor performance % cumulative self=20=20=20=20=20=20=20=20=20=20=20=20=20 time seconds seconds procedure 16.51 54.14 38.72 language/cps/slot-allocation.scm:843:19 14.84 34.79 34.79 language/cps/intmap.scm:396:0:intmap-ref 6.95 1142.96 16.29 language/cps/intset.scm:470:5:visit-branch 6.36 19.34 14.90 anon #x7138d0 5.11 50.85 11.97 language/cps/intset.scm:729:2:subtract-nodes 4.23 20.79 9.91 language/cps/intset.scm:270:2:adjoin 4.21 9.88 9.88 language/cps/intset.scm:349:0:intset-ref 3.45 28.07 8.08 language/cps/intset.scm:551:2:union 3.42 8.14 8.01 ice-9/popen.scm:145:0:reap-pipes [=E2=80=A6] --- Sample count: 7285 Total time: 234.475384815 seconds (128.869116983 seconds in GC) --8<---------------cut here---------------end--------------->8--- Delaying the =E2=80=98add-hook!=E2=80=99 call as shown below removes =E2=80= =98reap-pipes=E2=80=99 from the profile but otherwise doesn=E2=80=99t have any significant effect. So I=E2=80=99m not sure if there=E2=80=99s much to conclude from that, othe= r than the fact that it=E2=80=99s GC=E2=80=99ing a lot. Ludo=E2=80=99. --=-=-= Content-Type: text/x-patch Content-Disposition: inline diff --git a/module/ice-9/popen.scm b/module/ice-9/popen.scm index 5ab93f275..55b6f09fc 100644 --- a/module/ice-9/popen.scm +++ b/module/ice-9/popen.scm @@ -90,6 +90,10 @@ (cons (port->fdes (car p)) (port->fdes (cdr p))))) +(define (initialize-popen!) + (add-hook! after-gc-hook reap-pipes) + (set! initialize-popen! (const #t))) + (define (open-process mode command . args) "Backwards compatible implementation of the former procedure in libguile/posix.c (scm_open_process) replaced by @@ -99,6 +103,7 @@ process (based on pipes) is created and returned. @var{mode} specifies whether an input, an output or an input-output port to the process is created: it should be the value of @code{OPEN_READ}, @code{OPEN_WRITE} or @code{OPEN_BOTH}." + (initialize-popen!) (let* ((from (and (or (string=? mode OPEN_READ) (string=? mode OPEN_BOTH)) (pipe->fdes))) (to (and (or (string=? mode OPEN_WRITE) @@ -185,8 +190,6 @@ information on how to interpret this value." (lambda args #f)))) (loop))))) -(add-hook! after-gc-hook reap-pipes) - (define (open-input-pipe command) "Equivalent to @code{open-pipe} with mode @code{OPEN_READ}" (open-pipe command OPEN_READ)) @@ -204,6 +207,7 @@ information on how to interpret this value." program and its arguments as strings -- returning an input port to the end of the pipeline, an output port to the beginning of the pipeline and a list of PIDs of the processes executing the @var(commands)." + (initialize-popen!) (let* ((to (pipe->fdes)) (pipes (map (lambda _ (pipe->fdes)) commands)) (pipeline (fold (lambda (from proc prev) --=-=-=--