unofficial mirror of guile-devel@gnu.org 
 help / color / mirror / Atom feed
* compile-file execution time driven by `reap-pipes'
@ 2020-04-07  2:50 Matt Wette
  2020-05-17 21:39 ` Ludovic Courtès
  0 siblings, 1 reply; 2+ messages in thread
From: Matt Wette @ 2020-04-07  2:50 UTC (permalink / raw)
  To: guile-devel

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




^ permalink raw reply	[flat|nested] 2+ messages in thread

* 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	[flat|nested] 2+ messages in thread

end of thread, other threads:[~2020-05-17 21:39 UTC | newest]

Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-04-07  2:50 compile-file execution time driven by `reap-pipes' Matt Wette
2020-05-17 21:39 ` Ludovic Courtès

unofficial mirror of guile-devel@gnu.org 

This inbox may be cloned and mirrored by anyone:

	git clone --mirror https://yhetil.org/guile-devel/0 guile-devel/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 guile-devel guile-devel/ https://yhetil.org/guile-devel \
		guile-devel@gnu.org
	public-inbox-index guile-devel

Example config snippet for mirrors.
Newsgroups are available over NNTP:
	nntp://news.yhetil.org/yhetil.lisp.guile.devel
	nntp://news.gmane.io/gmane.lisp.guile.devel


AGPL code for this site: git clone http://ou63pmih66umazou.onion/public-inbox.git