8213397: Stack dump should show more clearly when a thread is blocked on a class initialization monitor

Reviewed-by: rehn, coleenp

src/hotspot/share/oops/instanceKlass.cpp

@@ -918,25 +918,28 @@ void InstanceKlass::initialize_impl(TRAPS) {
 
   bool wait = false;
 
+  assert(THREAD->is_Java_thread(), "non-JavaThread in initialize_impl");
+  JavaThread* jt = (JavaThread*)THREAD;
+
   // refer to the JVM book page 47 for description of steps
   // Step 1
   {
     Handle h_init_lock(THREAD, init_lock());
     ObjectLocker ol(h_init_lock, THREAD, h_init_lock() != NULL);
 
-    Thread *self = THREAD; // it's passed the current thread
-
     // Step 2
     // If we were to use wait() instead of waitInterruptibly() then
     // we might end up throwing IE from link/symbol resolution sites
     // that aren't expected to throw.  This would wreak havoc.  See 6320309.
-    while(is_being_initialized() && !is_reentrant_initialization(self)) {
-        wait = true;
-      ol.waitUninterruptibly(CHECK);
+    while (is_being_initialized() && !is_reentrant_initialization(jt)) {
+      wait = true;
+      jt->set_class_to_be_initialized(this);
+      ol.waitUninterruptibly(jt);
+      jt->set_class_to_be_initialized(NULL);
     }
 
     // Step 3
-    if (is_being_initialized() && is_reentrant_initialization(self)) {
+    if (is_being_initialized() && is_reentrant_initialization(jt)) {
       DTRACE_CLASSINIT_PROBE_WAIT(recursive, -1, wait);
       return;
     }
@@ -966,7 +969,7 @@ void InstanceKlass::initialize_impl(TRAPS) {
 
     // Step 6
     set_init_state(being_initialized);
-    set_init_thread(self);
+    set_init_thread(jt);
   }
 
   // Step 7
@@ -1006,8 +1009,6 @@ void InstanceKlass::initialize_impl(TRAPS) {
 
   // Step 8
   {
-    assert(THREAD->is_Java_thread(), "non-JavaThread in initialize_impl");
-    JavaThread* jt = (JavaThread*)THREAD;
     DTRACE_CLASSINIT_PROBE_WAIT(clinit, -1, wait);
     // Timer includes any side effects of class initialization (resolution,
     // etc), but not recursive entry into call_class_initializer().
@@ -1033,14 +1034,14 @@ void InstanceKlass::initialize_impl(TRAPS) {
     CLEAR_PENDING_EXCEPTION;
     // JVMTI has already reported the pending exception
     // JVMTI internal flag reset is needed in order to report ExceptionInInitializerError
-    JvmtiExport::clear_detected_exception((JavaThread*)THREAD);
+    JvmtiExport::clear_detected_exception(jt);
     {
       EXCEPTION_MARK;
       set_initialization_state_and_notify(initialization_error, THREAD);
       CLEAR_PENDING_EXCEPTION;   // ignore any exception thrown, class initialization error is thrown below
       // JVMTI has already reported the pending exception
       // JVMTI internal flag reset is needed in order to report ExceptionInInitializerError
-      JvmtiExport::clear_detected_exception((JavaThread*)THREAD);
+      JvmtiExport::clear_detected_exception(jt);
     }
     DTRACE_CLASSINIT_PROBE_WAIT(error, -1, wait);
     if (e->is_a(SystemDictionary::Error_klass())) {

src/hotspot/share/runtime/thread.cpp

@@ -1671,6 +1671,8 @@ void JavaThread::initialize() {
     SafepointMechanism::initialize_header(this);
   }
 
+  _class_to_be_initialized = NULL;
+
   pd_initialize();
 }
 

src/hotspot/share/runtime/thread.hpp

@@ -2088,6 +2088,16 @@ class JavaThread: public Thread {
   bool is_attaching_via_jni() const { return _jni_attach_state == _attaching_via_jni; }
   bool has_attached_via_jni() const { return is_attaching_via_jni() || _jni_attach_state == _attached_via_jni; }
   inline void set_done_attaching_via_jni();
+
+  // Stack dump assistance:
+  // Track the class we want to initialize but for which we have to wait
+  // on its init_lock() because it is already being initialized.
+  void set_class_to_be_initialized(InstanceKlass* k);
+  InstanceKlass* class_to_be_initialized() const;
+
+private:
+  InstanceKlass* _class_to_be_initialized;
+
 };
 
 // Inline implementation of JavaThread::current

src/hotspot/share/runtime/thread.inline.hpp

@@ -233,4 +233,16 @@ inline void JavaThread::set_terminated_value() {
   OrderAccess::release_store((volatile jint *) &_terminated, (jint) _thread_terminated);
 }
 
+// Allow tracking of class initialization monitor use
+inline void JavaThread::set_class_to_be_initialized(InstanceKlass* k) {
+  assert((k == NULL && _class_to_be_initialized != NULL) ||
+         (k != NULL && _class_to_be_initialized == NULL), "incorrect usage");
+  assert(this == Thread::current(), "Only the current thread can set this field");
+  _class_to_be_initialized = k;
+}
+
+inline InstanceKlass* JavaThread::class_to_be_initialized() const {
+  return _class_to_be_initialized;
+}
+
 #endif // SHARE_RUNTIME_THREAD_INLINE_HPP

src/hotspot/share/runtime/vframe.cpp

@@ -190,6 +190,14 @@ void javaVFrame::print_lock_info_on(outputStream* st, int frame_count) {
       Klass* k = obj->klass();
       st->print_cr("\t- %s <" INTPTR_FORMAT "> (a %s)", "parking to wait for ", p2i(obj), k->external_name());
     }
+    else if (thread()->osthread()->get_state() == OBJECT_WAIT) {
+      // We are waiting on an Object monitor but Object.wait() isn't the
+      // top-frame, so we should be waiting on a Class initialization monitor.
+      InstanceKlass* k = thread()->class_to_be_initialized();
+      if (k != NULL) {
+        st->print_cr("\t- waiting on the Class initialization monitor for %s", k->external_name());
+      }
+    }
   }
 
   // Print out all monitors that we have locked, or are trying to lock,

test/hotspot/jtreg/runtime/Thread/TestThreadDumpClassInitMonitor.java

@@ -0,0 +1,195 @@
+/*
+ * Copyright (c) 2019, 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test
+ * @bug     8213397
+ * @summary Check that the thread dump shows when a thread is blocked
+ *          on a class initialization monitor
+ *
+ * @library /test/lib
+ * @run main/othervm TestThreadDumpClassInitMonitor
+ */
+
+import jdk.test.lib.process.OutputAnalyzer;
+import jdk.test.lib.JDKToolFinder;
+
+import java.io.IOException;
+import java.util.List;
+
+public class TestThreadDumpClassInitMonitor {
+    // jstack tends to be closely bound to the VM that we are running
+    // so use getTestJDKTool() instead of getCompileJDKTool() or even
+    // getJDKTool() which can fall back to "compile.jdk".
+    final static String JSTACK = JDKToolFinder.getTestJDKTool("jstack");
+    final static String PID = "" + ProcessHandle.current().pid();
+
+    final static Thread current = Thread.currentThread();
+
+    /*
+     * This is the output we're looking for:
+     *
+     * "TestThread" #22 prio=5 os_prio=0 cpu=1.19ms elapsed=0.80s tid=0x00007f8f9405d800 nid=0x568b in Object.wait()  [0x00007f8fd94d0000]
+     *   java.lang.Thread.State: RUNNABLE
+     * Thread: 0x00007f8f9405d800  [0x568b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
+     *   JavaThread state: _thread_blocked
+     *         at TestThreadDumpClassInitMonitor$Target$1.run(TestThreadDumpClassInitMonitor.java:69)
+     *         - waiting on the Class initialization monitor for TestThreadDumpClassInitMonitor$Target
+     *
+     */
+    final static String TEST_THREAD = "TestThread";
+    final static String TEST_THREAD_ENTRY = "\"" + TEST_THREAD;
+    final static String IN_OBJECT_WAIT = "in Object.wait()";
+    final static String THREAD_STATE = "java.lang.Thread.State: RUNNABLE";
+    final static String THREAD_INFO = "Thread:"; // the details are not important
+    final static String JAVATHREAD_STATE = "JavaThread state: _thread_blocked";
+    final static String CURRENT_METHOD = "at TestThreadDumpClassInitMonitor$Target$1.run";
+    final static String WAIT_INFO = "- waiting on the Class initialization monitor for TestThreadDumpClassInitMonitor$Target";
+
+    volatile static boolean ready = false;
+
+    static List<String> stackDump;  // jstack output as lines
+
+    static class Target {
+
+        static int field;
+
+        // The main thread will initialize this class and so
+        // execute the actual test logic here.
+        static {
+            if (Thread.currentThread() != current) {
+                throw new Error("Initialization logic error");
+            }
+            System.out.println("Initializing Target class in main thread");
+
+            Thread t  = new Thread() {
+                    public void run() {
+                        System.out.println("Test thread about to access Target");
+                        ready = true; // tell main thread we're close
+                        // This will block until the main thread completes
+                        // static initialization of target
+                        Target.field = 42;
+                        System.out.println("Test thread done");
+                    }
+                };
+            t.setName(TEST_THREAD);
+            t.start();
+
+            // We want to run jstack once the test thread is blocked but
+            // there's no programmatic way to detect that. So we check the flag
+            // that will be set just before it should block, then by the time
+            // we can exec jstack it should be ready.
+            try {
+                while (!ready) {
+                    Thread.sleep(200);
+                }
+            }
+            catch (InterruptedException ie) {
+                throw new Error("Shouldn't happen");
+            }
+
+            // Now run jstack
+            try {
+                ProcessBuilder pb = new ProcessBuilder(JSTACK, PID);
+                OutputAnalyzer output = new OutputAnalyzer(pb.start());
+                output.shouldHaveExitValue(0);
+                stackDump = output.asLines();
+            }
+            catch (IOException ioe) {
+                throw new Error("Launching jstack failed", ioe);
+            }
+        }
+    }
+
+
+    public static void main(String[] args) throws Throwable {
+        // Implicitly run the main test logic
+        Target.field = 21;
+
+        // Now check the output of jstack
+        try {
+            int foundLines = 0;
+            parseStack: for (String line : stackDump) {
+                switch(foundLines) {
+                case 0: {
+                    if (!line.startsWith(TEST_THREAD_ENTRY)) {
+                        continue;
+                    }
+                    foundLines++;
+                    if (!line.contains(IN_OBJECT_WAIT)) {
+                        throw new Error("Unexpected initial stack line: " + line);
+                    }
+                    continue;
+                }
+                case 1: {
+                    if (!line.trim().equals(THREAD_STATE)) {
+                        throw new Error("Unexpected thread state line: " + line);
+                    }
+                    foundLines++;
+                    continue;
+                }
+                case 2: {
+                    if (!line.startsWith(THREAD_INFO)) {
+                        throw new Error("Unexpected thread info line: " + line);
+                    }
+                    foundLines++;
+                    continue;
+                }
+                case 3: {
+                    if (!line.trim().equals(JAVATHREAD_STATE)) {
+                        throw new Error("Unexpected JavaThread state line: " + line);
+                    }
+                    foundLines++;
+                    continue;
+                }
+                case 4: {
+                    if (!line.trim().startsWith(CURRENT_METHOD)) {
+                        throw new Error("Unexpected current method line: " + line);
+                    }
+                    foundLines++;
+                    continue;
+                }
+                case 5: {
+                    if (!line.trim().equals(WAIT_INFO)) {
+                        throw new Error("Unexpected monitor information line: " + line);
+                    }
+                    break parseStack;
+                }
+                default: throw new Error("Logic error in case statement");
+                }
+            }
+
+            if (foundLines == 0) {
+                throw new Error("Unexpected stack content - did not find line starting with "
+                                + TEST_THREAD_ENTRY);
+            }
+        }
+        catch (Error e) {
+            // Dump the full stack trace on error so we can check the content
+            for (String line : stackDump) {
+                System.out.println(line);
+            }
+            throw e;
+        }
+    }
+}