8193513: add support for printing a stack trace on class loading

Reviewed-by: dholmes, iklam, coleenp

Author: Doug Simon

src/hotspot/share/logging/logTag.hpp

@@ -45,6 +45,7 @@ class outputStream;
   LOG_TAG(bot) \
   LOG_TAG(breakpoint) \
   LOG_TAG(bytecode) \
+  LOG_TAG(cause) \
   LOG_TAG(cds) \
   LOG_TAG(census) \
   LOG_TAG(class) \
@@ -124,6 +125,7 @@ class outputStream;
   LOG_TAG(module) \
   LOG_TAG(monitorinflation) \
   LOG_TAG(monitormismatch) \
+  LOG_TAG(native) \
   LOG_TAG(nestmates) \
   LOG_TAG(nmethod) \
   LOG_TAG(nmt) \

src/hotspot/share/oops/instanceKlass.cpp

@@ -83,6 +83,7 @@
 #include "runtime/javaThread.inline.hpp"
 #include "runtime/mutexLocker.hpp"
 #include "runtime/orderAccess.hpp"
+#include "runtime/os.inline.hpp"
 #include "runtime/reflectionUtils.hpp"
 #include "runtime/threads.hpp"
 #include "services/classLoadingService.hpp"
@@ -3786,10 +3787,19 @@ const char* InstanceKlass::internal_name() const {
 void InstanceKlass::print_class_load_logging(ClassLoaderData* loader_data,
                                              const ModuleEntry* module_entry,
                                              const ClassFileStream* cfs) const {
+
   if (ClassListWriter::is_enabled()) {
     ClassListWriter::write(this, cfs);
   }
 
+  print_class_load_helper(loader_data, module_entry, cfs);
+  print_class_load_cause_logging();
+}
+
+void InstanceKlass::print_class_load_helper(ClassLoaderData* loader_data,
+                                             const ModuleEntry* module_entry,
+                                             const ClassFileStream* cfs) const {
+
   if (!log_is_enabled(Info, class, load)) {
     return;
   }
@@ -3847,15 +3857,15 @@ void InstanceKlass::print_class_load_logging(ClassLoaderData* loader_data,
 
     // Class hierarchy info
     debug_stream.print(" klass: " PTR_FORMAT " super: " PTR_FORMAT,
-                       p2i(this),  p2i(superklass()));
+                      p2i(this),  p2i(superklass()));
 
     // Interfaces
     if (local_interfaces() != nullptr && local_interfaces()->length() > 0) {
       debug_stream.print(" interfaces:");
       int length = local_interfaces()->length();
       for (int i = 0; i < length; i++) {
         debug_stream.print(" " PTR_FORMAT,
-                           p2i(InstanceKlass::cast(local_interfaces()->at(i))));
+                          p2i(InstanceKlass::cast(local_interfaces()->at(i))));
       }
     }
 
@@ -3867,15 +3877,75 @@ void InstanceKlass::print_class_load_logging(ClassLoaderData* loader_data,
     // Classfile checksum
     if (cfs) {
       debug_stream.print(" bytes: %d checksum: %08x",
-                         cfs->length(),
-                         ClassLoader::crc32(0, (const char*)cfs->buffer(),
-                         cfs->length()));
+                        cfs->length(),
+                        ClassLoader::crc32(0, (const char*)cfs->buffer(),
+                        cfs->length()));
     }
 
     msg.debug("%s", debug_stream.as_string());
   }
 }
 
