8344165: Trace exceptions with a complete call-stack

iklam · iklam · commit 20e0055e202e · 2025-06-26T17:23:55.000Z
Reviewed-by: coleenp, dholmes
diff --git a/src/hotspot/share/interpreter/interpreterRuntime.cpp b/src/hotspot/share/interpreter/interpreterRuntime.cpp
@@ -500,6 +500,10 @@ JRT_ENTRY(address, InterpreterRuntime::exception_handler_for_exception(JavaThrea
                    h_method->print_value_string(), current_bci, p2i(current), current->name());
       Exceptions::log_exception(h_exception, tempst.as_string());
     }
+    if (log_is_enabled(Info, exceptions, stacktrace)) {
+      Exceptions::log_exception_stacktrace(h_exception, h_method, current_bci);
+    }
+
 // Don't go paging in something which won't be used.
 //     else if (extable->length() == 0) {
 //       // disabled for now - interpreter is not using shortcut yet
diff --git a/src/hotspot/share/utilities/exceptions.cpp b/src/hotspot/share/utilities/exceptions.cpp
@@ -114,15 +114,17 @@ bool Exceptions::special_exception(JavaThread* thread, const char* file, int lin
 #endif // ASSERT
 
   if (h_exception.is_null() && !thread->can_call_java()) {
-    ResourceMark rm(thread);
-    const char* exc_value = h_name != nullptr ? h_name->as_C_string() : "null";
-    log_info(exceptions)("Thread cannot call Java so instead of throwing exception <%.*s%s%.*s> (" PTR_FORMAT ") \n"
-                        "at [%s, line %d]\nfor thread " PTR_FORMAT ",\n"
-                        "throwing pre-allocated exception: %s",
-                        MAX_LEN, exc_value, message ? ": " : "",
-                        MAX_LEN, message ? message : "",
-                        p2i(h_exception()), file, line, p2i(thread),
-                        Universe::vm_exception()->print_value_string());
+    if (log_is_enabled(Info, exceptions)) {
+      ResourceMark rm(thread);
+      const char* exc_value = h_name != nullptr ? h_name->as_C_string() : "null";
+      log_info(exceptions)("Thread cannot call Java so instead of throwing exception <%.*s%s%.*s> (" PTR_FORMAT ") \n"
+                           "at [%s, line %d]\nfor thread " PTR_FORMAT ",\n"
+                           "throwing pre-allocated exception: %s",
+                           MAX_LEN, exc_value, message ? ": " : "",
+                           MAX_LEN, message ? message : "",
+                           p2i(h_exception()), file, line, p2i(thread),
+                           Universe::vm_exception()->print_value_string());
+    }
     // We do not care what kind of exception we get for a thread which
     // is compiling.  We just install a dummy exception object
     thread->set_pending_exception(Universe::vm_exception(), file, line);
@@ -152,6 +154,9 @@ void Exceptions::_throw(JavaThread* thread, const char* file, int line, Handle h
                        message ? ": " : "",
                        MAX_LEN, message ? message : "",
                        p2i(h_exception()), file, line, p2i(thread));
+  if (log_is_enabled(Info, exceptions, stacktrace)) {
+    log_exception_stacktrace(h_exception);
+  }
 
   // for AbortVMOnException flag
   Exceptions::debug_check_abort(h_exception, message);
@@ -609,3 +614,42 @@ void Exceptions::log_exception(Handle exception, const char* message) {
                          MAX_LEN, message);
   }
 }
+
+// This is called from InterpreterRuntime::exception_handler_for_exception(), which is the only
+// easy way to be notified in the VM that an _athrow bytecode has been executed. (The alternative
+// would be to add hooks into the interpreter and compiler, for all platforms ...).
+//
+// Unfortunately, InterpreterRuntime::exception_handler_for_exception() is called for every level
+// of the Java stack when looking for an exception handler. To avoid excessive output,
+// we print the stack only when the bci points to an _athrow bytecode.
+//
+// NOTE: exceptions that are NOT thrown by _athrow are handled by Exceptions::special_exception()
+// and Exceptions::_throw()).
+void Exceptions::log_exception_stacktrace(Handle exception, methodHandle method, int bci) {
+  if (!method->is_native() && (Bytecodes::Code) *method->bcp_from(bci) == Bytecodes::_athrow) {
+    // TODO: try to find a way to avoid repeated stacktraces when an exception gets re-thrown
+    // by a finally block
+    log_exception_stacktrace(exception);
+  }
+}
+
+// This should be called only from a live Java thread.
+void Exceptions::log_exception_stacktrace(Handle exception) {
+  LogStreamHandle(Info, exceptions, stacktrace) st;
+  ResourceMark rm;
+  const char* detail_message = java_lang_Throwable::message_as_utf8(exception());
+  if (detail_message != nullptr) {
+    st.print_cr("Exception <%.*s: %.*s>",
+                MAX_LEN, exception->print_value_string(),
+                MAX_LEN, detail_message);
+  } else {
+    st.print_cr("Exception <%.*s>",
+                MAX_LEN, exception->print_value_string());
+  }
+  JavaThread* t = JavaThread::current();
+  if (t->has_last_Java_frame()) {
+    t->print_active_stack_on(&st);
+  } else {
+    st.print_cr("(Cannot print stracktrace)");
+  }
+}
diff --git a/src/hotspot/share/utilities/exceptions.hpp b/src/hotspot/share/utilities/exceptions.hpp
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 1998, 2024, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2025, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -190,6 +190,8 @@ class Exceptions {
 
   // for logging exceptions
   static void log_exception(Handle exception, const char* message);
+  static void log_exception_stacktrace(Handle exception);
+  static void log_exception_stacktrace(Handle exception, methodHandle method, int bci);
 };
 
 
