What is GHC doing when run with -N (parallel) flag?

Viewed 297

I've written the following test application:

main = print $ sum $ map (read . show) [1 .. 10^7]

When I run it with and without -N flag, I get the following results:

$ ghc -O2 -threaded -rtsopts -o test test.hs
...
$ time ./test +RTS -s
50000005000000
real    0m12.411s
user    0m12.367s
sys     0m0.040s
$ time ./test +RTS -s -N12
50000005000000
real    0m22.702s
user    1m14.904s
sys     0m12.608s

It seems like GHC decides to honour the -N12 flag by distributing the calculation over different cores (with very bad results), but I can't find any documentation about how exactly it decides to do so when the code doesn't contain explicit instructions. Is there some documentation that I'm missing?

I have GHC version 8.6.5.

Garbage collection statistics:

$ ghc -O2 -threaded -rtsopts -o test test.hs
...
$ time ./test +RTS -s
50000005000000
  54,332,520,712 bytes allocated in the heap
      53,571,832 bytes copied during GC
          56,824 bytes maximum residency (2 sample(s))
          29,192 bytes maximum slop
               0 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0     52088 colls,     0 par    0.154s   0.150s     0.0000s    0.0001s
  Gen  1         2 colls,     0 par    0.000s   0.000s     0.0001s    0.0001s

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

  SPARKS: 0(0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

  INIT    time    0.000s  (  0.000s elapsed)
  MUT     time   12.250s  ( 12.249s elapsed)
  GC      time    0.155s  (  0.151s elapsed)
  EXIT    time    0.001s  (  0.010s elapsed)
  Total   time   12.406s  ( 12.410s elapsed)

  Alloc rate    4,435,169,879 bytes per MUT second

  Productivity  98.7% of total user, 98.7% of total elapsed


real    0m12.411s
user    0m12.367s
sys     0m0.040s
$ time ./test +RTS -s -N12
50000005000000
  54,332,687,840 bytes allocated in the heap
     214,001,248 bytes copied during GC
         183,360 bytes maximum residency (2 sample(s))
         146,696 bytes maximum slop
               0 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0     52088 colls, 52088 par   20.219s   0.975s     0.0000s    0.0001s
  Gen  1         2 colls,     1 par    0.001s   0.000s     0.0001s    0.0002s

  Parallel GC work balance: 0.15% (serial 0%, perfect 100%)

  TASKS: 26 (1 bound, 25 peak workers (25 total), using -N12)

  SPARKS: 0(0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)

  INIT    time    0.007s  (  0.003s elapsed)
  MUT     time   67.281s  ( 21.720s elapsed)
  GC      time   20.221s  (  0.975s elapsed)
  EXIT    time    0.002s  (  0.003s elapsed)
  Total   time   87.511s  ( 22.701s elapsed)

  Alloc rate    807,549,654 bytes per MUT second

  Productivity  76.9% of total user, 95.7% of total elapsed


real    0m22.702s
user    1m14.904s
sys     0m12.608s

1 Answers

GHC doesn't automatically parallelize code. (The runtime system itself may take advantage of multiple threads for initialization giving a small, fixed performance improvement at startup, but that's the only thing that happends "automatically".)

So, your code is running sequentially. As noted in some of the comments, the bizarre performance problem is probably parallel garbage collection.

Parallel GC has been observed to perform very poorly on certain workloads when running on large numbers of capabilities. See issue #14981, for example. Of course, that issue talks about 32- or 64-core machines.

However, I have observed very poor performance especially with the default runtime GC settings even on relatively small numbers of cores. For example, using your test case and GHC version, I get similar poor performance on my 8-core, 16-thread Intel i9-9980HK laptop with -N12 or more. Here is the comparison of a 1-capability and 12-capability run. Compile it:

$ cat test.hs
main = print $ sum $ map (read . show) [1 .. 10^7]
$ stack ghc --resolver=lts-14.27 -- -fforce-recomp -O2 -threaded -rtsopts -o test test.hs
[1 of 1] Compiling Main             ( test.hs, test.o )
Linking test ...

Run it on one capability:

$ time ./test +RTS -N1
50000005000000

real    0m10.803s
user    0m10.770s
sys     0m0.037s

Run it on twelve:

$ time ./test +RTS -N12
50000005000000

real    0m15.655s
user    0m52.103s
sys     0m7.019s

To see that parallel GC is at fault, we can switch to sequential GC:

$ time ./test +RTS -N12 -qg
50000005000000

real    0m11.175s
user    0m11.066s
sys     0m0.120s

I had assumed that this poor parallel GC performance was related to exceeding the number of physical cores, but your experience suggests this can happen with around 12 capabilities even if it doesn't exceed the physical core count.

Instead of disabling parallel GC entirely, you are advised to play with the runtime garbage collector controls. The effects can be startling. For example, increasing the generation 0 allocation area from its default of 1m to 4m results in a big improvement:

$ time ./test +RTS -N12 -A4m
50000005000000

real    0m12.485s
user    0m25.219s
sys     0m2.053s

and going even higher to 16m eliminates the performance problem entirely, at least for this simple test case.

$ time ./test +RTS -N12 -A16m
50000005000000

real    0m11.481s
user    0m11.775s
sys     0m0.126s

I get similar improvements switching to compaction for the second generation:

$ time ./test +RTS -N12 -c
50000005000000

real    0m11.125s
user    0m11.043s
sys     0m0.089s

Of course, running the parallel GC on a reduced number of cores may also help:

$ time ./test +RTS -N12 -qn4
50000005000000

real    0m14.092s
user    0m18.961s
sys     0m3.031s
Related