[GHC] #14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression)
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Runtime | Version: 8.2.1 System | Keywords: | Operating System: Unknown/Multiple Architecture: | Type of failure: None/Unknown Unknown/Multiple | Test Case: | Blocked By: Blocking: | Related Tickets: #14006 Differential Rev(s): | Wiki Page: -------------------------------------+------------------------------------- The following program generates an invalid .hp file when compiled with ghc 8.2.1 but it does not when using ghc 8.0.2. {{{#!hs {-# LANGUAGE ScopedTypeVariables #-} module Main where eval :: forall a b. (a -> b -> b) -> b -> [a] -> b eval f b xs = load xs [] where load :: [a] -> [a] -> b load [] stk = unload b stk load (x:xs) stk = load xs (x : stk) unload :: b -> [a] -> b unload v [] = v unload v (x : stk) = unload ((f $! x) $! v) stk main :: IO () main = print (eval (||) False (True : replicate 10000000 False)) }}} If strict application ($!) is substituted for normal application ($) or removed then the .hp generated file is correct. For reproducing the error: {{{ ghc -O2 --make -prof -fprof-auto Example.hs -fforce-recomp ./Example +RTS -hc hp2ps -e8in -c Example.hp }}} It outputs: {{{ hp2ps: Example.hp, line 43, samples out of sequence }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Indeed I can reproduce this verbatim. Interestingly enough, the sample in question is at the very end up the `hp` file and has no cost centers in it, {{{ ... BEGIN_SAMPLE 0.455729 MAIN 160 (198)GHC.IO.Handle.FD.CAF 680 (218)GHC.Conc.Signal.CAF 640 (225)main 152 (223)Main.CAF 16 (206)GHC.IO.Encoding.Iconv.CAF 120 (208)GHC.IO.Encoding.CAF 1096 (114)PINNED 36816 END_SAMPLE 0.455729 BEGIN_SAMPLE 0.455359 END_SAMPLE 0.455359 }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:1 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): So the bad sample is being written by `endHeapProfiling` which gets its timestamp from `mut_user_time`. This is in contrast to the samples produced during the bulk of the program's execution, which come from `dumpCensus`, which takes its timestamp from `mut_user_time_until(t)`, where `t` comes from `getProcessTimes` (by way of `gct->gc_start_cpu`). I've added a bit of instrumentation, {{{#!patch --- a/rts/ProfHeap.c +++ b/rts/ProfHeap.c @@ -363,6 +363,12 @@ void endProfiling( void ) static void printSample(bool beginSample, StgDouble sampleValue) { + static StgDouble lastValue = 0; + CHECK(sampleValue >= lastValue); + printf("sampleValue=%f\n", sampleValue); + lastValue = sampleValue; + (void) lastValue; + fprintf(hp_file, "%s %f\n", (beginSample ? "BEGIN_SAMPLE" : "END_SAMPLE"), sampleValue); diff --git a/rts/Stats.c b/rts/Stats.c index 6a5f80130e..773c55e431 100644 --- a/rts/Stats.c +++ b/rts/Stats.c @@ -77,6 +77,7 @@ Time stat_getElapsedTime(void) double mut_user_time_until( Time t ) { + printf("mut_user_time_until %f %f \n", TimeToSecondsDbl(t), TimeToSecondsDbl(stats.gc_cpu_ns)); return TimeToSecondsDbl(t - stats.gc_cpu_ns); // heapCensus() time is included in GC_tot_cpu, so we don't need // to subtract it here. @@ -331,6 +332,7 @@ stat_endGC (Capability *cap, gc_thread *gct, stats.cumulative_par_balanced_copied_bytes += stats.gc.par_balanced_copied_bytes; } + printf("end gc %f\n", TimeToSecondsDbl(NSToTime(stats.gc.cpu_ns))); stats.gc_cpu_ns += stats.gc.cpu_ns; stats.gc_elapsed_ns += stats.gc.elapsed_ns; }}} Which produces the following, {{{ ... end gc 0.000205 end gc 0.000195 mut_user_time_until 0.930493 0.603123 sampleValue=0.327370 sampleValue=0.327370 end gc 0.000200 True end gc 0.014411 mut_user_time_until 0.945025 0.617734 hi: internal error: ASSERTION FAILED: file rts/ProfHeap.c, line 367 (GHC version 8.3.20170919 for x86_64_unknown_linux) Please report this as a GHC bug: http://www.haskell.org/ghc/reportabug Aborted }}} I believe what is happening here is that we are producing the second-to- last sample before `stat_endGC` has been run. This means that `stats.gc_cpu_ns` is stale as it does not include the time spent during this present GC. Then, some time later we go to emit the final sample. However, now `stats.gc_cpu_ns` includes the time spent in the final GC, meaning that it may appear that we have "gone backwards" in time. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:2 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * owner: (none) => bgamari * priority: normal => high * milestone: => 8.4.1 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:3 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by mnislaih): * cc: mnislaih (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by alexandersgreen): * cc: alexandersgreen (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:5 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by angerman): * cc: angerman (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:6 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * keywords: => profiler * related: #14006 => #14006, #11645 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:7 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by duog): I had a little look at this. The description in comment:2 looks right to me, except that I think ALL censuses are using stale stats.gc.cpu_ns values. I moved the `stats_endGC` call before the `heapCensus` call in phab:D4183, and this issue seems to be fixed. Of course it's quite hard to tell that this doesn't break something else. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:8 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Thanks for picking this up, duog! I was in the middle of writing a reply starting with,
The issue with this approach is that we will now have runtime which won't be accounted for. The heap census can be a considerable amount of time... when I noticed that we already have a separate set of fields for accounting heap census time. Presumably this means that we were double- counting time previously. Anyways, this suggests to me at least that your approach should be fine.
-- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:9 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by duog):
when I noticed that we already have a separate set of fields for accounting heap census time. Presumably this means that we were double- counting time previously. Anyways, this suggests to me at least that your approach should be fine.
I don't ''think'' we were double counting. `stat_endGC` is only accounting for time, it doesn't call `getProcessTimes`. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:10 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: new Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by duog): Having done some more investigation, my understanding has improved. The diff linked in comment:8 is quite wrong. `heapCensus` should be called during a garbage collection, and it's time should be included in GC stats. It's parameter should be the start time of the current gc. I now believe the cause of this is a bug in how gc times are accumulated, see Phab:4184, which does fix this issue. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:11 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: patch Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Phab:D4184 Wiki Page: | -------------------------------------+------------------------------------- Changes (by duog): * status: new => patch * differential: => Phab:D4184 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:12 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!)
gives samples out of sequence (regression)
-------------------------------------+-------------------------------------
Reporter: carlostome | Owner: bgamari
Type: bug | Status: patch
Priority: high | Milestone: 8.4.1
Component: Runtime System | Version: 8.2.1
Resolution: | Keywords: profiler
Operating System: Unknown/Multiple | Architecture:
| Unknown/Multiple
Type of failure: None/Unknown | Test Case:
Blocked By: | Blocking:
Related Tickets: #14006, #11645 | Differential Rev(s): Phab:D4184
Wiki Page: |
-------------------------------------+-------------------------------------
Comment (by Ben Gamari
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: closed Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: fixed | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Phab:D4184 Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * status: patch => closed * resolution: => fixed -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:14 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!) gives samples out of sequence (regression) -------------------------------------+------------------------------------- Reporter: carlostome | Owner: bgamari Type: bug | Status: closed Priority: high | Milestone: 8.4.1 Component: Runtime System | Version: 8.2.1 Resolution: fixed | Keywords: profiler Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: T14257 Blocked By: | Blocking: Related Tickets: #14006, #11645 | Differential Rev(s): Phab:D4184 Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * testcase: => T14257 Comment: Test coming. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/14257#comment:15 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#14257: Heap profiling with ghc and hp2ps and strict function application ($!)
gives samples out of sequence (regression)
-------------------------------------+-------------------------------------
Reporter: carlostome | Owner: bgamari
Type: bug | Status: closed
Priority: high | Milestone: 8.4.1
Component: Runtime System | Version: 8.2.1
Resolution: fixed | Keywords: profiler
Operating System: Unknown/Multiple | Architecture:
| Unknown/Multiple
Type of failure: None/Unknown | Test Case: T14257
Blocked By: | Blocking:
Related Tickets: #14006, #11645 | Differential Rev(s): Phab:D4184
Wiki Page: |
-------------------------------------+-------------------------------------
Comment (by Ben Gamari
participants (1)
-
GHC