Opened 20 months ago

Closed 18 months ago

Last modified 18 months ago

#11047 closed task (fixed)

Provide call stacks in GHCi

Reported by: simonmar Owned by: simonmar
Priority: high Milestone: 8.0.1
Component: GHCi Version: 7.11
Keywords: Cc: gridaphobe, kgardas, bgamari
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: None/Unknown Test Case:
Blocked By: Blocking:
Related Tickets: #545, #4837, #11100 Differential Rev(s): Phab:D1407, Phab:D1595, Phab:D1747
Wiki Page:

Description (last modified by simonmar)

I want call stacks to be available in GHCi with no effort on the part of the user, or changes to the source code. The call stack will be available both programatically and via GHCi commands:

  • GHC.Stack.currentCallStack returns the current call stack as [String]. This can be used from error and copied into the exception string.
  • Debug.Trace.traceStack prints out the stack anywhere.
  • GHCi will have a new command :where to print out the stack when stopped at a breakpoint

The stack trace will be the accurate (i.e. not exposing details of lazy evaluation or tail calls) and detailed (including locations of calls, not just the enclosing function definition).

Implementation

Here's how it's going to work:

  • We make GHCi work with profiling (done: Phab:D1407)
  • We make breakpoint ticks behave like SCC annotations, and update the interpreter to implement the cost-centre-stack semantics.

Example

Here's an example from my prototype:

g :: Int -> [Int]
g n = traceStack "g" [n]

h :: Int -> Bool
h n = case g n of
         [] -> True
         (x:xs) -> False

map :: (a -> b) -> [a] -> [b]
map f [] = []
map f (x:xs) = f x : map f xs

k n = map h [n]
[1 of 1] Compiling Main             ( /home/smarlow/scratch/dbg1.hs, interpreted )
Ok, modules loaded: Main.
*Main> k 1
[g
Stack trace:
  Main.g (/home/smarlow/scratch/dbg1.hs:13:7-24)
  Main.g (/home/smarlow/scratch/dbg1.hs:13:1-24)
  Main.h (/home/smarlow/scratch/dbg1.hs:16:12-14)
  Main.h (/home/smarlow/scratch/dbg1.hs:(16,7)-(18,24))
  Main.h (/home/smarlow/scratch/dbg1.hs:(16,1)-(18,24))
  Main.map (/home/smarlow/scratch/dbg1.hs:22:16-18)
  Main.map (/home/smarlow/scratch/dbg1.hs:22:16-29)
  Main.map (/home/smarlow/scratch/dbg1.hs:(21,1)-(22,29))
  Main.k (/home/smarlow/scratch/dbg1.hs:24:7-15)
  Main.k (/home/smarlow/scratch/dbg1.hs:24:1-15)
False]
*Main> 

We could trim some of the extra detail from the stack trace so that each function appears once; there are several choices here, currently I'm collecting and displaying the most detail.

Deployment

One disadvantage of this is that it requires GHCi to be built with profiling, and all the libraries have to be built with profiling too. There are two options for deployment:

  1. We deploy two versions of GHCi (profiled and non-profiled), or
  2. We expand on what GHCJS did, and make the interpreted code run in a separate process, thus separating the GHCi binary itself from the code being interpreted. This would allow the interpreted code to be run with the profiled RTS while GHCi itself is unprofiled.

Change History (19)

comment:1 Changed 20 months ago by gridaphobe

Cc: gridaphobe added

comment:2 Changed 20 months ago by simonmar

Description: modified (diff)

comment:3 Changed 20 months ago by kgardas

Cc: kgardas added

comment:4 Changed 20 months ago by gridaphobe

Just for clarity, could you elaborate on how this differs from the existing call stacks that you can print in ghci (i.e. the :trace and :hist commands)? Is the main difference that currently ghci's call stack only traces byte-compiled code?

It's also not clear to me how we're going to avoid exposing the details of lazy evaluation. Both the breakpoint-based traces and the SCC-based traces currently expose lazy evaluation (which I agree is a bad thing, at least for error debugging!). I guess this means extending the byte-code interpreter to distinguish between a lexical call-site vs entering a closure based on demand?

Last edited 20 months ago by gridaphobe (previous) (diff)

comment:5 Changed 20 months ago by simonmar

:hist doesn't really print a call stack, it just prints a history of the recent locations that execution passed through. It was a hack because we didn't have real stack trace support. We might even drop :trace or replace it with something better when we have stack traces.

