[GHC] #15832: returnIO/bindIO destroys runtime explicit stack information in some cases

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Keywords: | Operating System: Unknown/Multiple Architecture: | Type of failure: None/Unknown Unknown/Multiple | Test Case: | Blocked By: Blocking: | Related Tickets: Differential Rev(s): | Wiki Page: -------------------------------------+------------------------------------- Tested in GHC 8.2.2, 8.4.3 and 8.6.1: Test-good.hs {{{#!hs import GHC.Base data X = X Int deriving (Eq, Show) main :: IO () main = (returnIO undefined) `bindIO` (const (print $ X (error "XXX"))) }}} Test-bad.hs {{{#!hs import GHC.Base data X = X Int deriving (Eq, Show) main :: IO () main = (returnIO undefined) `bindIO` (\_ -> (print $ X (error "XXX"))) }}} build.sh {{{#!shell #!/bin/sh set -e p="${1:-stg}" for i in good bad; do rm -rf ghc*_* Test-$i Test-$i.dump-* Test-$i.hi Test-$i.o ghc "-ddump-$p" -dsuppress-module-prefixes -dsuppress-uniques \ -keep-tmp-files -dumpdir . -ddump-to-file \ -fno-cse -prof -fprof-auto -fprof-auto-calls -fprof-cafs \ -dinitial-unique=0 -dunique-increment=1 \ Test-$i.hs ./Test-$i +RTS -xc || true done colordiff -ruw Test-*.dump-"$p" | less -R }}} Running `sh build.sh` gives the following output: {{{ [1 of 1] Compiling Main ( Test-good.hs, Test-good.o ) Linking Test-good ... *** Exception (reporting due to +RTS -xc): (THUNK_2_0), stack trace: Main.main, called from Main.main, called from Main.main, called from Main.main, called from Main.main, called from Main.CAF:main --> evaluated by: Main.main, called from Main.main, called from Main.main, called from Main.CAF:main --> evaluated by: Main.main, called from Main.main, called from Main.main Test-good: XXX CallStack (from HasCallStack): error, called at Test-good.hs:6:57 in main:Main CallStack (from -prof): Main.main (Test-good.hs:6:57-67) Main.main (Test-good.hs:6:54-68) Main.main (Test-good.hs:6:46-68) Main.main (Test-good.hs:6:39-69) Main.main (Test-good.hs:6:8-70) Main.CAF:main (Test-good.hs:6:1-4) [1 of 1] Compiling Main ( Test-bad.hs, Test-bad.o ) Linking Test-bad ... *** Exception (reporting due to +RTS -xc): (THUNK_2_0), stack trace: Main.main, called from Main.main, called from Main.main, called from Main.main Test-bad: XXX CallStack (from HasCallStack): error, called at Test-bad.hs:6:57 in main:Main CallStack (from -prof): Main.main (Test-bad.hs:6:57-67) Main.main (Test-bad.hs:6:54-68) Main.main (Test-bad.hs:6:46-68) Main.main (Test-bad.hs:6:8-70) }}} As you can see, in Test-bad.hs all the entries below "evaluated by" are missing. I am not familiar with STG output, but running the script also shows you a diff of the STG dump. It seems innocent enough. Running `sh build.sh cmm` shows many more differences. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by infinity0): Some more examples: Good: {{{#!hs data X = X Int deriving (Eq, Show) main :: IO () main = do return undefined print $ X (error "XXX") }}} Bad: {{{#!hs data X = X Int deriving (Eq, Show) main :: IO () main = do _ <- return undefined print $ X (error "XXX") }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:1 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by infinity0): I forgot to add, adding `-O2` to `build.sh` makes the bad behaviours go away in these specific reduced cases. However it does not help in a larger "real world" case. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:2 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases
-------------------------------------+-------------------------------------
Reporter: infinity0 | Owner: (none)
Type: bug | Status: new
Priority: normal | Milestone:
Component: Compiler | Version: 8.6.1
Resolution: | Keywords:
Operating System: Unknown/Multiple | Architecture:
| Unknown/Multiple
Type of failure: None/Unknown | Test Case:
Blocked By: | Blocking:
Related Tickets: | Differential Rev(s):
Wiki Page: |
-------------------------------------+-------------------------------------
Comment (by infinity0):
Adding `-debug` and `-Dp` reveals that something is preventing the
relevant cost-centre from being added to the relevant CAF cost-centre-
stacks. But this is necessary in order for the logic in fprintCCS_stderr
to find the subsequent stacks, to print the "evaluated by" stuff.
{{{
$ sh build.sh
[1 of 1] Compiling Main ( Test-good.hs, Test-good.o )
Linking Test-good ...
7facde5a7740: pushing main on Main.CAF:main
Appending <> to

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): If you look at the STG you will see that in the good case we get STG of the form, {{{#!hs main = (>>) (return undefined) (print (X (error ...))) }}} The second argument then becomes a CAF during codegen. This CAF then as a cost-center added to it due to `-fprof-cafs`. The bad case, on the other hand, is of the form: {{{#!hs main = (>>=) (return undefined) (\_ -> print (X (error ...))) }}} Here the second argument is not a CAF and therefore will not get a cost- center. This is the reason for this difference. Out of curiosity, what is your application? -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by infinity0): OK, but then how do I get a proper "evaluated by" stack trace? From [https://github.com/ghc/ghc/blob/f877d9cc99dd1ba0c038e70527031e9ba0934cd3/rts... here] it seems that only CAF stacks can be traversed to the "evaluated by" stacks. Stacks that don't come from a CAF, can't be traversed further to see what caused the evaluation of an error/bottom value. In both cases, I am creating an `X` with a bottom inside it. This is a decently common pattern used in Haskell, the intent is that I never evaluate the bottom. However, programmers make mistakes and it's nice to be able to get a stack trace showing me what was trying to evaluate the bottom. In the good case, I can see both (a) the stack that created the bottom value and (b) the stack that caused the evaluation of bottom. In the bad case, I can only see (a) and I can't see (b), making things very hard to debug. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:5 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by infinity0): Here is an even more realistic example, which hopefully convinces you that this is a Very Important bug (at least with stack-trace printing), and closer to my real-world code: Good code: {{{#!hs data X = X Int | XX deriving (Eq, Show) mkX = X doInnocentThings a = case a of X i -> putStr "" XX -> putStr "XX" doBadThing a = case a of X i -> print i XX -> print "XX" main :: IO () main = do return undefined let a = mkX (error "XXX") doInnocentThings a doBadThing a }}} Good stack trace: {{{ *** Exception (reporting due to +RTS -xc): (THUNK_2_0), stack trace: Main.main.a, called from Main.main.a, called from Main.CAF:sat_s2O2 --> evaluated by: Main.doBadThing, called from Main.main, called from Main.CAF:sat_s2O2 --> evaluated by: Main.doBadThing, called from Main.main Test-good: XXX CallStack (from HasCallStack): error, called at Test-good.hs:16:16 in main:Main CallStack (from -prof): Main.main.a (Test-good.hs:16:16-26) Main.main.a (Test-good.hs:16:11-27) Main.CAF:sat_s2O2 (<no location info>) }}} Here the stack trace mentions "doBadThing", it is obvious which piece of code is at fault. Now: Bad code: (change `return undefined` to `_ <- return undefined` in the good code) Bad stack trace: {{{ *** Exception (reporting due to +RTS -xc): (THUNK_2_0), stack trace: Main.main.a, called from Main.main.a Test-bad: XXX CallStack (from HasCallStack): error, called at Test-bad.hs:16:16 in main:Main CallStack (from -prof): Main.main.a (Test-bad.hs:16:16-26) Main.main.a (Test-bad.hs:16:11-27) }}} There is no "evaluated by" entry, the only thing I see is the `let a =` statement being mentioned, which is perfectly fine logic-wise. There is no way to debug this, except by guessing based on knowledge of the whole codebase. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:6 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: normal | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Thanks for the additional context! -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:7 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: returnIO/bindIO destroys runtime explicit stack information in some cases -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: high | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * priority: normal => high Comment: I agree that this is a serious debugging impediment; stack traces are very important for the usability of the language in an applied setting. Bumping the priority. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:8 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: fprintCCS_stderr (+RTS -xc) should be able to recurse into stacks that evaluated a given stack even if the latter does not come from a CAF -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: high | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by infinity0): <bgamari> infinity0, have you considered simply using a more aggressive -fprof-* flag? <infinity0> bgamari: i'm already using "-fprof-auto -fprof-auto-calls -fprof-cafs" that seems to be the most aggressive available option <bgamari> ahh yes, so you are <bgamari> well then, that is indeed tricky <bgamari> can you describe where ideally you would like CCs to be inserted? <infinity0> i tried manually inserting CCs in the bad cases and couldn't get them working, so i don't really know <infinity0> but it seems to me that the logic that traverses different stacks to find subsequent "evaluated by" stacks, maybe can be expanded <infinity0> because it apparently only works when each stack except the last starts from a CAF <infinity0> i previously thought perhaps everything is supposed to start from a CAF but from what you're saying now it seems maybe not <infinity0> in which case, the "evaluated by" traversal logic ofc can't work for these latter cases * bgamari tries to work out what the stack looks like in the bad case <bgamari> infinity0, for what it's worth, I'm not sure this will just be a matter of expanding the existing stack printing logic <bgamari> infinity0, I suspect the information you need is actually not present at runtime <infinity0> oh :( <bgamari> afterall, in both cases we have tail-called <bgamari> so there is no stack frame to reconstruct execution from <bgamari> it just happens that in the good case we tail called into a CAF, which had a cost center <bgamari> I agree that this is an unfortunate behavior though <bgamari> I may be missing something but I think the right way to think about this may be from the perspective of finding a heuristic to use to insert the necessary CCs <bgamari> admittedly it's not immediately clear what that should look like, however <infinity0> yeah, going back to the original bad example, I tried changing it to {-# SCC test0 #-} ( {-# SCC test1 #-} \_ -> {-# SCC test2 #-} (print ... <infinity0> and this didn't fix the stack either <bgamari> I'll admit, that's a bit surprising <bgamari> oh, perhaps because it's non-updateable <bgamari> so you don't get an update frame -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:9 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: fprintCCS_stderr (+RTS -xc) should be able to traverse into stacks that evaluated a given stack even if the latter does not come from a CAF -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: high | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15832#comment:10 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler

#15832: fprintCCS_stderr (+RTS -xc) should be able to traverse into stacks that evaluated a given stack even if the latter does not come from a CAF -------------------------------------+------------------------------------- Reporter: infinity0 | Owner: (none) Type: bug | Status: new Priority: high | Milestone: Component: Compiler | Version: 8.6.1 Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | 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/15832#comment:11 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
participants (1)
-
GHC