Missing DWARF debug information

[Blacksmoke16]

Bug Report

https://github.com/SimonKagstrom/kcov uses DWARF debug information to power its code coverage reporting. While viewing the reports more closely I notice that it reports certain things as missed even tho they were most definitely hits. For example with the following code:

# test.cr
class Foo
  getter callback : Proc(Int32, Int32)? = nil

  def callback(&@callback : Int32 -> Int32) : Nil
  end
end

foo = Foo.new

foo.callback do |val|
  val * 10
end

pp foo.callback.not_nil!.call 10

Generate the report:

$ crystal build --debug test.cr
$ kcov --include-path=./test.cr ./coverage ./test
100
$ xdg-open coverage/index.html

Results in:

The block body and the calling of the proc are reported as missed, even tho you can clearly see 100 in the console output. Using getter! instead of an explicit not_nil! makes it correctly report that line as a hit.

I think this implies those specific lines are missing debug information?

[ysbaddaden]

The example uses hardcoded values and only records a single callback: I'd wager that LLVM optimized the callback away and the call with a mere 100.

It's also possible the actual line is wrong.

A GDB or LLDB debug session might help.

[RX14]

No --release means no optimisation: every operation loads to registers from the stack, does a compiler primitive then stores again. The simplest possible code generation from the IR. This means that each line of code does indeed get instructions emitted. Getting correct debug info has always been tough, and I can imagine that macros and blocks got broken somewhere along the way. Or that the emitted debug info is not quite compatible with kcov?

[Blacksmoke16]

Here's the debug output from kcov. Seems it registers a breakpoint on line 11, but doesn't consider it a hit?

