[GHC] #16102: forkProcess causes weird GC summary in the child process

[GHC]

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

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.

 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:2>
GHC <http://www.haskell.org/ghc/>
The Glasgow Haskell Compiler