+void InstanceKlass::print_class_load_cause_logging() const {
+  bool log_cause_native = log_is_enabled(Info, class, load, cause, native);
+  if (log_cause_native || log_is_enabled(Info, class, load, cause)) {
+    JavaThread* current = JavaThread::current();
+    ResourceMark rm(current);
+    const char* name = external_name();
+
+    if (LogClassLoadingCauseFor == nullptr ||
+        (strcmp("*", LogClassLoadingCauseFor) != 0 &&
+         strstr(name, LogClassLoadingCauseFor) == nullptr)) {
+        return;
+    }
+
+    // Log Java stack first
+    {
+      LogMessage(class, load, cause) msg;
+      NonInterleavingLogStream info_stream{LogLevelType::Info, msg};
+
+      info_stream.print_cr("Java stack when loading %s:", name);
+      current->print_stack_on(&info_stream);
+    }
+
+    // Log native stack second
+    if (log_cause_native) {
+      // Log to string first so that lines can be indented
+      stringStream stack_stream;
+      char buf[O_BUFLEN];
+      address lastpc = nullptr;
+      if (os::platform_print_native_stack(&stack_stream, nullptr, buf, O_BUFLEN, lastpc)) {
+        // We have printed the native stack in platform-specific code,
+        // so nothing else to do in this case.
+      } else {
+        frame f = os::current_frame();
+        VMError::print_native_stack(&stack_stream, f, current, true /*print_source_info */,
+                                    -1 /* max stack_stream */, buf, O_BUFLEN);
+      }
+
+      LogMessage(class, load, cause, native) msg;
+      NonInterleavingLogStream info_stream{LogLevelType::Info, msg};
+      info_stream.print_cr("Native stack when loading %s:", name);
+
+      // Print each native stack line to the log
+      int size = (int) stack_stream.size();
+      char* stack = stack_stream.as_string();
+      char* stack_end = stack + size;
+      char* line_start = stack;
+      for (char* p = stack; p < stack_end; p++) {
+        if (*p == '\n') {
+          *p = '\0';
+          info_stream.print_cr("\t%s", line_start);
+          line_start = p + 1;
+        }
+      }
+      if (line_start < stack_end) {
+        info_stream.print_cr("\t%s", line_start);
+      }
+    }
+  }
+}
+
 // Verification
 
 class VerifyFieldClosure: public BasicOopIterateClosure {

src/hotspot/share/oops/instanceKlass.hpp

@@ -1164,6 +1164,11 @@ class InstanceKlass: public Klass {
   void print_class_load_logging(ClassLoaderData* loader_data,
                                 const ModuleEntry* module_entry,
                                 const ClassFileStream* cfs) const;
+ private:
+  void print_class_load_cause_logging() const;
+  void print_class_load_helper(ClassLoaderData* loader_data,
+                               const ModuleEntry* module_entry,
+                               const ClassFileStream* cfs) const;
 };
 
 // for adding methods

src/hotspot/share/runtime/arguments.cpp

@@ -3961,6 +3961,12 @@ jint Arguments::parse(const JavaVMInitArgs* initial_cmd_args) {
     warning("dependency logging results may be inflated by VerifyDependencies");
   }
 
+  bool log_class_load_cause = log_is_enabled(Info, class, load, cause, native) ||
+                              log_is_enabled(Info, class, load, cause);
+  if (log_class_load_cause && LogClassLoadingCauseFor == nullptr) {
+    warning("class load cause logging will not produce output without LogClassLoadingCauseFor");
+  }
+
   apply_debugger_ergo();
 
   if (log_is_enabled(Info, arguments)) {

src/hotspot/share/runtime/globals.hpp

@@ -933,6 +933,11 @@ const int ObjectAlignmentInBytes = 8;
   product(bool, TraceCompilerThreads, false, DIAGNOSTIC,                    \
              "Trace creation and removal of compiler threads")              \
                                                                             \
+  product(ccstr, LogClassLoadingCauseFor, nullptr,                          \
+          "Apply -Xlog:class+load+cause* to classes whose fully "           \
+          "qualified name contains this string (\"*\" matches "             \
+          "any class).")                                                    \
+                                                                            \
   develop(bool, InjectCompilerCreationFailure, false,                       \
           "Inject thread creation failures for "                            \
           "UseDynamicNumberOfCompilerThreads")                              \

test/hotspot/jtreg/runtime/logging/ClassLoadUnloadTest.java

@@ -118,5 +118,22 @@ public static void main(String... args) throws Exception {
         pb = exec("-Xlog:class+loader+data=trace");
         checkFor("[class,loader,data]", "create loader data");
 
+        //  -Xlog:class+load+cause
+        pb = exec("-Xlog:class+load+cause");
+        checkAbsent("[class,load,cause]");
+        checkFor("class load cause logging will not produce output without LogClassLoadingCauseFor");
+
+        //  -Xlog:class+load+cause -XX:LogClassLoadingCauseFor=java.lang.StringCoding
+        pb = exec("-Xlog:class+load+cause", "-XX:LogClassLoadingCauseFor=java.lang.StringCoding");
+        checkFor("[class,load,cause]", "Java stack when loading java.lang.StringCoding:");
+
+        //  -Xlog:class+load+cause -XX:LogClassLoadingCauseFor=java.lang.StringCoding
+        pb = exec("-Xlog:class+load+cause+native", "-XX:LogClassLoadingCauseFor=java.lang.StringCoding");
+        checkFor("[class,load,cause,native]", "Native stack when loading java.lang.StringCoding:");
+
+        //  -Xlog:class+load+cause* -XX:LogClassLoadingCauseFor=java.lang.StringCoding
+        pb = exec("-Xlog:class+load+cause*", "-XX:LogClassLoadingCauseFor=java.lang.StringCoding");
+        checkFor("[class,load,cause] Java stack when loading java.lang.StringCoding:");
+        checkFor("[class,load,cause,native] Native stack when loading java.lang.StringCoding:");
     }
 }