Hi Tom,
I think debugging this sort of problem is exactly what we need to be doing
(and making easier). Have you tried Duncan's newest version of Threadscope
by the way?
It looks like -- completely aside from the GC time -- this program is not
scaling. The mutator time itself, disregarding GC, isn't going down much
with parallelism (with the total mutator time increasing drastically).
Either this is completely memory bottlenecked or there is some other kind
of bad interaction (e.g. false sharing, contention on a hot lock, etc).
My inclination would be to figure this out first before worrying about the
GC time. Is this code that you would be able to share for debugging?
I think we need to get together some general documentation on how to debug
this kind of problem. For example, you can get some hints as to the memory
behavior by running valgrind/cachegrind on the program. Also, what does
"top" say, by the way? Is the process using 1200% CPU?
Cheers,
-Ryan
On Wed, Oct 5, 2011 at 2:15 PM, Tom Thorne
I am having some strange performance issues when using SMP parallelism, that I think may be something to do with GC. Apologies for the large readouts below but I'm not familiar enough to know what is and isn't relevant!
I have a pure function that is mapped over a list of around 10 values, and this happens several times for each iteration of my program. It does some fairly intensive calculations using hmatrix, generating intermediate matrices along the way. The computation is significantly more complex for some values, so the work done by each call is not spread equally. I did some profiling and it seems like the program is spending about 50% of its time in that function. First of all, without any attempts at parallelism, I see this from ./Main +RTS -s
67,142,126,336 bytes allocated in the heap 147,759,264 bytes copied during GC 109,384 bytes maximum residency (58 sample(s)) 354,408 bytes maximum slop 3 MB total memory in use (0 MB lost due to fragmentation)
Generation 0: 104551 collections, 0 parallel, 1.13s, 1.11s elapsed Generation 1: 58 collections, 0 parallel, 0.01s, 0.01s elapsed
Parallel GC work balance: -nan (0 / 0, ideal 1)
MUT time (elapsed) GC time (elapsed) Task 0 (worker) : 0.00s ( 67.06s) 0.00s ( 0.00s) Task 1 (worker) : 0.00s ( 67.09s) 0.00s ( 0.00s) Task 2 (bound) : 66.95s ( 67.09s) 1.14s ( 1.12s)
SPARKS: 0 (0 converted, 0 pruned)
INIT time 0.00s ( 0.00s elapsed) MUT time 66.95s ( 67.09s elapsed) GC time 1.14s ( 1.12s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 68.09s ( 68.21s elapsed)
%GC time 1.7% (1.6% elapsed)
Alloc rate 1,002,835,517 bytes per MUT second
Productivity 98.3% of total user, 98.2% of total elapsed
gc_alloc_block_sync: 0 whitehole_spin: 0 gen[0].sync_large_objects: 0 gen[1].sync_large_objects: 0
This looks ok to me...
Then if I try to use Control.Parallel to parallelise my code, simpy replacing a map with parMap (rdeepseq), on a 12 core machine using +RTS -N12 -s I get this:
66,065,148,144 bytes allocated in the heap 197,202,056 bytes copied during GC 181,312 bytes maximum residency (251 sample(s)) 387,240 bytes maximum slop 12 MB total memory in use (3 MB lost due to fragmentation)
Generation 0: 37592 collections, 37591 parallel, 245.32s, 26.67s elapsed Generation 1: 251 collections, 251 parallel, 3.12s, 0.33s elapsed
Parallel GC work balance: 2.41 (24219609 / 10058220, ideal 12)
MUT time (elapsed) GC time (elapsed) Task 0 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 1 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 2 (worker) : 0.00s ( 17.97s) 0.00s ( 0.00s) Task 3 (worker) : 0.00s ( 19.35s) 0.00s ( 0.00s) Task 4 (worker) : 0.00s ( 40.28s) 0.00s ( 0.00s) Task 5 (worker) : 0.00s ( 45.08s) 0.00s ( 0.00s) Task 6 (worker) : 0.00s ( 47.06s) 0.00s ( 0.00s) Task 7 (worker) : 18.30s ( 49.73s) 16.24s ( 1.71s) Task 8 (worker) : 0.00s ( 51.22s) 0.00s ( 0.00s) Task 9 (worker) : 0.00s ( 53.75s) 0.00s ( 0.00s) Task 10 (worker) : 0.00s ( 54.17s) 0.00s ( 0.00s) Task 11 (worker) : 5.65s ( 54.30s) 0.70s ( 0.08s) Task 12 (worker) : 0.00s ( 54.41s) 0.41s ( 0.04s) Task 13 (worker) : 4.34s ( 54.58s) 4.50s ( 0.48s) Task 14 (worker) : 5.82s ( 54.76s) 5.91s ( 0.64s) Task 15 (worker) : 6.50s ( 55.01s) 3.37s ( 0.38s) Task 16 (worker) : 7.60s ( 55.21s) 8.56s ( 0.94s) Task 17 (worker) : 11.05s ( 55.21s) 9.04s ( 0.96s) Task 18 (worker) : 11.75s ( 55.21s) 12.94s ( 1.43s) Task 19 (worker) : 16.02s ( 55.21s) 13.32s ( 1.43s) Task 20 (worker) : 26.98s ( 55.23s) 7.43s ( 0.77s) Task 21 (worker) : 7.36s ( 55.23s) 7.47s ( 0.83s) Task 22 (worker) : 16.08s ( 55.23s) 10.25s ( 1.12s) Task 23 (worker) : 7.04s ( 55.23s) 4.99s ( 0.57s) Task 24 (worker) : 28.47s ( 55.23s) 8.78s ( 0.94s) Task 25 (worker) : 7.43s ( 55.23s) 1.62s ( 0.18s) Task 26 (worker) : 6.33s ( 55.23s) 11.42s ( 1.23s) Task 27 (worker) : 9.80s ( 55.23s) 8.72s ( 0.95s) Task 28 (worker) : 4.88s ( 55.26s) 8.92s ( 0.99s) Task 29 (worker) : 0.00s ( 55.26s) 0.00s ( 0.00s) Task 30 (bound) : 5.59s ( 55.26s) 0.59s ( 0.06s) Task 31 (worker) : 41.16s ( 55.26s) 3.48s ( 0.38s) Task 32 (worker) : 17.03s ( 55.26s) 3.90s ( 0.42s) Task 33 (worker) : 14.89s ( 55.26s) 5.29s ( 0.58s) Task 34 (worker) : 6.30s ( 55.26s) 1.99s ( 0.21s) Task 35 (worker) : 16.13s ( 55.26s) 13.95s ( 1.50s) Task 36 (worker) : 16.70s ( 55.26s) 13.02s ( 1.41s) Task 37 (worker) : 11.68s ( 55.26s) 15.45s ( 1.68s) Task 38 (worker) : 7.65s ( 55.26s) 13.61s ( 1.50s) Task 39 (worker) : 14.18s ( 55.26s) 12.48s ( 1.35s) Task 40 (worker) : 5.51s ( 55.26s) 11.92s ( 1.31s) Task 41 (worker) : 3.10s ( 55.26s) 8.17s ( 0.93s)
SPARKS: 42525 (37707 converted, 519 pruned)
INIT time 0.00s ( 0.00s elapsed) MUT time 365.55s ( 55.26s elapsed) GC time 248.45s ( 27.00s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 614.01s ( 82.26s elapsed)
%GC time 40.5% (32.8% elapsed)
Alloc rate 180,724,403 bytes per MUT second
Productivity 59.5% of total user, 444.4% of total elapsed
gc_alloc_block_sync: 1339708 whitehole_spin: 36 gen[0].sync_large_objects: 197621 gen[1].sync_large_objects: 6396
It seems like suddenly GC is taking a lot longer.
I also tried using Control.Monad.Par, with runPar $ do parMap, and using +RTS -N12 -s I get this:
71,480,561,920 bytes allocated in the heap 275,752,912 bytes copied during GC 198,704 bytes maximum residency (343 sample(s)) 394,232 bytes maximum slop 12 MB total memory in use (3 MB lost due to fragmentation)
Generation 0: 37575 collections, 37574 parallel, 169.08s, 16.67s elapsed Generation 1: 343 collections, 343 parallel, 6.24s, 0.61s elapsed
Parallel GC work balance: 2.56 (33928871 / 13275450, ideal 12)
MUT time (elapsed) GC time (elapsed) Task 0 (worker) : 0.70s ( 46.46s) 0.00s ( 0.00s) Task 1 (worker) : 2.94s ( 46.46s) 0.00s ( 0.00s) Task 2 (worker) : 0.10s ( 46.46s) 0.00s ( 0.00s) Task 3 (worker) : 0.06s ( 46.47s) 0.00s ( 0.00s) Task 4 (worker) : 1.70s ( 46.47s) 0.00s ( 0.00s) Task 5 (worker) : 0.07s ( 46.47s) 0.00s ( 0.00s) Task 6 (worker) : 2.75s ( 46.47s) 0.00s ( 0.00s) Task 7 (worker) : 1.21s ( 46.47s) 0.00s ( 0.00s) Task 8 (worker) : 0.43s ( 46.47s) 0.00s ( 0.00s) Task 9 (worker) : 10.44s ( 46.47s) 0.00s ( 0.00s) Task 10 (worker) : 0.06s ( 46.47s) 0.00s ( 0.00s) Task 11 (worker) : 1.36s ( 46.47s) 0.00s ( 0.00s) Task 12 (worker) : 0.00s ( 46.50s) 46.69s ( 4.63s) Task 13 (worker) : 0.00s ( 46.50s) 0.00s ( 0.00s) Task 14 (bound) : 0.05s ( 46.50s) 0.56s ( 0.06s) Task 15 (worker) : 24.84s ( 46.50s) 2.24s ( 0.21s) Task 16 (worker) : 28.00s ( 46.50s) 1.95s ( 0.19s) Task 17 (worker) : 35.30s ( 46.50s) 2.79s ( 0.27s) Task 18 (worker) : 29.03s ( 46.50s) 4.06s ( 0.39s) Task 19 (worker) : 32.71s ( 46.50s) 7.04s ( 0.69s) Task 20 (worker) : 32.74s ( 46.50s) 11.47s ( 1.09s) Task 21 (worker) : 23.35s ( 46.50s) 15.16s ( 1.49s) Task 22 (worker) : 36.00s ( 46.50s) 7.94s ( 0.76s) Task 23 (worker) : 0.00s ( 46.50s) 35.84s ( 3.63s) Task 24 (worker) : 24.70s ( 46.50s) 21.26s ( 2.06s) Task 25 (worker) : 23.07s ( 46.50s) 18.33s ( 1.82s)
SPARKS: 0 (0 converted, 0 pruned)
INIT time 0.00s ( 0.00s elapsed) MUT time 307.74s ( 46.50s elapsed) GC time 175.32s ( 17.29s elapsed) EXIT time 0.00s ( 0.00s elapsed) Total time 483.06s ( 63.79s elapsed)
%GC time 36.3% (27.1% elapsed)
Alloc rate 232,274,501 bytes per MUT second
Productivity 63.7% of total user, 482.4% of total elapsed
gc_alloc_block_sync: 1619540 whitehole_spin: 258 gen[0].sync_large_objects: 232661 gen[1].sync_large_objects: 6378
This seems slightly better, but the GC time is still much bigger than I would expect it to be.
I don't think it is solely because of parallel GC, since running the parallel code with +RTS -N1 gives results similar to the non-parallel version.
Am I simply misunderstanding the way the GC time is represented in this output, or is there something amiss?
(I also noticed that there seem to be a lot more than 12 threads running if I look at top while the program is running, but I assume this is something to do with the runtime spawning more threads for GC etc)
_______________________________________________ Haskell-Cafe mailing list Haskell-Cafe@haskell.org http://www.haskell.org/mailman/listinfo/haskell-cafe