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).