[GHC] #15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled
#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
#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
#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 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 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 -- -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:2 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#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
#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: | -------------------------------------+------------------------------------- Changes (by osa1): * cc: osa1 (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#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: | -------------------------------------+------------------------------------- Changes (by osa1): * cc: duog (added) Comment: This is probably introduced in #14660 (Phab:D4303). -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:5 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#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: | -------------------------------------+------------------------------------- Changes (by osa1): * cc: bgamari (added) Comment: If I run this program with debug runtime I get this assertion failure: {{{ Main: internal error: ASSERTION FAILED: file rts/Stats.c, line 1123 (GHC version 8.7.20181115 for x86_64_unknown_linux) Please report this as a GHC bug: http://www.haskell.org/ghc/reportabug zsh: abort (core dumped) ./Main 5000000 +RTS -s -h }}} Code that fails: {{{ // The subdivision of runtime into INIT/EXIT/GC/MUT is just adding // and subtracting, so the parts should add up to the total exactly. // Note that stats->total_ns is captured a tiny bit later than // end_exit_elapsed, so we don't use it here. ASSERT(stats.init_elapsed_ns \ + stats.mutator_elapsed_ns \ + stats.gc_elapsed_ns \ + sum.exit_elapsed_ns \ == end_exit_elapsed - start_init_elapsed); }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:6 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled -------------------------------------+------------------------------------- Reporter: maoe | Owner: (none) Type: bug | Status: patch Priority: normal | Milestone: 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: | -------------------------------------+------------------------------------- Changes (by osa1): * status: new => patch Comment: Fix at https://gitlab.haskell.org/ghc/ghc/merge_requests/51 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:8 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled -------------------------------------+------------------------------------- Reporter: maoe | Owner: (none) Type: bug | Status: merge Priority: normal | Milestone: 8.8.1 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: | -------------------------------------+------------------------------------- Changes (by osa1): * status: patch => merge * milestone: => 8.8.1 Comment: Fixed with 19670bc397. @bgamari I'm milestoning this to 8.8.1, please revert if you disagree. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:9 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled
-------------------------------------+-------------------------------------
Reporter: maoe | Owner: (none)
Type: bug | Status: merge
Priority: normal | Milestone: 8.8.1
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: |
-------------------------------------+-------------------------------------
Comment (by Ömer Sinan Ağacan
#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled -------------------------------------+------------------------------------- Reporter: maoe | Owner: (none) Type: bug | Status: merge Priority: normal | Milestone: 8.8.1 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: | -------------------------------------+------------------------------------- Comment (by sgraf): There was a (probably) spurious failure of this in https://gitlab.haskell.org/ghc/ghc/-/jobs/20475. Let's see if this happens again (https://gitlab.haskell.org/ghc/ghc/-/jobs/20799). -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:11 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15897: Negative MUT time in +RTS -s -RTS when heap profiling is enabled -------------------------------------+------------------------------------- Reporter: maoe | Owner: (none) Type: bug | Status: merge Priority: normal | Milestone: 8.8.1 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: | -------------------------------------+------------------------------------- Comment (by osa1): The failures are due to test timing out on CI because it takes too long sometimes. I'll try to find a smaller test case. I think I've never tried making the input smaller, maybe that still reproduces the bug. I should try that first. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15897#comment:12 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
participants (1)
-
GHC