SCC-based stack traces don't expose lazy evaluation (or at least, if they do, it's a bug we should fix, so please let me know). I'm using the same cost-centre-stack semantics in GHCi as we have in the profiling system.

comment:6 Changed 20 months ago by gridaphobe

Ah, I haven't actually used the SCC-based stack traces in a while, so I'm probably just misremembering how they work.

comment:7 Changed 20 months ago by simonpj

I like the idea of running GHCi commands in a separate process. But the division of responsibility between the two is quite obscure to me. Presumably we have a non-profiled GHC compiling profiled code, in the host process, that then squirts bytecode (?) to the assistant process which runs it?

We have various unsolved semantic bugs in cost-centre semantics, which makes me feel uneasy.

comment:8 Changed 20 months ago by simonmar

Yes - we would need to clearly define the interface between GHC and the interpreter as a set of commands that have to be serializable across the process boundary. I imagine there would be a mkByteCodeObject command that took byte-code as an argument, and we would have to keep track of the byte-code with StablePtrs (or something like that).

Luite has already done some of this work in order to get TH working with GHCJS - all the methods of the Quasi class are serialized using Data.Binary across the process boundary, including all of the TH syntax returned by a splice (see https://github.com/ghcjs/ghcjs/tree/master/lib/ghcjs-prim/GHCJS/Prim/TH).

Regarding the semantic bugs, the main one is #5654. I'll try to fix that, but it doesn't seem to happen all that often, and for a debugging tool I think an occasional inaccuracy isn't too much of a concern. Some information is better than none, and we get *lots* of good information.

comment:9 Changed 20 months ago by luite

GHCJSi also runs code in a separate process, which works in a similar way. I haven't merged it in the GHCJS master branch yet since it requires some horrible hacking (with lots of copy/paste) of the GHC bytecode interpreter to make it not try to load/run the BCO in its own process (and then segfault). GHCJSi is actually a lot simpler than GHCJS TH in terms of communication, it just sends new pieces of code to run, and there's an additional command to abort the running computation (with an async exception), however stepping/tracing/breakpoints are not yet supported (GHCJSi uses the usual code generator, there is no bytecode interpreter).

The other reason for it still being experimental is that I haven't properly designed input/output yet, GHCJSi just prints all the stdout output from the underlying node.js process (or browser), which sometimes messes up the prompt. If anyone is interested in designing and implementing some proper process boundary protocol, let me know, I'd be happy to help (time permitting).

comment:10 Changed 20 months ago by Simon Marlow <marlowsd@…>

In 8988be8/ghc:

Make 'error' include the CCS call stack when profiled

Summary:
The idea here is that this gives a more detailed stack trace in two
cases:

1. With `-prof` and `-fprof-auto`
2. In GHCi (see #11047)

Example, with an error inserted in nofib/shootout/binary-trees:

```
$ ./Main 3
Main: z
CallStack (from ImplicitParams):
  error, called at Main.hs:67:29 in main:Main
CallStack (from -prof):
  Main.check' (Main.hs:(67,1)-(68,82))
  Main.check (Main.hs:63:1-21)
  Main.stretch (Main.hs:32:35-57)
  Main.main.c (Main.hs:32:9-57)
  Main.main (Main.hs:(27,1)-(43,42))
  Main.CAF (<entire-module>)
```

This doesn't quite obsolete +RTS -xc, which also attempts to display
more information in the case when the error is in a CAF, but I'm
exploring other solutions to that.

Includes submodule updates.

Test Plan: validate

Reviewers: simonpj, ezyang, gridaphobe, bgamari, hvr, austin

Reviewed By: bgamari

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D1426

comment:11 Changed 19 months ago by simonmar

Design page for implementing GHCi in a separate process: RemoteGHCi, ticket: #11100

comment:12 Changed 18 months ago by Simon Marlow <marlowsd@…>

In c8c44fd/ghc:

Maintain cost-centre stacks in the interpreter

Summary:
Breakpoints become SCCs, so we have detailed call-stack info for
interpreted code.  Currently this only works when GHC is compiled with
-prof, but D1562 (Remote GHCi) removes this constraint so that in the
future call stacks will be available without building your own GHCi.

How can you get a stack trace?

* programmatically: GHC.Stack.currentCallStack
* I've added an experimental :where command that shows the stack when
  stopped at a breakpoint
* `error` attaches a call stack automatically, although since calls to
  `error` are often lifted out to the top level, this is less useful
  than it might be (ImplicitParams still works though).
* Later we might attach call stacks to all exceptions

Other related changes in this diff:

* I reduced the number of places that get ticks attached for
  breakpoints.  In particular there was a breakpoint around the whole
  declaration, which was often redundant because it bound no variables.
  This reduces clutter in the stack traces and speeds up compilation.

* I tidied up some RealSrcSpan stuff in InteractiveUI, and made a few
  other small cleanups

Test Plan: validate

Reviewers: ezyang, bgamari, austin, hvr

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D1595

GHC Trac Issues: #11047

comment:13 Changed 18 months ago by simonmar

Differential Rev(s): Phab:D1407Phab:D1407, Phab:D1595, Phab:D1747

comment:14 Changed 18 months ago by Simon Marlow <marlowsd@…>

In 6be09e8/ghc:

Enable stack traces with ghci -fexternal-interpreter -prof

Summary:
The main goal here is enable stack traces in GHCi.  After this change,
if you start GHCi like this:

  ghci -fexternal-interpreter -prof

(which requires packages to be built for profiling, but not GHC
itself) then the interpreter manages cost-centre stacks during
execution and can produce a stack trace on request.  Call locations
are available for all interpreted code, and any compiled code that was
built with the `-fprof-auto` familiy of flags.

There are a couple of ways to get a stack trace:

* `error`/`undefined` automatically get one attached
* `Debug.Trace.traceStack` can be used anywhere, and prints the current
  stack

Because the interpreter is running in a separate process, only the
interpreted code is running in profiled mode and the compiler itself
isn't slowed down by profiling.

The GHCi debugger still doesn't work with -fexternal-interpreter,
although this patch gets it a step closer.  Most of the functionality
of breakpoints is implemented, but the runtime value introspection is
still not supported.

Along the way I also did some refactoring and added type arguments to
the various remote pointer types in `GHCi.RemotePtr`, so there's
better type safety and documentation in the bridge code between GHC
and ghc-iserv.

Test Plan: validate

Reviewers: bgamari, ezyang, austin, hvr, goldfire, erikd

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D1747

GHC Trac Issues: #11047, #11100

comment:15 Changed 18 months ago by simonmar

Status: newmerge

Ben, could we get 6be09e884730f19da6c24fc565980f515300e53c merged into 8.0?

comment:16 Changed 18 months ago by simonmar

Cc: bgamari added

comment:17 Changed 18 months ago by bgamari

Resolution: fixed
Status: mergeclosed

Done.

comment:18 Changed 18 months ago by Simon Marlow <marlowsd@…>

In 6cb860a9/ghc:

Add -prof stack trace to assert

Summary:
So that assertion failures have full call stack information attached
when using `ghc -fexternal-interpreter -prof`.  Here's one I just
collected by inserting a dummy assert in Happy:

```
*** Exception: Assertion failed
CallStack (from ImplicitParams):
  assert, called at ./First.lhs:37:11 in main:First
CallStack (from -prof):
  First.mkFirst (First.lhs:37:11-27)
  First.mkFirst (First.lhs:37:11-93)
  Main.main2.runParserGen.first (Main.lhs:107:48-56)
  Main.main2.runParserGen.first (Main.lhs:107:27-57)
  Main.main2.runParserGen (Main.lhs:(96,9)-(276,9))
  Main.main2.runParserGen (Main.lhs:(90,9)-(276,10))
  Main.main2.runParserGen (Main.lhs:(86,9)-(276,10))
  Main.main2.runParserGen (Main.lhs:(85,9)-(276,10))
  Main.main2 (Main.lhs:74:20-43)
  Main.main2 (Main.lhs:(64,9)-(78,61))
  Main.main (Main.lhs:57:9-18)
```

Test Plan: validate

Reviewers: erikd, hvr, austin, bgamari

Reviewed By: bgamari

Subscribers: thomie

Differential Revision: https://phabricator.haskell.org/D1765

GHC Trac Issues: #11047

comment:19 Changed 18 months ago by simonpj

Would it be possible to comment the new code in assertError? Why unsafeDupablePerformIO? What's the goal? What happens in the non-profiling case?

That would help people working on this in the future.

Thanks!

Simon

Note: See TracTickets for help on using tickets.