[email protected]
[Top] [All Lists]

Re: [Haskell-cafe] Space Leak with semi-implicit parallelization and th

Subject: Re: [Haskell-cafe] Space Leak with semi-implicit parallelization and the nasty Garbage collector
From: Michael Lesniak
Date: Thu, 24 Dec 2009 10:35:45 +0100
Hello Daniel,

thanks for your fast response. That's strange: On your system "total
time elapsed" according to GHC is ~190%, on mine (reproducible!) ~140%
(see below). I once had a problem with a particular linux kernel[1],
unfortunately I currently (over the holidays) have no other computers
available.

Does anyone also have an up-to-date ubuntu karmic 9.10 with my kernel
version to confirm or refute the problem's dependency on the linux
kernel?

A bit irritated, but still in an Haskelllish christmas mood,
  Michael

[1] http://www.mail-archive.com/[email protected]/msg67148.html


> time exa +RTS -N2 -ls -sstderr
exa +RTS -N2 -ls -sstderr
1
3
0
0
9
3
6
9
1
8
8
9
2
5
5
8
6
5
7
8
4
  72,748,227,888 bytes allocated in the heap
      65,331,056 bytes copied during GC
         183,032 bytes maximum residency (22 sample(s))
         209,352 bytes maximum slop
               4 MB total memory in use (1 MB lost due to fragmentation)

  Generation 0: 131339 collections, 131338 parallel,  7.29s,  6.25s elapsed
  Generation 1:    22 collections,    22 parallel,  0.03s,  0.03s elapsed

  Parallel GC work balance: 1.10 (7778368 / 7059369, ideal 2)

                        MUT time (elapsed)       GC time  (elapsed)
  Task  0 (worker) :   66.38s    ( 36.22s)       1.75s    (  1.37s)
  Task  1 (worker) :   66.40s    ( 36.25s)       0.00s    (  0.00s)
  Task  2 (worker) :   68.13s    ( 36.25s)       0.00s    (  0.00s)
  Task  3 (worker) :   62.56s    ( 36.25s)       5.57s    (  4.91s)

  SPARKS: 21 (21 converted, 0 pruned)

  INIT  time    0.00s  (  0.01s elapsed)
  MUT   time   60.81s  ( 36.25s elapsed)
  GC    time    7.32s  (  6.28s elapsed)
  EXIT  time    0.00s  (  0.00s elapsed)
  Total time   66.40s  ( 42.54s elapsed)

  %GC time      11.0%  (14.8% elapsed)

  Alloc rate    1,231,351,182 bytes per MUT second

  Productivity  89.0% of total user, 138.9% of total elapsed

gc_alloc_block_sync: 61137
whitehole_spin: 0
gen[0].steps[0].sync_large_objects: 17681
gen[0].steps[1].sync_large_objects: 20647
gen[1].steps[0].sync_large_objects: 0

real    0m42.626s
user    1m6.400s
sys     0m0.510s


2009/12/24 Daniel Fischer <[email protected]>:
> 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



-- 
Dipl.-Inf. Michael C. Lesniak
University of Kassel
Programming Languages / Methodologies Research Group
Department of Computer Science and Electrical Engineering

Wilhelmshöher Allee 73
34121 Kassel

Phone: +49-(0)561-804-6269
_______________________________________________
Haskell-Cafe mailing list
[email protected]
http://www.haskell.org/mailman/listinfo/haskell-cafe

<Prev in Thread] Current Thread [Next in Thread>