From: "Ludovic Courtès" <ludo@gnu.org>
To: Matt Wette <matt.wette@gmail.com>
Cc: Guile Devel <guile-devel@gnu.org>
Subject: Re: compile-file execution time driven by `reap-pipes'
Date: Sun, 17 May 2020 23:39:14 +0200 [thread overview]
Message-ID: <87eerinsvx.fsf@gnu.org> (raw)
In-Reply-To: <65448df1-5fd7-c0c3-852c-432c093915b2@gmail.com> (Matt Wette's message of "Mon, 6 Apr 2020 19:50:13 -0700")
[-- Attachment #1: Type: text/plain, Size: 2950 bytes --]
Hi Matt,
Matt Wette <matt.wette@gmail.com> 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’t remember noticing it before but I see the same now. The
compiler is GC-intensive, so after-GC hooks such as ‘reap-pipes’ are
called quite frequently. On this 19K line file, it doesn’t come first
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
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
[…]
---
Sample count: 7285
Total time: 234.475384815 seconds (128.869116983 seconds in GC)
--8<---------------cut here---------------end--------------->8---
Delaying the ‘add-hook!’ call as shown below removes ‘reap-pipes’ from
the profile but otherwise doesn’t have any significant effect.
So I’m not sure if there’s much to conclude from that, other than
the fact that it’s GC’ing a lot.
Ludo’.
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 1679 bytes --]
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)
prev parent reply other threads:[~2020-05-17 21:39 UTC|newest]
Thread overview: 2+ messages / expand[flat|nested] mbox.gz Atom feed top
2020-04-07 2:50 compile-file execution time driven by `reap-pipes' Matt Wette
2020-05-17 21:39 ` Ludovic Courtès [this message]
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=87eerinsvx.fsf@gnu.org \
--to=ludo@gnu.org \
--cc=guile-devel@gnu.org \
--cc=matt.wette@gmail.com \
/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).