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