Skip to content

Negative MUT time in +RTS -s -RTS when heap profiling is enabled

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 #881##15897 (closed)

{-# 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
Edited by Mitsutoshi Aoe
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information