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

14 Nov 2018

      #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
           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:
-------------------------------------+-------------------------------------
 Mutator run time in +RTS -s -RTS can go negative in GHC 8.6.x when
 retainer 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 yesterday's HEAD 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

-- 
Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897
GHC http://www.haskell.org/ghc/
The Glasgow Haskell Compiler