[Haskell-cafe] Space Leak with semi-implicit parallelization and the nasty Garbage collector

Daniel Fischer daniel.is.fischer at web.de
Wed Dec 23 21:09:49 EST 2009


Am Donnerstag 24 Dezember 2009 02:14:51 schrieb Michael Lesniak:
> Hello haskell-cafe (and merry christmas!),
>
> I have a strange problem with the garbage collector / memory which I'm
> unable to find a solution for. I think the source of my problems has to do
> with lazy evaluation, but currently I'm unable to find it.
>
> Using the attached program and threadscope I see that the GC is using a lot
> of time and the program comes (more or less) to a halt (see exa-1.png).
> When I increase the heap the program takes much longer and the GC is
> running more or less all the time (see exa-2.png).
>
> Some more detailled information:
>
> * I can see the described behaviour under both GHC 10.4 and GHC 12.1
> * Linux kernel 2.6.31-16 on a dualcore
> * Program compiled with ghc --make -O2 -threaded -eventlog Example.hs -o
> exa * Started with exa +RTS -ls and one of { -N, -N1, -N2 }
>
> Any help (pointing into the right direction, mention possibly helpful
> blog articles
> or paper, constructive critic in general) is appreciated!

I can't reproduce that  (ghc-6.12.1, Linux linux-mkk1 2.6.27.39-0.2-pae #1 SMP 2009-11-23 
12:57:38 +0100 i686 i686 i386 GNU/Linux, dual core):

$  time ./exa +RTS -ls -N2 -sstderr     
./exa +RTS -ls -N2 -sstderr                                                  
1                                                                            
3                                                                            
0                                                                            
0                                                                            
9                                                                            
3                                                                            
6                                                                            
9                                                                            
1                                                                            
8                                                                            
8                                                                            
9                                                                            
2                                                                            
5                                                                            
5                                                                            
8                                                                            
6                                                                            
5                                                                            
7                                                                            
8                                                                            
4                                                                            
  72,499,126,908 bytes allocated in the heap                                 
      45,280,708 bytes copied during GC                                      
         177,504 bytes maximum residency (10 sample(s))
         183,844 bytes maximum slop
               4 MB total memory in use (1 MB lost due to fragmentation)

  Generation 0: 131527 collections, 131526 parallel,  7.18s,  3.88s elapsed
  Generation 1:    10 collections,    10 parallel,  0.00s,  0.00s elapsed

  Parallel GC work balance: 1.16 (10931266 / 9433437, ideal 2)

                        MUT time (elapsed)       GC time  (elapsed)
  Task  0 (worker) :  115.10s    (126.56s)       3.34s    (  1.84s)
  Task  1 (worker) :  124.21s    (126.56s)       3.84s    (  2.04s)
  Task  2 (worker) :    0.09s    (126.56s)       0.00s    (  0.00s)
  Task  3 (worker) :    0.00s    (126.56s)       0.00s    (  0.00s)

  SPARKS: 21 (21 converted, 0 pruned)

  INIT  time    0.00s  (  0.13s elapsed)
  MUT   time  238.05s  (126.56s elapsed)
  GC    time    7.19s  (  3.88s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time  244.46s  (130.57s elapsed)

  %GC time       2.9%  (3.0% elapsed)

  Alloc rate    305,559,453 bytes per MUT second

  Productivity  97.1% of total user, 181.7% of total elapsed

gc_alloc_block_sync: 151252
whitehole_spin: 0
gen[0].steps[0].sync_large_objects: 75620
gen[0].steps[1].sync_large_objects: 9662
gen[1].steps[0].sync_large_objects: 0
244.45user 2.06system 2:10.58elapsed 188%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+35736outputs (0major+2426minor)pagefaults 0swaps

Garbage collection isn't even visible in the threadscope profile.

With -N1:
  71,999,280,108 bytes allocated in the heap                            
      20,729,380 bytes copied during GC
          92,492 bytes maximum residency (2 sample(s))
         190,872 bytes maximum slop
               3 MB total memory in use (0 MB lost due to fragmentation)

  Generation 0: 130901 collections,     0 parallel,  2.64s,  2.68s elapsed
  Generation 1:     2 collections,     0 parallel,  0.00s,  0.00s elapsed

  Parallel GC work balance: nan (0 / 0, ideal 1)

                        MUT time (elapsed)       GC time  (elapsed)
  Task  0 (worker) :  184.86s    (206.14s)       2.38s    (  2.40s)
  Task  1 (worker) :    0.00s    (216.71s)       0.00s    (  0.00s)
  Task  2 (worker) :   20.90s    (216.71s)       0.26s    (  0.28s)

  SPARKS: 21 (19 converted, 2 pruned)

  INIT  time    0.00s  (  0.05s elapsed)
  MUT   time  215.33s  (216.71s elapsed)
  GC    time    2.64s  (  2.68s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time  217.96s  (219.44s elapsed)

  %GC time       1.2%  (1.2% elapsed)

  Alloc rate    334,374,215 bytes per MUT second

  Productivity  98.8% of total user, 98.1% of total elapsed

gc_alloc_block_sync: 0
whitehole_spin: 0
gen[0].steps[0].sync_large_objects: 0
gen[0].steps[1].sync_large_objects: 0
gen[1].steps[0].sync_large_objects: 0
217.96user 0.88system 3:39.52elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
1576inputs+19552outputs (5major+1686minor)pagefaults 0swaps

>
> Best wishes,
> Michael


-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.haskell.org/pipermail/haskell-cafe/attachments/20091223/2e564b73/attachment-0001.html


More information about the Haskell-Cafe mailing list