DWARF support in GHC (part 2)

Ben Gamari - 2020-04-04

This post is the second of a series examining GHC’s support for DWARF debug information and the tooling that this support enables:

• Part 1 introduces DWARF debugging information and explains how its generation can be enabled in GHC.
• Part 2 looks at a DWARF-enabled program in gdb and examines some of the limitations of this style of debug information.
• Part 3 looks at the backtrace support of GHC’s runtime system and how it can be used from Haskell.
• Part 4 examines how the Linux perf utility can be used on GHC-compiled programs.
• Part 5 concludes the series by describing future work, related projects, and ways in which you can help.

Using gdb on Haskell programs

gdb is an interactive debugger ubiquitous on Unix systems. Let’s try using it to run our executable and then break into execution with Ctrl-C:

$ gdb vector-tests-O0
GNU gdb (GDB) 8.3
...
Reading symbols from dist-newstyle/.../vector-tests-O0...
(gdb) run
Using host libthread_db library "/nix/store/pnd2kl27sag76h23wa5kl95a76n3k9i3-glibc-2.27/lib/libthread_db.so.1".
Data.Vector.Fusion.Bundle:
  fromList.toList == id: [OK, passed 100 tests]
  toList.fromList == id: [OK, passed 100 tests]
...
  postscanr: [OK, passed 100 tests]
  postscanr': [OK, passed 100 tests]
^C
Program received signal SIGINT, Interrupt.
stg_ap_pp_fast () at _build/stage1/rts/build/cmm/AutoApply.cmm:3708
3708	        default: {
(gdb) bt
#0  stg_ap_pp_fast () at _build/stage1/rts/build/cmm/AutoApply.cmm:3708
#1  0x000000000137de10 in _rts_stgzuupdzuframe_ret ()
#2  0x0000000000997668 in QuickCheckzm2zi13zi2zmac90a2a0d9e0dd2c227d795a9d4d9de22a119c3781b679f3b245300e1b658c43_TestziQuickCheckziArbitrary_zdfCoArbitraryAll1_info () at Test/QuickCheck/Arbitrary.hs:1230
#3  0x000000000137de10 in _rts_stgzuupdzuframe_ret ()
...
#54 0x0000000000997668 in QuickCheckzm2zi13zi2zmac90a2a0d9e0dd2c227d795a9d4d9de22a119c3781b679f3b245300e1b658c43_TestziQuickCheckziArbitrary_zdfCoArbitraryAll1_info () at Test/QuickCheck/Arbitrary.hs:1230
#55 0x000000000137de10 in _rts_stgzuupdzuframe_ret ()
#56 0x0000000001316510 in ghczmprim_GHCziClasses_zdfEqBoolzuzdczeze_info () at libraries/ghc-prim/GHC/Classes.hs:205
#57 0x0000000000643698 in r5bd2_info () at Data/Vector.hs:289
#58 0x000000000137de10 in _rts_stgzuupdzuframe_ret ()
#59 0x00000000009bc478 in s1TRr_info () at Test/QuickCheck/Property.hs:225
#60 0x00000000009bbc88 in s1TQC_info () at Test/QuickCheck/Property.hs:190
#61 0x0000000001375f50 in _rts_stgzucatchzuframe_ret () at rts/Exception.cmm:335
#62 0x00000000009bbe08 in s1TQX_info () at Test/QuickCheck/Property.hs:252
#63 0x00000000009b7670 in s1TIa_info () at Test/QuickCheck/Property.hs:216
...
#68 0x00000000009b7670 in s1TIa_info () at Test/QuickCheck/Property.hs:216
#69 0x00000000009b7c18 in s1TIJ_info () at Test/QuickCheck/Property.hs:207
#70 0x00000000009b7670 in s1TIa_info () at Test/QuickCheck/Property.hs:216
#71 0x00000000009b7670 in s1TIa_info () at Test/QuickCheck/Property.hs:216
#72 0x00000000009bff88 in QuickCheckzm2zi13zi2zmac90a2a0d9e0dd2c227d795a9d4d9de22a119c3781b679f3b245300e1b658c43_TestziQuickCheckziProperty_reduceRose1_info () at Test/QuickCheck/Property.hs:232
#73 0x00000000009e18a8 in s2eT1_info () at Test/QuickCheck/Test.hs:331
#74 0x0000000001375f50 in _rts_stgzucatchzuframe_ret () at rts/Exception.cmm:335
#75 0x00000000009e2380 in QuickCheckzm2zi13zi2zmac90a2a0d9e0dd2c227d795a9d4d9de22a119c3781b679f3b245300e1b658c43_TestziQuickCheckziTest_quickCheck4_info () at Test/QuickCheck/Test.hs:333
#76 0x00000000007479b0 in s4py_info () at Test/Framework/Providers/QuickCheck2.hs:114
#77 0x0000000000755cf8 in s2dc_info () at Test/Framework/Improving.hs:68
#78 0x0000000000762080 in r6ny_info () at Test/Framework/Runners/ThreadPool.hs:62
#79 0x0000000001375f50 in _rts_stgzucatchzuframe_ret () at rts/Exception.cmm:335
#80 0x000000000137c810 in _rts_stgzustopzuthread_ret ()
#81 0x000000000136571b in StgRunIsImplementedInAssembler () at rts/StgCRun.c:370
#82 0x000000000136241b in schedule (task=0x175aa00, initialCapability=<optimized out>) at rts/Schedule.c:467
#83 scheduleWaitThread (tso=<optimized out>, ret=ret@entry=0x0, pcap=pcap@entry=0x7fffffff5210) at rts/Schedule.c:2600
#84 0x000000000138b204 in rts_evalLazyIO (cap=cap@entry=0x7fffffff5210, p=p@entry=0x14122d0, ret=ret@entry=0x0) at rts/RtsAPI.c:530
#85 0x000000000135f35e in hs_main (argc=<optimized out>, argv=<optimized out>, main_closure=0x14122d0, rts_config=...) at rts/RtsMain.c:72
#86 0x0000000000455df4 in main ()
(gdb) 

Here we see the state of the stack around one second into the execution. Note that I have elided a good number (around 50) repeated CoArbitraryAll1 frames. There are four kinds of symbol names seen here:

1. C functions provided by the runtime system (e.g. rts_evalLazyIO)
2. C– functions provided by the runtime system (e.g. _rts_stgzuupdzuframe_ret)
3. Haskell functions exported by modules (e.g. ghczmprim_GHCziClasses_zdfEqBoolzuzdczeze_info)
4. Haskell functions internal to modules (e.g. s1TRr_info)

In cases (2) and (3) the names are derived from source program names via GHC’s Z encoding) symbol name mangling scheme. For instance,

