[Haskell-cafe] SMP parallelism increasing GC time dramatically

Tom Thorne thomas.thorne21 at gmail.com
Wed Oct 5 20:15:28 CEST 2011


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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.haskell.org/pipermail/haskell-cafe/attachments/20111005/46921279/attachment-0001.htm>


More information about the Haskell-Cafe mailing list