$ kcov --debug=31 --include-path=./test.cr ./coverage ./test
PT forked 1083414
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x7ffff7a0102d:-1 for 1083414
Can't find breakpoint at 0x7ffff7a0102d
main file relocation = 0x555555554000
BP registered at 0x5555555a5759
REPORT /home/george/downloads/test.cr:1 at 0x5555555a5759
REPORT /home/george/downloads/test.cr:1 at 0x1fb7f7503
0x59f0780450e0 REPORT hit at 0x1fb7f7503
BP registered at 0x5555555a5a88
REPORT /home/george/downloads/test.cr:8 at 0x5555555a5a88
REPORT /home/george/downloads/test.cr:8 at 0x8fb7f7503
0x59f0780450e0 REPORT hit at 0x8fb7f7503
BP registered at 0x5555555a5a9d
REPORT /home/george/downloads/test.cr:10 at 0x5555555a5a9d
REPORT /home/george/downloads/test.cr:10 at 0xafb7f7503
0x59f0780450e0 REPORT hit at 0xafb7f7503
BP registered at 0x5555555a5af3
REPORT /home/george/downloads/test.cr:14 at 0x5555555a5af3
REPORT /home/george/downloads/test.cr:14 at 0xefb7f7503
BP registered at 0x5555555b68b0
REPORT /home/george/downloads/test.cr:10 at 0x5555555b68b0
REPORT /home/george/downloads/test.cr:10 at 0xafb7f7503
BP registered at 0x5555555b68bc
REPORT /home/george/downloads/test.cr:10 at 0x5555555b68bc
REPORT /home/george/downloads/test.cr:10 at 0xafb7f7503
BP registered at 0x5555555b68d7
REPORT /home/george/downloads/test.cr:11 at 0x5555555b68d7
REPORT /home/george/downloads/test.cr:11 at 0xbfb7f7503
BP registered at 0x55555567e350
REPORT /home/george/downloads/test.cr:4 at 0x55555567e350
REPORT /home/george/downloads/test.cr:4 at 0x4fb7f7503
0x59f0780450e0 REPORT hit at 0x4fb7f7503
BP registered at 0x55555567e35f
REPORT /home/george/downloads/test.cr:4 at 0x55555567e35f
REPORT /home/george/downloads/test.cr:4 at 0x4fb7f7503
BP registered at 0x55555567e387
REPORT /home/george/downloads/test.cr:5 at 0x55555567e387
REPORT /home/george/downloads/test.cr:5 at 0x5fb7f7503
0x59f0780450e0 REPORT hit at 0x5fb7f7503
BP registered at 0x55555567e390
REPORT /home/george/downloads/test.cr:5 at 0x55555567e390
REPORT /home/george/downloads/test.cr:5 at 0x5fb7f7503
Cannot open linux-vdso.so.1
No debug symbols in /usr/lib/libgc.so.1.
No debug symbols in /usr/lib/libc.so.6.
No debug symbols in /lib64/ld-linux-x86-64.so.2.
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x5555555a5759:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x5555555a5759
0x59f0780450e0 REPORT hit at 0x1fb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x5555555a5a88:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x5555555a5a88
0x59f0780450e0 REPORT hit at 0x8fb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x5555555a5a9d:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x5555555a5a9d
0x59f0780450e0 REPORT hit at 0xafb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x55555567e350:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x55555567e350
0x59f0780450e0 REPORT hit at 0x4fb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x55555567e35f:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x55555567e35f
0x59f0780450e0 REPORT hit at 0x4fb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x55555567e387:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x55555567e387
0x59f0780450e0 REPORT hit at 0x5fb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x5555555b68b0:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x5555555b68b0
0x59f0780450e0 REPORT hit at 0xafb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x5555555b68bc:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x5555555b68bc
0x59f0780450e0 REPORT hit at 0xafb7f7503
PT continuing 1083414 with signal 0
PT stopped PID 1083414 0x0000057f
PT BP at 0x55555567e390:-1 for 1083414
0x59f078044ad0 REPORT hit at 0x55555567e390
0x59f0780450e0 REPORT hit at 0x5fb7f7503
PT continuing 1083414 with signal 0
100
PT stopped PID 1083414 0x00000000
PT exit 0 at 0xffffffffffffffff for 1083414 (first child)
PT continuing 1083414 with signal 0
PT error for 1083414: -1
Returning error
REPORT /home/george/downloads/test.cr:5 at 0x5fb7f7503
0x59f0780450e0 REPORT hit at 0x5fb7f7503
REPORT /home/george/downloads/test.cr:4 at 0x4fb7f7503
0x59f0780450e0 REPORT hit at 0x4fb7f7503
REPORT /home/george/downloads/test.cr:11 at 0xbfb7f7503
REPORT /home/george/downloads/test.cr:10 at 0xafb7f7503
0x59f0780450e0 REPORT hit at 0xafb7f7503
REPORT /home/george/downloads/test.cr:8 at 0x8fb7f7503
0x59f0780450e0 REPORT hit at 0x8fb7f7503
REPORT /home/george/downloads/test.cr:14 at 0xefb7f7503
REPORT /home/george/downloads/test.cr:1 at 0x1fb7f7503
0x59f0780450e0 REPORT hit at 0x1fb7f7503
REPORT /home/george/downloads/test.cr:5 at 0x5fb7f7503
0x59f0780450e0 REPORT hit at 0x5fb7f7503
REPORT /home/george/downloads/test.cr:4 at 0x4fb7f7503
0x59f0780450e0 REPORT hit at 0x4fb7f7503
REPORT /home/george/downloads/test.cr:11 at 0xbfb7f7503
REPORT /home/george/downloads/test.cr:10 at 0xafb7f7503
0x59f0780450e0 REPORT hit at 0xafb7f7503
REPORT /home/george/downloads/test.cr:8 at 0x8fb7f7503
0x59f0780450e0 REPORT hit at 0x8fb7f7503
REPORT /home/george/downloads/test.cr:14 at 0xefb7f7503
REPORT /home/george/downloads/test.cr:1 at 0x1fb7f7503
0x59f0780450e0 REPORT hit at 0x1fb7f7503

Throwing in a breakpoint and stepping thru the code via lldb I did notice this:

Process 1084592 stopped
* thread #1, name = 'test', stop reason = step in
    frame #0: 0x00005555555b68e0 test`->(val=10) at test.cr:13:7
   10   debugger
   11
   12   foo.callback do |val|
-> 13     val * 10
   14   end
   15
   16   pp foo.callback.not_nil!.call 10

The one step that points to val * 10 says it's on line 13? Maybe that's why it's not marked as a hit because there's no code on that line?

EDIT: NVM, it was because of the debugger line itself shifting things down by 2 lines.