[GHC] #15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled

[GHC]

#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled
-------------------------------------+-------------------------------------
        Reporter:  maoe              |                Owner:  (none)
            Type:  bug               |               Status:  new
        Priority:  normal            |            Milestone:  8.6.3
       Component:  Profiling         |              Version:  8.6.2
      Resolution:                    |             Keywords:
Operating System:  Linux             |         Architecture:  x86_64
 Type of failure:  Debugging         |  (amd64)
  information is incorrect           |            Test Case:
      Blocked By:                    |             Blocking:
 Related Tickets:                    |  Differential Rev(s):
       Wiki Page:                    |
-------------------------------------+-------------------------------------
Description changed by maoe:

Old description:

> Mutator run time in +RTS -s -RTS can go negative in GHC 8.6.x when heap
> profiling is enabled.
>

> Here is an example taken from
> https://ghc.haskell.org/trac/ghc/ticket/881#comment:9
> {{{
> {-# OPTIONS_GHC -fprof-auto #-}
> import Control.Monad
> import Data.IORef
> import System.Environment
>
> main = do
>   [n] <- getArgs
>   replicateM (read n) (newIORef [1,2,3])
> }}}
> {{{
> % ghc-8.6.2 -prof -rtsopts -fforce-recomp repro.hs
> [1 of 1] Compiling Main             ( repro.hs, repro.o )
> Linking repro ...
> % ./repro 10000000 +RTS -s -h
>    3,053,080,472 bytes allocated in the heap
>    5,538,404,848 bytes copied during GC
>    1,013,615,328 bytes maximum residency (16 sample(s))
>       36,422,944 bytes maximum slop
>              966 MB total memory in use (0 MB lost due to fragmentation)
>
>                                      Tot time (elapsed)  Avg pause  Max
> pause
>   Gen  0      2600 colls,     0 par    1.375s   1.376s     0.0005s
> 0.0019s
>   Gen  1        16 colls,     0 par    4.355s   4.355s     0.2722s
> 1.0136s
>
>   INIT    time    0.000s  (  0.000s elapsed)
>   MUT     time    0.000s  ( -0.833s elapsed)
>   GC      time    4.016s  (  4.016s elapsed)
>   RP      time    0.000s  (  0.000s elapsed)
>   PROF    time    1.715s  (  1.715s elapsed)
>   EXIT    time    1.715s  (  1.715s elapsed)
>   Total   time    6.612s  (  6.612s elapsed)
>
>   %GC     time       0.0%  (0.0% elapsed)
>
>   Alloc rate    0 bytes per MUT second
>
>   Productivity -12.6% of total user, -12.6% of total elapsed
>
> }}}
>
> Here is what I found so far:
>
> * GHC 8.6.1, 8.6.2, and recent HEAD (20181112) have the same issue. GHC
> 8.4.4 doesn't have this issue.
> * `-hr` has the same issue. `-hT` is fine.
> * Without heap profiling the numbers this doesn't happen

New description:

 Mutator run time in +RTS -s -RTS can go negative in GHC 8.6.x when heap
 profiling is enabled.


 Here is an example taken from
 https://ghc.haskell.org/trac/ghc/ticket/881#comment:9
 {{{
 {-# OPTIONS_GHC -fprof-auto #-}
 import Control.Monad
 import Data.IORef
 import System.Environment

 main = do
   [n] <- getArgs
   replicateM (read n) (newIORef [1,2,3])
 }}}
 {{{
 % ghc-8.6.2 -prof -rtsopts -fforce-recomp repro.hs
 [1 of 1] Compiling Main             ( repro.hs, repro.o )
 Linking repro ...
 % ./repro 10000000 +RTS -s -h
    3,053,080,472 bytes allocated in the heap
    5,538,404,848 bytes copied during GC
    1,013,615,328 bytes maximum residency (16 sample(s))
       36,422,944 bytes maximum slop
              966 MB total memory in use (0 MB lost due to fragmentation)

                                      Tot time (elapsed)  Avg pause  Max
 pause
   Gen  0      2600 colls,     0 par    1.375s   1.376s     0.0005s
 0.0019s
   Gen  1        16 colls,     0 par    4.355s   4.355s     0.2722s
 1.0136s

   INIT    time    0.000s  (  0.000s elapsed)
   MUT     time    0.000s  ( -0.833s elapsed)
   GC      time    4.016s  (  4.016s elapsed)
   RP      time    0.000s  (  0.000s elapsed)
   PROF    time    1.715s  (  1.715s elapsed)
   EXIT    time    1.715s  (  1.715s elapsed)
   Total   time    6.612s  (  6.612s elapsed)

   %GC     time       0.0%  (0.0% elapsed)

   Alloc rate    0 bytes per MUT second

   Productivity -12.6% of total user, -12.6% of total elapsed

 }}}

 Here is what I found so far:

 * GHC 8.6.1, 8.6.2, and recent HEAD (20181112) have the same issue. GHC
 8.4.4 doesn't have this issue.
 * `-hr` has the same issue. `-hT` is fine.
 * Without heap profiling the numbers look fine

--

-- 
Ticket URL: <http://ghc.haskell.org/trac/ghc/ticket/15897#comment:3>
GHC <http://www.haskell.org/ghc/>
The Glasgow Haskell Compiler