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’.