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