#16102: forkProcess causes weird GC summary in the child process -------------------------------------+------------------------------------- Reporter: osa1 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Runtime System | Version: 8.6.3 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Description changed by osa1: Old description:
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 https://gitlab.haskell.org/ghc/ghc/merge_requests/51 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.
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).
New description: 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 https://gitlab.haskell.org/ghc/ghc/merge_requests/51 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). -- -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/16102#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler