Opened 2 years ago

Closed 21 months ago

#6104 closed bug (fixed)

Regression: space leak in HEAD vs. 7.4

Reported by: simonmar Owned by: igloo
Priority: highest Milestone: 7.6.1
Component: Compiler Version: 7.5
Keywords: Cc:
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: Compile-time performance bug Difficulty: Unknown
Test Case: Blocked By:
Blocking: Related Tickets:

Description

I often keep an eye on compiler performance by compiling Cabal. Yesterday I noticed that HEAD appears to have a space leak: it needs 806MB to compile Cabal with -O, vs 424MB with 7.4.1.

Here are the results. First 7.4.1:

$ ghc-7.4.1 -O --make Distribution.Simple +RTS -s
  53,658,077,704 bytes allocated in the heap
   9,679,170,192 bytes copied during GC
     148,845,896 bytes maximum residency (56 sample(s))
       6,610,216 bytes maximum slop
             424 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0     102382 colls,     0 par   24.24s   24.22s     0.0002s    0.0046s
  Gen  1        56 colls,     0 par   12.48s   12.48s     0.2229s    0.4738s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time   57.37s  ( 60.81s elapsed)
  GC      time   36.72s  ( 36.70s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time   94.09s  ( 97.52s elapsed)

And HEAD:

$ ghc-nightly2 -O --make Distribution.Simple +RTS -s
  55,699,304,032 bytes allocated in the heap
  11,721,558,728 bytes copied during GC
     288,988,200 bytes maximum residency (50 sample(s))
       7,808,192 bytes maximum slop
             806 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0     107655 colls,     0 par   28.83s   28.83s     0.0003s    0.0043s
  Gen  1        50 colls,     0 par   16.36s   16.36s     0.3272s    1.0063s

  TASKS: 3 (1 bound, 2 peak workers (2 total), using -N1)

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time   59.87s  ( 63.18s elapsed)
  GC      time   45.19s  ( 45.19s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time  105.07s  (108.37s elapsed)

We need to squash this before 7.6 is released.

Attachments (7)

setup-head.ps (126.1 KB) - added by pcapriotti 23 months ago.
heap profile when compiling Distribution/Simple/Setup?.hs with GHC HEAD
setup-7.4.ps (132.0 KB) - added by pcapriotti 23 months ago.
heap profile when compiling Distribution/Simple/Setup?.hs with GHC 7.4.2
cabal-head-auto.ps.gz (153.0 KB) - added by pcapriotti 23 months ago.
heap profile for GHC HEAD
cabal-7.4-auto.ps.gz (114.6 KB) - added by pcapriotti 23 months ago.
CopyFile.hs (2.0 KB) - added by igloo 22 months ago.
before.txt (12.4 KB) - added by igloo 22 months ago.
after.txt (22.6 KB) - added by igloo 22 months ago.

Download all attachments as: .zip

Change History (21)

comment:1 Changed 2 years ago by pcapriotti

  • Owner set to pcapriotti

Changed 23 months ago by pcapriotti

heap profile when compiling Distribution/Simple/Setup?.hs with GHC HEAD

Changed 23 months ago by pcapriotti

heap profile when compiling Distribution/Simple/Setup?.hs with GHC 7.4.2

Changed 23 months ago by pcapriotti

heap profile for GHC HEAD

Changed 23 months ago by pcapriotti

comment:2 Changed 23 months ago by pcapriotti

  • Owner pcapriotti deleted

Here are some heap profiler reports comparing GHC HEAD with 7.4 when compiling
Cabal and the single Cabal module Distribution/Simple/Setup?.hs.

They are obtained by running:

ghc -O --make Distribution.Simple +RTS -hc

and

ghc -O -fforce-recomp --make Distribution/Simple/Setup.hs +RTS -hc

respectively, with both compilers built with -prof -auto on
compiler/simplCore/Simplify.lhs, where the leak seems to be located.

comment:3 Changed 23 months ago by simonmar

I've narrowed this down to something that happened around May 8-10. I'm seeing a roughly 10% increase in compile times that was in the May 10 nightly build compared to the May 8 nightly build (I've unpacked the builds to check).

e.g. compiling Cabal with -O and ghc-20120508:

  51,777,170,264 bytes allocated in the heap
  10,213,181,272 bytes copied during GC
     174,111,968 bytes maximum residency (57 sample(s))
       6,843,024 bytes maximum slop
             496 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0     100232 colls,     0 par   25.37s   25.36s     0.0003s    0.0040s
  Gen  1        57 colls,     0 par   13.46s   13.46s     0.2362s    0.5846s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time   58.57s  ( 61.82s elapsed)
  GC      time   38.82s  ( 38.82s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time   97.40s  (100.65s elapsed)

and with ghc-20120510:

  55,714,073,216 bytes allocated in the heap
  11,751,752,512 bytes copied during GC
     288,316,064 bytes maximum residency (51 sample(s))
       8,407,960 bytes maximum slop
             809 MB total memory in use (0 MB lost due to fragmentation)

                                    Tot time (elapsed)  Avg pause  Max pause
  Gen  0     107660 colls,     0 par   28.91s   28.90s     0.0003s    0.0044s
  Gen  1        51 colls,     0 par   16.56s   16.56s     0.3247s    1.0106s

  INIT    time    0.00s  (  0.00s elapsed)
  MUT     time   60.13s  ( 63.20s elapsed)
  GC      time   45.47s  ( 45.46s elapsed)
  EXIT    time    0.00s  (  0.00s elapsed)
  Total   time  105.60s  (108.67s elapsed)

we don't have a May 9 build because the change from mtl to transformers broke it.

I've had a look at the patches that went in around that time, and these are the only possible culprits as far as I can tell:

commit f7e246b50a33c329e9730296f7a342e03bc3db72
Merge: 4b089db... ff10612...
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Wed May 9 15:50:54 2012 +0100

    Merge branch 'ghc-new-flavor'

commit 4bbd6baee066b906ed93a0659205ecbffdbd0954
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Fri May 4 23:02:46 2012 +0100

    Simplify the SimplCont data type

commit e08cad76e8a434aca42996f79fc8bb790f291570
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Tue May 8 10:25:22 2012 +0100

    Wibbles to 'simplify the SimplCont data type'

commit 2112f43c466935818a371c53c706608cfa069d01
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Wed May 9 11:06:44 2012 +0100

    Be a little less aggressive about inlining (fixes Trac #5623)

commit 980372f357667c1ba63b28acbf5798826890b7a5
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Wed May 9 16:22:49 2012 +0100

    Re-do the "function application discount" (fixes Trac #6048)

comment:4 Changed 22 months ago by igloo

  • Owner set to igloo

comment:5 Changed 22 months ago by igloo

Most of the regression comes from this patch:

commit 980372f357667c1ba63b28acbf5798826890b7a5
Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Wed May 9 16:22:49 2012 +0100

    Re-do the "function application discount" (fixes Trac #6048)

(the SimplCont? patches also made things a bit worse, but I haven't looked into that at all).

I think that the problem is more/bigger inlinings, rather than a space leak in GHC itself. I'll attach CopyFile.hs, and before.txt and after.txt showing the interface files before and after this patch is applied.

Changed 22 months ago by igloo

Changed 22 months ago by igloo

Changed 22 months ago by igloo

comment:6 Changed 22 months ago by igloo

  • Owner changed from igloo to simonpj

Simon, would it make most sense for you to look at the heuristics? Otherwise, please bounce it back to Paolo or I.

comment:7 Changed 22 months ago by igloo

#4138 is another inlining-heuristic-related ticket.

comment:8 Changed 22 months ago by simonpj

There doesn't seem to be much of a difference on CopyFile, at least not now. Here's the size of the .o file:

                text	   data	    bss	    dec	    hex	filename
With 7.4.1      6480	    760	      0	   7240	   1c48	T6104.o
With HEAD       4769	    704	      0	   5473	   1561	T6104.o

So HEAD generates less code, not more. The compiler does allocate a bit more, but not much:

-------- 7.4.1  with -O on CopyFile.hs ------------
[1 of 1] Compiling CopyFile         ( T6104.hs, T6104.o )
     146,131,584 bytes allocated in the heap
      67,295,032 bytes copied during GC
      16,663,568 bytes maximum residency (6 sample(s))
       1,330,480 bytes maximum slop
              33 MB total memory in use (0 MB lost due to fragmentation)


-------- HEAD  with -O on CopyFile.hs ------------
[1 of 1] Compiling CopyFile         ( T6104.hs, T6104.o )
     156,295,232 bytes allocated in the heap
      71,474,496 bytes copied during GC
      16,357,872 bytes maximum residency (7 sample(s))
       1,451,648 bytes maximum slop
              32 MB total memory in use (0 MB lost due to fragmentation)

I suppose the next thing is to try compiling Cabal.

comment:9 Changed 22 months ago by simonpj

Interface file size:

GHC 7.4.1 -O     -rw-rw-r-- 1 simonpj GHC  5983 Jul 16 15:21 T6104.hi
HEAD             -rw-rw-r-- 1 simonpj GHC 10487 Jul 16 14:08 T6104.hi

So, yes, the interface file is a lot bigger. Looking more closely, this seems largely accidental. The code in HEAD is broken into more functions, each of which is individually small enough to be below the inlining-creation threshold.

I compiled Cabal with -O, and compared the total size (with ls -l) of the .o files and .hi files with both compilers:

                   HEAD change over 7.4.1   
.o file size            -6%
.hi file size           +8%

So yes, interface file size is up, but not massively, and .o file size is down.

This does not seem to account for the originally-reported doubling of residency! And (I've checked) that doubling is still happening.

Conclusion: I don't think it's just bigger interface files. I there is some other space leak too.

Simon

comment:10 Changed 22 months ago by simonpj

Paulo, might you produce a space profile of 7.4.1 and HEAD compiling Cabal? Thanks

Simon

comment:11 Changed 21 months ago by simonpj@…

commit cd627bcfda713efa63b7f5290c84a5077f4976f9

Author: Simon Peyton Jones <simonpj@microsoft.com>
Date:   Fri Jul 20 20:07:51 2012 +0100

    Do calcUnfoldingGuidance on the *non* occ-analysed RHS
    
    See Note [Calculate unfolding guidance on the non-occ-anal'd expression]
    This makes a big difference to residency (530M vs over 800M when compiling
    Cabal).
    
    This fixes the majority of the regression in Trac #6104

 compiler/coreSyn/CoreUnfold.lhs |   79 +++++++++++++++++++++++++-------------
 1 files changed, 52 insertions(+), 27 deletions(-)

comment:12 Changed 21 months ago by simonpj

  • Owner changed from simonpj to igloo

I claim we are done here. Paolo or Ian, can you check and close?

Compiling Cabal seems like a good perf test, if an expensive one. Maybe we should add it as a perf regression test?

Simon

comment:13 Changed 21 months ago by pcapriotti

  • Status changed from new to merge

Residency is now only 25% bigger in HEAD. Closing.

comment:14 Changed 21 months ago by pcapriotti

  • Resolution set to fixed
  • Status changed from merge to closed
Note: See TracTickets for help on using tickets.