diff options
| author | Ömer Sinan Ağacan <omeragacan@gmail.com> | 2018-12-28 13:51:28 +0300 |
|---|---|---|
| committer | Ömer Sinan Ağacan <omeragacan@gmail.com> | 2019-01-12 06:52:38 -0500 |
| commit | 19670bc397d858b04eb9b4eb01480f7f8c59e2f5 (patch) | |
| tree | 0e84040446183e032bcd05f2a8c1fd620ba1b9b2 /testsuite/tests/profiling | |
| parent | 74cd4ec5d2f9321aad5db3285cb60d78f2562996 (diff) | |
| download | haskell-19670bc397d858b04eb9b4eb01480f7f8c59e2f5.tar.gz | |
Fix negative mutator time in GC stats in prof builds
Because garbage collector calls `retainerProfile()` and `heapCensus()`,
GC times normally include some of PROF times too. To fix this we have
these lines:
// heapCensus() is called by the GC, so RP and HC time are
// included in the GC stats. We therefore subtract them to
// obtain the actual GC cpu time.
stats.gc_cpu_ns -= prof_cpu;
stats.gc_elapsed_ns -= prof_elapsed;
These variables are later used for calculating GC time excluding the
final GC (which should be attributed to EXIT).
exit_gc_elapsed = stats.gc_elapsed_ns - start_exit_gc_elapsed;
The problem is if we subtract PROF times from `gc_elapsed_ns` and then
subtract `start_exit_gc_elapsed` from the result, we end up subtracting
PROF times twice, because `start_exit_gc_elapsed` also includes PROF
times.
We now subtract PROF times from GC after the calculations for EXIT and
MUT times. The existing assertion that checks
INIT + MUT + GC + EXIT = TOTAL
now holds. When we subtract PROF numbers from GC, and a new assertion
INIT + MUT + GC + PROF + EXIT = TOTAL
also holds.
Fixes #15897. New assertions added in this commit also revealed #16102,
which is also fixed by this commit.
Diffstat (limited to 'testsuite/tests/profiling')
| -rw-r--r-- | testsuite/tests/profiling/should_run/Makefile | 8 | ||||
| -rw-r--r-- | testsuite/tests/profiling/should_run/T15897.hs | 7 | ||||
| -rw-r--r-- | testsuite/tests/profiling/should_run/all.T | 5 |
3 files changed, 20 insertions, 0 deletions
diff --git a/testsuite/tests/profiling/should_run/Makefile b/testsuite/tests/profiling/should_run/Makefile index d52bda1918..19a682fb97 100644 --- a/testsuite/tests/profiling/should_run/Makefile +++ b/testsuite/tests/profiling/should_run/Makefile @@ -22,3 +22,11 @@ T14257: ./T14257 +RTS -hc # Make sure that samples are monotonically increasing awk 'BEGIN{t=0} /BEGIN_SAMPLE/{if ($$2 < t) print "uh oh", $$t, $$0; t=$$2;}' T14257.hp + +.PHONY: T15897 +T15897: + # The bug is caught by an assertion so we run the tests with debug runtime + # and ignore the outputs + "$(TEST_HC)" -prof -fprof-auto -debug -v0 T15897.hs + ./T15897 10000000 +RTS -s -hc 2>/dev/null + ./T15897 10000000 +RTS -s -hr 2>/dev/null diff --git a/testsuite/tests/profiling/should_run/T15897.hs b/testsuite/tests/profiling/should_run/T15897.hs new file mode 100644 index 0000000000..b004cd1248 --- /dev/null +++ b/testsuite/tests/profiling/should_run/T15897.hs @@ -0,0 +1,7 @@ +import Control.Monad +import Data.IORef +import System.Environment + +main = do + [n] <- getArgs + replicateM (read n) (newIORef [1,2,3]) diff --git a/testsuite/tests/profiling/should_run/all.T b/testsuite/tests/profiling/should_run/all.T index 968d678164..9bca86b274 100644 --- a/testsuite/tests/profiling/should_run/all.T +++ b/testsuite/tests/profiling/should_run/all.T @@ -145,3 +145,8 @@ test('toplevel_scc_1', test('T12962', [], compile_and_run, ['']) test('T14257', [], run_command, ['$MAKE -s --no-print-directory T14257']) + +test('T15897', + [extra_ways(['profasm']), only_ways(['profasm']), run_timeout_multiplier(2)], + run_command, + ['$MAKE -s --no-print-directory T15897']) |