JDK-8305005 : hs_err source line information is incorrect
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 21
  • Priority: P4
  • Status: Closed
  • Resolution: Won't Fix
  • Submitted: 2023-03-28
  • Updated: 2024-09-12
  • Resolved: 2023-07-13
Related Reports
Relates :  
JDK-8242181 - [Linux] Show source information when printing native stack traces in hs_err files
Relates :  
JDK-8305489 - runtime/ErrorHandling/TestDwarf.java fails in some Linux configurations after JDK-8303805
Description
I spotted the following:

Stack: [0x00007fc0da919000,0x00007fc0daa1a000],  sp=0x00007fc0daa18180,  free space=1020k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xf55024]  HandleArea::allocate_handle(oop)+0x214  (handles.cpp:40)
V  [libjvm.so+0x1416adb]  klassVtable::check_constraints(GrowableArray<InstanceKlass*>*, JavaThread*)+0x5eb  (handles.inline.hpp:42)
V  [libjvm.so+0x1417981]  klassVtable::initialize_vtable_and_check_constraints(JavaThread*)+0x1a1  (klassVtable.cpp:620)
V  [libjvm.so+0x1011257]  InstanceKlass::link_class_impl(JavaThread*)+0x3d7  (instanceKlass.cpp:917)
V  [libjvm.so+0x1620c47]  MetaspaceShared::try_link_class(JavaThread*, InstanceKlass*)+0xc7  (metaspaceShared.cpp:832)
V  [libjvm.so+0x1621797]  MetaspaceShared::link_shared_classes(bool, JavaThread*)+0x2e7  (metaspaceShared.cpp:620)
V  [libjvm.so+0xd01988]  DynamicArchive::dump_at_exit(JavaThread*, char const*)+0x318  (dynamicArchive.cpp:391)
V  [libjvm.so+0x10651d6]  before_exit(JavaThread*, bool)+0x86  (java.cpp:445)
V  [libjvm.so+0x1ac8798]  Threads::destroy_vm()+0x1b8  (threads.cpp:1085)
V  [libjvm.so+0x118c1ad]  jni_DestroyJavaVM+0xad  (jni.cpp:3735)
C  [libjli.so+0x3d42]  JavaMain+0x2c2  (java.c:555)
C  [libjli.so+0x7a29]  ThreadJavaMain+0x9  (java_md.c:650)


The second line:

V  [libjvm.so+0x1416adb]  klassVtable::check_constraints(GrowableArray<InstanceKlass*>*, JavaThread*)+0x5eb  (handles.inline.hpp:42)

is incorrectly listed as being from handles.inline.hpp when it is actually in klassVtable.cpp
Comments
Runtime Triage: This is not on our current list of priorities. We will consider this feature if we receive additional customer requirements.
13-07-2023
I think the problem is the PC for a native frame that contains inlined frames is ambiguous. It actually refers to multiple "logical" frames. The code that gets the function name is using dladdr(), so it gets the outer-most frame. The code that gets the file name and line number is using ElfDecoder-->ElfFile-->DwarfFile and gets the inner-most frame.
01-04-2023
That sounds good, thanks David!
31-03-2023
Thanks for that analysis [~chagedorn]! Will see if I can find a Decoder expert.
31-03-2023
I've had a closer look and it does not seem to be a problem with our DWARF parser. llvm-dwarfdump and addr2line show the same source information for the address 0x1416efc at the call (the pc at address 0x1416f0e points to the next instruction after the call, so we take the previous address 0x1416efc to find the correct source information). hs_err_file: Stack: [0x00007f49248ac000,0x00007f49249ac000], sp=0x00007f49249aa580, free space=1017k Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.so+0xf54d24] HandleArea::allocate_handle(oop)+0x224 (handles.cpp:41) V [libjvm.so+0x1416f0e] klassVtable::check_constraints(GrowableArray<InstanceKlass*>*, JavaThread*)+0x44e (handles.inline.hpp:42) DWARF parser: [dwarf] 0x0000000001416efc 42 53 48 [dwarf] ^^^ Found line for requested offset 0x01416f0e ^^^ [dwarf] 0x0000000001416f0e 95 5 17 llvm-dwarfdump: 0x0000000001416efc 42 53 48 0 0 0x0000000001416f0e 95 5 17 0 0 addr2line: addr2line -e /home/christian/jdk2/build/linux-x64-debug/jdk/lib/server/libjvm.so 0x1416efc /home/christian/jdk2/open/src/hotspot/share/runtime/handles.inline.hpp:42 That made me thinking whether Decoder::decode() might be the problem. First of all, for a caller frame, we are decoding the pc pointing to the next instruction after the call and not the address of the caller instruction which could return the wrong method. I've first checked the offset at 0x1416f0e at the pc with llvm-symbolizer: llvm-symbolizer -p --obj=/home/christian/jdk2/build/linux-x64-debug/jdk/lib/server/libjvm.so 0x1416f0e oop::~oop() at /home/christian/jdk2/open/src/hotspot/share/oops/oopsHierarchy.hpp:95:5 (inlined by) Handle::Handle(Thread*, oop) at /home/christian/jdk2/open/src/hotspot/share/runtime/handles.inline.hpp:42:53 (inlined by) klassVtable::check_constraints(GrowableArray<InstanceKlass*>*, JavaThread*) at /home/christian/jdk2/open/src/hotspot/share/oops/klassVtable.cpp:584:63 This indeed seems to return the wrong method for our call instruction. ~oop() is for the next instruction after the call which we are not really interested in. When instead checking the address 0x1416efc at the call, we get the correct Handle::Handle() method which called HandleArea::allocate_handle(): llvm-symbolizer -p --obj=/home/christian/jdk2/build/linux-x64-debug/jdk/lib/server/libjvm.so 0x1416efc Handle::Handle(Thread*, oop) at /home/christian/jdk2/open/src/hotspot/share/runtime/handles.inline.hpp:42:53 (inlined by) klassVtable::check_constraints(GrowableArray<InstanceKlass*>*, JavaThread*) at /home/christian/jdk2/open/src/hotspot/share/oops/klassVtable.cpp:584:63 However, in both cases our decoder finds the (same) inliner method klassVTable::check_constraints() and not the inlinee method Handle::Handle() which we would be interested in. The DWARF debug information, on the other hand, points to the inlinee method. Hence we get the confusing wrong information in the hs_err file. I could dig deeper into how our decoder works but I'm not familiar with that code and maybe someone else has more experience there.
30-03-2023
I've been seeing this sort of line number information (from the wrong file etc) in gdb, so I don't know if it's due to our code.
29-03-2023
[~chagedorn] as the expert here perhaps you could comment? Thanks.
29-03-2023
This is not about inexact line numbers it is about the completely wrong file being reported - and not in the usual way that inlining would affect this (ie the inlined code gets reported as being in the callers file).Here the non-inlined code was reported as being in the file that would potentially be inlined.
29-03-2023
Thanks [~dholmes] for the report. I can manually reproduce this case by adding a failing assert to HandleArea::allocate_handle(oop) when calling it from klassVtable::check_constraints(). I'm not yet sure what the problem is. I'll have a closer look.
29-03-2023
Runtime Triage: with fastdebug build the line numbers are not guaranteed to be exact, due to inlining.
28-03-2023
I don't have a direct reproducer as this happened whilst testing other changes and triggering a missing HandleMark assertion failure. I suspect the fact the Handle code gets inlined is what causes the source info to be incorrect - but that may be a limitation of the underlying Dwarf file representation.
28-03-2023