In principle gdb could be taught to perform this demangling on our behalf.

Aside from symbol names, the above backtrace also gives us (often more informative) source locations. However, it should be noted that this line information can be slightly misleading at times for reasons that we will describe below.

Surprises in debug information

As noted above, GHC backtraces can at times be slightly surprising. To see why, consider the simple program,

f :: [Int] -> Int
f = sum . map (* 42)

The code generated for this function (when compiled with -O) will inevitably contain a multiplication instruction and an addition instruction. However, which source location should these be attributed to ¹? One might say f, or somewhere in Data.List.sum, or somewhere in foldl (which sum is defined in terms of). Moreover, these sets of options can grow to be quite large, particularly in cases where stream fusion is involved.

Unfortunately, the DWARF specification requires that GHC choose precisely one of these locations when producing debug information. At the moment GHC uses heuristics to choose from among the options, but these heuristics, like all heuristics, can sometimes produce less than helpful results. GHC can also emit an extended DWARF form which encodes the entire set of source locations. However, there is currently widely available tooling which can consume this information.

In addition to the above wrinkle there is another feature of GHC’s produced code that poses a challenge when producing debug information: tail calls. In a language lacking tail calls, a stack frame typically contains a pointer to the instruction following the function call that pushed the frame. This serves as the address to which execution will return after the callee finishes and is guaranteed to be in the same procedure as the call itself. For this reason, stack backtraces always reflect the history of a program’s execution. That is, a stack containing the frames f; g; h means:

• f called g
• g called h
• h is currently executing

However, tail calls break this model. For instance, consider the Haskell function:

tail_caller :: [Int] -> Int
tail_caller xs = sum xs

sum :: [Int] -> Int
sum xs = foldl' (+) 0 xs

Without optimisation, the code generated for tail_caller will simply jump straight to the entry-point of sum; no stack entry will be left to mark the fact that sum was called by tail_caller. This, coupled with the source location ambiguity described above, can at times lead to slightly surprising backtraces. If you find a case that you think makes little sense, please do open a ticket. We are always looking for ways to improve the quality of the debug information produced by GHC.

Breakpoints

In addition to printing backtraces, we can also set breakpoints:

(gdb) break Test/Framework/Improving.hs:68
(gdb) cont
Continuing.

Breakpoint 1, s2dc_info () at Test/Framework/Improving.hs:68
68	Test/Framework/Improving.hs: No such file or directory.
(gdb) bt
#0  s2dc_info () at Test/Framework/Improving.hs:68
#1  0x0000000000762080 in r6ny_info () at Test/Framework/Runners/ThreadPool.hs:62
#2  0x0000000001375f50 in _rts_stgzucatchzuframe_ret () at rts/Exception.cmm:335
#3  0x000000000137c810 in _rts_stgzustopzuthread_ret ()
#4  0x000000000136571b in StgRunIsImplementedInAssembler () at rts/StgCRun.c:370
#5  0x000000000136241b in schedule (task=0x175aa00, initialCapability=<optimized out>) at rts/Schedule.c:467
#6  scheduleWaitThread (tso=<optimized out>, ret=ret@entry=0x0, pcap=pcap@entry=0x7fffffff5210) at rts/Schedule.c:2600
#7  0x000000000138b204 in rts_evalLazyIO (cap=cap@entry=0x7fffffff5210, p=p@entry=0x14122d0, ret=ret@entry=0x0) at rts/RtsAPI.c:530
#8  0x000000000135f35e in hs_main (argc=<optimized out>, argv=<optimized out>, main_closure=0x14122d0, rts_config=...) at rts/RtsMain.c:72
#9  0x0000000000455df4 in main ()

However, at the moment this is little more than a parlor trick since our debug information does not encode information about in-scope bindings (fixing this is a significant project in its own right and is not currently planned).

In the next post we will see how we can use GHC’s native unwinding support to gather stack traces from within Haskell programs.