Get backtrace function names from DWARF sections #3958

ysbaddaden · 2017-01-30T16:49:09Z

Parses the .debug_info section of executables to get the original function name instead of raw symbols (that sometimes can't be found on Linux) in backtraces. Function names (just like line numbers) will always be displayed, unless the program is compiled with --no-debug. For Example:

Before:

0x45a8fa: *Kls#callee1:Nil at /home/github/crystal/spec/std/data/backtrace_sample 3:10
0x432d4e: *callee3:Nil at /home/github/crystal/spec/std/data/backtrace_sample 15:3
0x42f03f: ??? at /home/github/crystal/spec/std/data/backtrace_sample 17:1
0x432c29: main at /home/julien/.cache/crystal/macro70621728.cr 12:15
0x7f2ab0c52f45: __libc_start_main at ??

After:

0x47e65a: callee1 at /home/github/crystal/spec/std/data/backtrace_sample 3:10
0x445dce: callee3 at /home/github/crystal/spec/std/data/backtrace_sample 15:3
0x43825d: __crystal_main at /home/github/crystal/spec/std/data/backtrace_sample 17:1
0x445ca9: main at /home/julien/.cache/crystal/macro85348592.cr 12:15
0x7f9e86ef4f45: __libc_start_main at ??

0x1eef · 2017-01-30T17:08:17Z

nice 💯
is there a "before" example too? i guess no method names showed up before?

RX14 · 2017-01-30T21:21:06Z

Does this not have the class/type information like before?

ysbaddaden · 2017-01-30T23:01:12Z

We only push the function name to LLVM. I was surprised at first, but then noticed that Ruby, for example, does exactly the same: only the function name is displayed in backtraces. Along with the file:line information, this has always been enough. I believe this avoids even more noise.

RX14 · 2017-01-30T23:51:48Z

I think it would be nice to include at least the type name in the backtrace. For example Foo::Bar#foo. I don't think that would get too cluttered.

ysbaddaden · 2017-01-31T00:15:15Z

Not my opinio, but is is out of scope of this PR anyway. Here, I seek the information, I don't set it.

bcardiff

@ysbaddaden Of course this is really great! I rebased locally on master and the class/return type is present in osx. I am not sure if on linux is present.

There is also a couple of minor comments.

Would you rebase/check them when you have time so we can merge this? Thanks!

bcardiff · 2017-03-17T18:08:28Z

src/callstack.cr

@@ -167,10 +171,12 @@ struct CallStack

  {% if flag?(:darwin) || flag?(:freebsd) || flag?(:linux) || flag?(:openbsd) %}
    @@dwarf_line_numbers : Debug::DWARF::LineNumbers?
+    @@dwarf_function_names : Array(Tuple(LibC::SizeT, LibC::SizeT, String))?


Array({LibC::SizeT, LibC::SizeT, String})? would match the most used style.

bcardiff · 2017-03-17T18:19:04Z

src/debug/dwarf/info.cr

+          code = DWARF.read_unsigned_leb128(@io)
+          attributes.clear
+
+          if abbrev = abbreviations[code - 1]? # abbreviations.find { |a| a.code == abbrev }


The commented part is correct but slow, the actual is faster, but maybe wrong. This looks like working, but must be tested more.

A better note with explanation should be added.

bcardiff · 2017-03-17T18:29:59Z

spec/std/callstack_spec.cr

-    output.should match(/#{sample} 15:3/) # callee3
-    output.should match(/#{sample} 17:1/) # ???
+    output.should match(/callee1 at #{sample} 3:10/)
+    output.should match(/callee3 at #{sample} 15:3/)


I rebase this over master locally and I get that class name and type return information is present in OSX.

The following make things pass in osx:

output.should match(/Kls#callee1:Nil at #{sample} 3:10/) output.should match(/callee3:Nil at #{sample} 15:3/)

This is the raw symbol, not the function name from the DWARF info; the hint is the :Nil return type, and the class type.

I.e., it fails on macOS.

Oh, I see.

Since in OSX the output of backtrace_sample changes before and after the use of dsymutil I though it was working on OSX.

So, Is this a WIP still?
Is the osx dwarf parsing possible?
Is there anything someone could help with to get that part done?

$ ./bin/crystal build --debug spec/std/data/backtrace_sample -o ./backtrace_sample $ ./backtrace_sample 0x104731675: *CallStack::unwind:Array(Pointer(Void)) at ?? 0x104731611: *CallStack#initialize:Array(Pointer(Void)) at ?? 0x1047315e8: *CallStack::new:CallStack at ?? 0x104730765: *caller:Array(String) at ?? 0x1047760e1: *Kls#callee1:Nil at ?? 0x104730741: *callee3:Nil at ?? 0x1047207d7: __crystal_main at ?? 0x104730618: main at ?? $ dsymutil --flat ./backtrace_sample $ ./backtrace_sample 0x109bfe0e1: *Kls#callee1:Nil at /.../src/spec/std/data/backtrace_sample 3:10 0x109bb8741: *callee3:Nil at /.../src/spec/std/data/backtrace_sample 15:3 0x109ba87d7: __crystal_main at /.../src/spec/std/data/backtrace_sample 17:1 0x109bb8618: main at /.../src/main.cr 12:15

What happens is that the __debug_line section is correctly parsed (from the .dwarf file) then lines in the backtrace originating from exception.cr and callstack.cr files are skipped (they don't matter to the exception). Yet, the __debug_info isn't parsed correctly, and we fallback to the raw symbols (it should be callee1 and callee3 only.

We should be able to parse this section. macOS outputs DWARF v2 so maybe there is some noticeable differences from DWARF v4 as generated by Linux, FreeBSD or OpenBSD; maybe we must parse the __debug_aranges section instead?

I need access to a Mac to debug that. If someone is motivated enough to investigate, looking at the .dwarf Mach-O file, and checking what happens when I parse it. Or maybe send me both an executable and its associated dwarf file, so I can look deeper.

In osx the CallStack.decode_function_name(pc) is not used (ie returns nil).
That is because @@dwarf_function_names is empty.

In self.read_dwarf_sections the __debug_info exists but inside the Debug::DWARF::Info.new I think there is something odd as you pointed. Because the @io.tell < end_offset in Debug::DWARF::Info#each is false from the beginning.

info # => Debug::DWARF::Info( @abbreviations=nil, @address_size=8, @debug_abbrev_offset=0, @dwarf64=false, @io= #<File:/path/to/backtrace_sample.dwarf>, @offset=566555, @ref_offset=0, @unit_length=2657, @version=4) {@io.tell, end_offset} # => {731730, 569212} (this is before the while guard in #each)

@ysbaddaden if you can spot/suggest something I am willing to continue.

Otherwise here you can find the binary and dwarf I am using to test it.

Thanks for testing and providing binaries! I'll try to read the sections and dwarf from them —I made a Mach-O and ELF reader that outputs data like readelf does. I should publish it somewhere :-)

ysbaddaden · 2017-04-13T18:09:12Z

I think I found the culprit, a sneaky seek bug. Thanks again for the binaries @bcardiff !

bcardiff · 2017-04-13T18:29:49Z

@ysbaddaden this is great! Thanks!

Would you mind rebasing on master so the merge commit references this PR and we have shorter branches merges?

Feel free to merge it directly 👍

Sija · 2017-04-14T11:09:54Z

Is there anything we could do to preserve class names?
I'd say loosing that part handicaps backtrace call signatures quite a bit.

ysbaddaden · 2017-04-14T12:10:27Z

This is out of scope of this PR (I extract the name, I don't set it). Furthermore other OO languages, such as C++, Ruby or Python, don't store/print the type name, only the function name, and that never bothered me —because file:line already provides enough.

ysbaddaden added the pr:wip label Jan 30, 2017

ysbaddaden self-assigned this Jan 30, 2017

ysbaddaden added the topic:compiler:debugger label Jan 30, 2017

ysbaddaden force-pushed the core-backtrace-function-names branch from b216abf to 0871079 Compare February 1, 2017 13:56

ysbaddaden removed the pr:wip label Feb 1, 2017

ysbaddaden force-pushed the core-backtrace-function-names branch from 0871079 to 4ba667e Compare February 1, 2017 14:03

bcardiff requested changes Mar 17, 2017

View reviewed changes

bcardiff added this to the Next milestone Mar 17, 2017

bcardiff added the kind:feature label Mar 17, 2017

bcardiff mentioned this pull request Mar 21, 2017

Add specs for #4163 #4171

Merged

ysbaddaden force-pushed the core-backtrace-function-names branch from 4ba667e to 39c1620 Compare March 31, 2017 13:52

asterite modified the milestone: Next Apr 7, 2017

ysbaddaden added 3 commits April 14, 2017 14:12

Parse DWARF abbrev, info and strings sections

cd829aa

Backtrace: get function name from DWARF sections

0f85b6e

Fix: MachO#read_section? doesn't reset seek position

b46a8c1

ysbaddaden force-pushed the core-backtrace-function-names branch from 321f504 to b46a8c1 Compare April 14, 2017 12:14

bcardiff merged commit 7b43477 into crystal-lang:master Apr 20, 2017

ysbaddaden deleted the core-backtrace-function-names branch April 21, 2017 09:21

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Get backtrace function names from DWARF sections #3958

Get backtrace function names from DWARF sections #3958

ysbaddaden commented Jan 30, 2017 •

edited

Loading

0x1eef commented Jan 30, 2017

RX14 commented Jan 30, 2017

ysbaddaden commented Jan 30, 2017

RX14 commented Jan 30, 2017

ysbaddaden commented Jan 31, 2017

bcardiff left a comment

bcardiff Mar 17, 2017

bcardiff Mar 17, 2017

ysbaddaden Mar 18, 2017

bcardiff Mar 17, 2017

ysbaddaden Mar 18, 2017

ysbaddaden Mar 18, 2017

bcardiff Mar 20, 2017

ysbaddaden Mar 20, 2017

bcardiff Apr 4, 2017

ysbaddaden Apr 5, 2017

ysbaddaden commented Apr 13, 2017

bcardiff commented Apr 13, 2017

Sija commented Apr 14, 2017

ysbaddaden commented Apr 14, 2017

Get backtrace function names from DWARF sections #3958

Get backtrace function names from DWARF sections #3958

Conversation

ysbaddaden commented Jan 30, 2017 • edited Loading

0x1eef commented Jan 30, 2017

RX14 commented Jan 30, 2017

ysbaddaden commented Jan 30, 2017

RX14 commented Jan 30, 2017

ysbaddaden commented Jan 31, 2017

bcardiff left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ysbaddaden commented Apr 13, 2017

bcardiff commented Apr 13, 2017

Sija commented Apr 14, 2017

ysbaddaden commented Apr 14, 2017

ysbaddaden commented Jan 30, 2017 •

edited

Loading