Re: [RFC][PATCH] Allow JIT unwinder provide symbol information

[Doug Evans <dje@google.com>]

On Sun, Feb 9, 2014 at 6:16 PM, Alexander Smundak <asmundak@google.com> wrote:
> On Fri, Feb 7, 2014 at 11:06 PM, Yao Qi <yao@codesourcery.com> wrote:
>> On 12/27/2013 02:36 AM, Sasha Smundak wrote:
>>> The change proposed in this RFC is part of the effort to support
>>> debugging applications containing Java code executed with the help of
>>> Java interpreter/ just-in-time (JIT) compiler. Here's the fragment of
>>> the backtrace of an application being debugged by the GDB modified to
>>> provide such support:
>>>
>>> #8 0x00007fffea743b03 in JNIEnv_::CallVoidMethod (this=0x7ffff001f220, obj=0x7ffff665d810, methodID=0x7ffff019d6d0) at <...>/jdk/include/jni.h:1054
>>> #9 0x00007fffea7439c2 in Java_Util_callObjectMethod (env=0x7ffff001f220, myclass=0x7ffff665d840, target_object=0x7ffff665d810, method_name=0x7ffff665d818) at <...>/testjni.cc:48
>>> #10 0x00007fffed05ef7b in Util.callObjectMethod+0x15b[C] (java.lang.Object=???) at Util.java:-1
>>> #11 0x00007fffed061188 in Myclass.method1+0x68[C] (this=@f665d2a8) at Myclass.java:18
>>> #12 0x00007fffed005f98 in Myclass.main#I ([]=[...]) at Myclass.java:48
>>> #13 0x00007fffed000438 in <StubRoutines> ()
>>>
>>> I.e., Myclass.main() calls Myclass.method1() calls
>>> Util.callObjectMethod(), which is implemented as a C function
>>> Java_Util_callObjectMethod(). Myclass.main() is interpreted, while
>>> Myclass.method1() is JIT-compiled.
>>
>> IWBN to show how GDB behaves without this patch.
>
> Here's what GDB shows without the plugin:
> (gdb) where
> #0  Java_gdbtest_Util_breakpoint (env=0x7ffff0009220,
> myclass=0x7ffff649c258) at <...>/testjni.cc:24
> #1  0x00007fffea013306 in ?? ()
> #2  0x00007ffff649c468 in ?? ()
> #3  0x00007ffff649c208 in ?? ()
> #4  0x000000060569ef48 in ?? ()
> #5  0x00007ffff649c260 in ?? ()
> #6  0x000000060569f638 in ?? ()
> #7  0x0000000000000000 in ?? ()
>
> and this is what is shows with the plugin:
> (gdb) jit-reader-load java.so
> (gdb) where
> #0  Java_gdbtest_Util_breakpoint (env=0x7ffff0009220,
> myclass=0x7ffff649c258) at <...>/testjni.cc:24
> #1  0x00007fffea013306 in gdbtest.Util.breakpoint#I () at Util.java:-1
> #2  0x00007fffea0667f4 in gdbtest.Interpreted.inner+0x54[C] (this=?)
> at Interpreted.java:31
> #3  0x00007fffea0004e7 in <StubRoutines> ()
> #4  0x00007ffff6bb6988 in JavaCalls::call_helper (result=<optimized
> out>, m=<optimized out>, args=<optimized out>,
> __the_thread__=<optimized out>)
>     at <...>/hotspot/src/share/vm/runtime/javaCalls.cpp:422
> #5  0x00007ffff6bb59d8 in JavaCalls::call (result=<optimized out>,
> method=..., args=0x0, __the_thread__=0x0)
>     at <...>/hotspot/src/share/vm/runtime/javaCalls.cpp:320
> #6  0x00007ffff6bc579d in jni_invoke_nonstatic (env=<optimized out>,
> result=0x7ffff649c620, receiver=<optimized out>, call_type=<optimized
> out>,
>     method_id=<optimized out>, args=0x7ffff649c5c0,
> __the_thread__=0x7ffff0009000)
>     at <...>/hotspot/src/share/vm/prims/jni.cpp:1414
> #7  0x00007ffff6bd1586 in jni_CallVoidMethodV(JNIEnv *, jobject,
> jmethodID, typedef __va_list_tag __va_list_tag *) (env=0x7ffff0009220,
>     obj=<optimized out>, methodID=0x7ffff0079848, args=<optimized out>)
>     at <...>/hotspot/src/share/vm/prims/jni.cpp:1958
> #8  0x00007fffe181ab03 in JNIEnv_::CallVoidMethod
> (this=0x7ffff0009220, obj=0x7ffff649c7e0, methodID=0x7ffff0079848)
>     at <...>/jdk/include/jni.h:1054
> #9  0x00007fffe181a9c2 in Java_gdbtest_Util_callObjectMethod
> (env=0x7ffff0009220, myclass=0x7ffff649c810,
> target_object=0x7ffff649c7e0,
>     method_name=0x7ffff649c7e8) at <...>/testjni.cc:48
> #10 0x00007fffea06043b in gdbtest.Util.callObjectMethod+0x15b[C]
> (java.lang.Object=???) at Util.java:-1
> #11 0x00007fffea066508 in gdbtest.Interpreted.method1+0x68[C] (this=?)
> at Interpreted.java:18
> #12 0x00007fffea006058 in gdbtest.Interpreted.main#I ([]=[...]) at
> Interpreted.java:48
> #13 0x00007fffea0004e7 in <StubRoutines> ()
> #14 0x00007ffff6bb6988 in JavaCalls::call_helper (result=<optimized
> out>, m=<optimized out>, args=<optimized out>,
> __the_thread__=<optimized out>)
>     at <...>/hotspot/src/share/vm/runtime/javaCalls.cpp:422
> #15 0x00007ffff6bb59d8 in JavaCalls::call (result=<optimized out>,
> method=..., args=0x0, __the_thread__=0x0)
>     at <...>/hotspot/src/share/vm/runtime/javaCalls.cpp:320
> #16 0x00007ffff6bc6501 in jni_invoke_static (env=<optimized out>,
> result=0x7ffff649cc90, receiver=<optimized out>, call_type=<optimized
> out>,
>     method_id=<optimized out>, args=0x7ffff649cc10,
> __the_thread__=0x7ffff0009000)
>     at <...>/hotspot/src/share/vm/prims/jni.cpp:1338
> #17 0x00007ffff6bd3008 in jni_CallStaticVoidMethod
> (env=0x7ffff0009220, cls=<optimized out>, methodID=0x7ffff0079840)
>     at <...>/hotspot/src/share/vm/prims/jni.cpp:2541
> #18 0x00007ffff7fdc7a4 in JavaMain (_args=<optimized out>) at
> ../../../src/share/bin/java.c:522
> #19 0x00007ffff7bc314e in start_thread () from
> /usr/grte/v3/lib64/libpthread.so.0
> #20 0x00007ffff763569d in clone () from /usr/grte/v3/lib64/libc.so.6
> #21 0x0000000000000000 in ?? ()
>
> (I've replaced absolute paths with <...>).
> Note that unaided GDB is unable to unwind the stack correctly as JVM
> does not always save the frame pointer at the expected place and
> does not supply explicit unwind info.
>
>>> ... Second, when JVM runs Java code in the
>>> interpreted mode, the code address in the frame points to the
>>> interpreter code, which is not what should be displayed.
>>
>> That is a separate problem, IMO.  GDB JIT interface was designed to deal
>> with JIT'ed code.  In interpreted mode, it is reasonable to me
>> that GDB shows the interpreter code in backtrace, because JVM is just a
>> typical executable, which is being debugged via GDB.  I don't know how
>> does your patch help to this problem.
> Consider this traceback (obtained with the same code running in JVM
> with JIT disabled):
>
> #0  Java_gdbtest_Util_breakpoint ...
> #1  0x00007fffea013306 in gdbtest.Util.breakpoint#I () at Util.java:-1
> #2  0x00007fffea006058 in gdbtest.Interpreted.inner#I (this=@58cd65e0)
> at Interpreted.java:31
> #3  0x00007fffea0004e7 in <StubRoutines> ()
> #4  0x00007ffff6bb6988 in JavaCalls::call_helper (...)
> #5  0x00007ffff6bb59d8 in JavaCalls::call (...)
> #6  0x00007ffff6bc579d in jni_invoke_nonstatic (...)
> #7  0x00007ffff6bd1586 in jni_CallVoidMethodV(...)
> #8  0x00007fffe181ab03 in JNIEnv_::CallVoidMethod (...)
> #9  0x00007fffe181a9c2 in Java_gdbtest_Util_callObjectMethod (...)
> #10 0x00007fffea013306 in gdbtest.Util.callObjectMethod#I ()
> #11 0x00007fffea006058 in gdbtest.Interpreted.method1#I ()
> #12 0x00007fffea006058 in gdbtest.Interpreted.main#I (...)
> #13 0x00007fffea0004e7 in <StubRoutines> ()
> ...
> Notice that the frames #2, #11, #12 have the same PC, which is the location of
> the place in the interpreter where it executes 'call method' instruction.
> The JIT plugin in this case additionally shows the location of the call in the
> Java source code, which is more useful.

Thanks for the examples!

>>>
>>> The solution proposed here is to add a "symbol provider" function to
>>> the unwinder interface and modify the code displaying frames to get
>>> the symbol information associated with the frame (function name,
>>> source location, arguments) from the frame's unwinder if it has
>>> symbol provider and use the current logic as a fallback strategy.
>>
>> IMHO, it is not a good idea to add "symbol provider" to the unwinder, as
>> it is unrelated to unwinding.  Unwinder's job is to compute the 'next'
>> frame_info, given one frame_info.  Displaying the function name and
>> source file of a frame_info is out the scope of its responsibilities.
>>
>> It is fine to register "symbol provider" to interpret frames of JIT'ed
>> code to function name, source file, and so forth, but I feel
>> uncomfortable to add "symbol provider" to the unwinder, at least to
>> 'struct frame_unwind'.
> I agree it would be more appropriate to rename 'frame_unwind'
> to 'frame_handler'. However, it's just a refactoring that can be done
> separately.

Agreed.