Skip to content

forkProcess causes weird GC summary in the child process

The existing test forkprocess01 actually exhibits this behavior, but we just don't have the necessary assertions in place to catch it. One of the assertions I added in !51 (merged) catches this bug.

Here's the output with GHC 8.4:

$ ghc forkprocess01.hs -debug -rtsopts
[1 of 1] Compiling Main             ( forkprocess01.hs, forkprocess01.o )
Linking forkprocess01 ...

$ ./forkprocess01 +RTS -s
          44,144 bytes allocated in the heap
           4,824 bytes copied during GC
          37,696 bytes maximum residency (1 sample(s))
          19,648 bytes maximum slop
               2 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0         0 colls,     0 par    0.000s   0.000s     0.0000s    0.0000s
  Gen  1         1 colls,     0 par    0.001s   0.001s     0.0006s    0.0006s

  INIT    time    0.000s  (  0.000s elapsed)
  MUT     time    0.000s  (  0.001s elapsed)
  GC      time    0.001s  (  0.001s elapsed)
  EXIT    time    0.000s  (  0.000s elapsed)
  Total   time    0.000s  (  0.002s elapsed)

  %GC     time     61200000.0%  (32.3% elapsed)

  Alloc rate    0 bytes per MUT second

  Productivity -100999900.0% of total user, 47.2% of total elapsed

Just (Exited (ExitFailure 72))
          54,160 bytes allocated in the heap
           3,480 bytes copied during GC
          44,576 bytes maximum residency (1 sample(s))
          25,056 bytes maximum slop
               2 MB total memory in use (0 MB lost due to fragmentation)

                                     Tot time (elapsed)  Avg pause  Max pause
  Gen  0         0 colls,     0 par    0.000s   0.000s     0.0000s    0.0000s
  Gen  1         1 colls,     0 par    0.001s   0.001s     0.0005s    0.0005s

  INIT    time    0.000s  (  0.000s elapsed)
  MUT     time    0.001s  (  0.003s elapsed)
  GC      time    0.001s  (  0.001s elapsed)
  EXIT    time    0.000s  (  0.000s elapsed)
  Total   time    0.002s  (  0.004s elapsed)

  %GC     time      32.0%  (14.5% elapsed)

  Alloc rate    87,073,954 bytes per MUT second

  Productivity  43.3% of total user, 74.6% of total elapsed

Notice the -100999900.0% productivity in the first summary, which is printed by the child process.

Can also reproduce with 8.6.3 and GHC HEAD.

Note that you sometimes need to run this a few times to reproduce. Every once in a while I get normal results (where productivity is not negative).

Edited by Ömer Sinan Ağacan
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information