JDK-8328639 : Add support for including a native stack trace in -Xlog:exceptions
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2024-03-20
  • Updated: 2025-04-10
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8193513 - add support for printing a stack trace on class loading
Relates :  
JDK-8344165 - Trace exceptions with a complete call-stack
Description
While the output of -Xlog:exceptions is already very helpful in diagnosing bugs, sometimes it helps to know where an exception is coming from within the VM.

For example, the CompileBroker does String constant resolution[1] and in JDK tests that stress OutOfMemoryError handling, this resolution can result in "spurious" OOMEs that cause test failure, especially when running -Xcomp. This was discovered by enhancing -Xlog:exceptions output to include a native stack trace when throwing an OOME (see dump_oome_native_stack.patch).

Such a general purpose facility can help with diagnosing other "spurious" exceptions. It could be modeled after JDK-8193513 with a new flag:

  product(ccstr, LogExceptionNativeStackFor, nullptr,                       \
          "Enhance -Xlog:exceptions to include a native stack trace for "   \
          "exceptions whose qualified name in internal format "             \
          "(e.g., java/lang/OutOfMemoryError) contains this string.")       \

[1] https://github.com/openjdk/jdk/blob/000f4d8d156a48939fd29f8b4dd84b3dfd7d9d95/src/hotspot/share/compiler/compileBroker.cpp#L1400
Comments
In your example, I see mostly only Java frames. For example: [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> (0x0000000456014810) thrown [open/src/hotspot/share/oops/instanceKlass.cpp, line 1183] for thread 0x00007fa6e40296b0 For this trace statement, where are the missing native frames between `instanceKlass.cpp:1183` and `Class.forName0`? With what I'm proposing, you would see them: V [libjvm.dylib+0x56f934] JVM_FindClassFromCaller+0x360 C [libjava.dylib+0x22d8] Java_java_lang_Class_forName0+0x134 j java.lang.Class.forName0(Ljava/lang/String;ZLjava/lang/ClassLoader;Ljava/lang/Class;)Ljava/lang/Class;+0 java.base@23-internal Of course, this level of detail is much more than you want in most situations (and not particularly illuminating in this example). But as [~never] and I discovered, it can be *very* useful in debugging unexpected exceptions thrown deep in VM code on compiler threads.
22-04-2024
Yes you are right, only frames actually involved in exception processing will be present in the current logging.
25-03-2024
> This feels analogous to JDK-8193513. It's a heavy extension to universal logging (UL) that would require an extra flag to enable it. JDK-8193513 added new UL tags as well as the flag for filtering. This one just adds the flag. There is definitely similarity here but I'm feeling uncomfortable with establishing this kind of pattern for extending UL this way. In general any logged event might end up being something where you wish you had a stacktrace. Need to think more about this and see what others think.
25-03-2024
> You're saying that there is already a -Xlog:exceptions line of output corresponding to each of the frames in my example stack trace above? There should be yes. As we unwind the stack and the exception is not caught we should log that the exception is thrown from that method. Of course if it is caught that won't happen, but with the right level of detail you will see where it was caught. Here's an example: public class Erroneous { static class Bad { static { throwIt(); } static void throwIt() { throw new RuntimeException(); } } public static void main(String[] args) throws Throwable { try { Class<?> c = Class.forName("Erroneous$Bad"); } catch (ExceptionInInitializerError eiie) { System.out.println("Okay got EIIE: " + eiie); } try { Class<?> c = Class.forName("Erroneous$Bad"); } catch (NoClassDefFoundError ncdfe) { System.out.println("Okay got NCDFE: " + ncdfe); Throwable cause = ncdfe.getCause(); System.out.println("With cause: " + cause); cause = cause.getCause(); System.out.println("With cause: " + cause); } } } > java21 -Xlog:exceptions Erroneous [0.031s][info][exceptions] Exception <a 'java/lang/RuntimeException'{0x0000000456013330}> thrown in interpreter method <{method} {0x00007fa657400a18} 'throwIt' '()V' in Erroneous$Bad'> at bci 7 for thread 0x00007fa6e40296b0 (main) [0.031s][info][exceptions] Exception <a 'java/lang/RuntimeException'{0x0000000456013330}> thrown in interpreter method <{method} {0x00007fa657400ab0} '<clinit>' '()V' in Erroneous$Bad'> at bci 0 for thread 0x00007fa6e40296b0 (main) [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> (0x0000000456014810) thrown [open/src/hotspot/share/oops/instanceKlass.cpp, line 1183] for thread 0x00007fa6e40296b0 [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> thrown in interpreter method <{method} {0x00007fa65b470180} 'forName0' '(Ljava/lang/String;ZLjava/lang/ClassLoader;Ljava/lang/Class;)Ljava/lang/Class;' in 'java/lang/Class'> at bci 0 for thread 0x00007fa6e40296b0 (main) [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> thrown in interpreter method <{method} {0x00007fa65b4701e8} 'forName' '(Ljava/lang/String;Ljava/lang/Class;)Ljava/lang/Class;' in 'java/lang/Class'> at bci 19 for thread 0x00007fa6e40296b0 (main) [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> thrown in interpreter method <{method} {0x00007fa65b470240} 'forName' '(Ljava/lang/String;)Ljava/lang/Class;' in 'java/lang/Class'> at bci 6 for thread 0x00007fa6e40296b0 (main) [0.032s][info][exceptions] Exception <a 'java/lang/ExceptionInInitializerError'{0x0000000456014810}> thrown in interpreter method <{method} {0x00007fa657400518} 'main' '([Ljava/lang/String;)V' in 'Erroneous'> at bci 2 for thread 0x00007fa6e40296b0 (main) [0.032s][info][exceptions] Found matching handler for exception of type "java.lang.ExceptionInInitializerError" in method "main" at BCI: 9 Okay got EIIE: java.lang.ExceptionInInitializerError ...
25-03-2024
> All the frames should be there you just have to collate them for a given thread. You're saying that there is already a -Xlog:exceptions line of output corresponding to each of the frames in my example stack trace above? How does that work? Wouldn't that involve a native stack walk to be done within the code that implements -Xlog:exceptions? I cannot see such code. > I'm just not sure logging is the right mechanism for dumping the stack in this way. This seems more like a standalone DumpStackOnException flag. This feels analogous to JDK-8193513. It's a heavy extension to universal logging (UL) that would require an extra flag to enable it. But I don't mind if it's a dedicated flag, disjoint from UL.
22-03-2024
> I'm aware of that but it's only a single frame All the frames should be there you just have to collate them for a given thread. Certainly the logging output is not as convenient as a complete stacktrace, I'm just not sure logging is the right mechanism for dumping the stack in this way. This seems more like a standalone DumpStackOnException flag.
22-03-2024
> The frame information is actually present in the existing output I'm aware of that but it's only a single frame and doesn't show the VM call stack. Here is some output produced by dump_oome_native_stack.patch that shows how this extra output looks: [34.881s][info][exceptions] Exception <a 'java/lang/OutOfMemoryError'{0x00001000002d8448}> (0x00001000002d8448) thrown [c:\\sb\\prod\\1710914048\\workspace\\open\\src\\hotspot\\share\\gc\\shared\\memAllocator.cpp, line 138] for thread 0x00000221b0721c30 Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) V [jvm.dll+0xc960d1] os::win32::platform_print_native_stack+0x101 (os_windows_x86.cpp:235) V [jvm.dll+0x62e0e1] dump_oome_native_stack+0x131 (exceptions.cpp:147) V [jvm.dll+0x62c23a] Exceptions::_throw+0x11a (exceptions.cpp:168) V [jvm.dll+0x62d85b] Exceptions::_throw_oop+0xab (exceptions.cpp:140) V [jvm.dll+0xbbce78] MemAllocator::Allocation::check_out_of_memory+0x208 (memAllocator.cpp:138) V [jvm.dll+0xbbcac8] MemAllocator::allocate+0x158 (memAllocator.cpp:377) V [jvm.dll+0x79bd05] InstanceKlass::allocate_instance+0x95 (instanceKlass.cpp:1509) V [jvm.dll+0x7ddeed] java_lang_String::basic_create+0x9d (javaClasses.cpp:273) V [jvm.dll+0x7e43c0] java_lang_String::create_from_unicode+0x60 (javaClasses.cpp:291) V [jvm.dll+0xdb91a5] StringTable::do_intern+0xb5 (stringTable.cpp:379) V [jvm.dll+0xdba9f2] StringTable::intern+0x1b2 (stringTable.cpp:368) V [jvm.dll+0xdbaaa6] StringTable::intern+0x86 (stringTable.cpp:328) V [jvm.dll+0x51c8b1] ConstantPool::string_at_impl+0x1d1 (constantPool.cpp:1251) V [jvm.dll+0x51b95b] ConstantPool::resolve_string_constants_impl+0xeb (constantPool.cpp:800) V [jvm.dll+0x4f2f8d] CompileBroker::compile_method+0x31d (compileBroker.cpp:1395) V [jvm.dll+0x4f3474] CompileBroker::compile_method+0xc4 (compileBroker.cpp:1348) V [jvm.dll+0x4d56d7] CompilationPolicy::compile_if_required+0x1d7 (compilationPolicy.cpp:108) V [jvm.dll+0xad28f1] LinkResolver::resolve_static_call+0x171 (linkResolver.cpp:1089) V [jvm.dll+0xad166f] LinkResolver::resolve_invoke+0xaf (linkResolver.cpp:1626) V [jvm.dll+0x7c8482] InterpreterRuntime::resolve_invoke+0x3a2 (interpreterRuntime.cpp:857) V [jvm.dll+0x7c7827] InterpreterRuntime::resolve_from_cache+0x147 (interpreterRuntime.cpp:982) C 0x0000021fab1e0697 (no source info available) It was this native stack trace that helped us see the spurious OOMEs were coming from the call to ConstantPool::resolve_string_constants from CompileBroker::compile_method.
21-03-2024
The frame information is actually present in the existing output, but may be hard to find if there are many exceptions happening at the same time. Depending on the logging level you see where an exception was thrown, whether a method caught it etc.. Because of the varying logging levels and the amount of detail that is produced at each level, I'm unclear where exactly the stack output would be generated - is it at the "throw" site, and we would then start unwinding the stack and reporting whether the exceptions was caught or rethrown for each frame? BTW when running -Xcomp the exception logging is unfortunately swamped by all the speculative actions of the compiler threads that encounter exceptions that can't actually be thrown e.g. [0.636s][info][exceptions] Thread cannot call Java so instead of throwing exception <java/lang/IncompatibleClassChangeError : Found interface java.security.PrivilegedAction, but class was expected> (0x0000000000000000) at [/scratch/users/daholme/jdk-dev3.git/open/src/hotspot/share/interpreter/linkResolver.cpp, line 735] for thread 0x00007f1490266810, throwing pre-allocated exception: a 'java/lang/VirtualMachineError'{0x0000000456001078}
21-03-2024