* Re: compile-file execution time driven by `reap-pipes'
2020-04-07 2:50 compile-file execution time driven by `reap-pipes' Matt Wette
@ 2020-05-17 21:39 ` Ludovic Courtès
0 siblings, 0 replies; 2+ messages in thread
From: Ludovic Courtès @ 2020-05-17 21:39 UTC (permalink / raw)
To: Matt Wette; +Cc: Guile Devel
[-- 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)
^ permalink raw reply related [flat|nested] 2+ messages in thread