diff --git a/test/hotspot/jtreg/runtime/logging/ExceptionsTest.java b/test/hotspot/jtreg/runtime/logging/ExceptionsTest.java
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2025, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -23,7 +23,7 @@
 
 /*
  * @test
- * @bug 8141211 8147477
+ * @bug 8141211 8147477 8358080
  * @summary exceptions=info output should have an exception message for interpreter methods
  * @requires vm.flagless
  * @library /test/lib
@@ -34,6 +34,8 @@
 
 import java.io.File;
 import java.util.Map;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
 import jdk.test.lib.process.OutputAnalyzer;
 import jdk.test.lib.process.ProcessTools;
 
@@ -44,10 +46,24 @@ static void updateEnvironment(ProcessBuilder pb, String environmentVariable, Str
     }
 
     static void analyzeOutputOn(ProcessBuilder pb) throws Exception {
-        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        OutputAnalyzer output = ProcessTools.executeProcess(pb);
         output.shouldContain("<a 'java/lang/RuntimeException'").shouldContain(": Test exception 1 for logging>");
         output.shouldContain(" thrown in interpreter method ");
-        output.shouldHaveExitValue(0);
+        output.shouldMatch("info..exceptions,stacktrace.*at ExceptionsTest[$]InternalClass.bar[(]ExceptionsTest.java:[0-9]+" +
+                           ".*\n.*" +
+                           "info..exceptions,stacktrace.*at ExceptionsTest[$]InternalClass.foo[(]ExceptionsTest.java:[0-9]+" +
+                           ".*\n.*" +
+                           "info..exceptions,stacktrace.*at ExceptionsTest[$]InternalClass.main[(]ExceptionsTest.java:[0-9]+");
+
+        // Note: "(?s)" means that the "." in the regexp can match the newline character.
+        // To avoid verbosity, stack trace for bar2()->baz2() should be printed only once:
+        // - It should be printed when the exception is thrown inside bzz2()
+        // - It should not be printed when the interpreter is looking for an exception handler inside bar2()
+        output.shouldMatch("(?s)baz2.*bar2");
+        output.shouldNotMatch("(?s)baz2.*bar2,*baz2.*bar2");
+
+        // Two stack traces should include main()->foo2(), as an exception is thrown at two different BCIs in bar2().
+        output.shouldMatch("(?s)foo2.*main.*foo2.*main");
     }
 
     static void analyzeOutputOff(ProcessBuilder pb) throws Exception {
@@ -57,7 +73,7 @@ static void analyzeOutputOff(ProcessBuilder pb) throws Exception {
     }
 
     public static void main(String[] args) throws Exception {
-        ProcessBuilder pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:exceptions=info",
+        ProcessBuilder pb = ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:exceptions,exceptions+stacktrace",
                                                                              InternalClass.class.getName());
         analyzeOutputOn(pb);
 
@@ -66,7 +82,7 @@ public static void main(String[] args) throws Exception {
         analyzeOutputOff(pb);
 
         pb = ProcessTools.createLimitedTestJavaProcessBuilder(InternalClass.class.getName());
-        updateEnvironment(pb, "_JAVA_OPTIONS", "-Xlog:exceptions=info");
+        updateEnvironment(pb, "_JAVA_OPTIONS", "-Xlog:exceptions,exceptions+stacktrace");
         analyzeOutputOn(pb);
 
         pb = ProcessTools.createLimitedTestJavaProcessBuilder(InternalClass.class.getName());
@@ -80,12 +96,45 @@ public static void main(String[] args) throws Exception {
     }
 
     public static class InternalClass {
-        public static void main(String[] args) throws Exception {
+        public static void main(String[] args) {
+            foo();
+            foo2();
+        }
+
+        static void foo() {
+            bar();
+        }
+
+        static void bar() {
             try {
                 throw new RuntimeException("Test exception 1 for logging");
             } catch (Exception e) {
                 System.out.println("Exception 1 caught.");
             }
         }
+
+        static void foo2() {
+            try {
+                bar2();
+            } catch (Exception e) {
+                System.out.println("Exception 2 caught.");
+            }
+        }
+
+        static void bar2() {
+            try {
+                baz2();
+            } catch (RuntimeException e) {
+                throw e; // Rethrow -- should print a new callstack.
+            }
+        }
+
+        static void baz2() {
+            bzz2();
+        }
+
+        static void bzz2() {
+            throw new RuntimeException("Test exception 2 for logging");
+        }
     }
 }
diff --git a/test/hotspot/jtreg/runtime/logging/ExceptionsTest_options_file b/test/hotspot/jtreg/runtime/logging/ExceptionsTest_options_file
@@ -1 +1 @@
--Xlog:exceptions=info
+-Xlog:exceptions,exceptions+stacktrace

Original file line number	Diff line number	Diff line change
`@@ -1 +1 @@`
`1`		`--Xlog:exceptions=info`
	`1`	`+-Xlog:exceptions,exceptions+stacktrace`