8142976: Reimplement TraceClassInitialization with Unified Logging

TraceClassInitialization logging reimplemented with Unified Logging.

Reviewed-by: coleenp, hseigel

hotspot/src/share/vm/classfile/verifier.cpp

@@ -48,6 +48,7 @@
 #include "runtime/thread.hpp"
 #include "services/threadService.hpp"
 #include "utilities/bytes.hpp"
+#include "logging/log.hpp"
 
 #define NOFAILOVER_MAJOR_VERSION                       51
 #define NONZERO_PADDING_BYTES_IN_SWITCH_MAJOR_VERSION  51
@@ -111,6 +112,18 @@ void Verifier::trace_class_resolution(Klass* resolve_class, InstanceKlass* verif
   }
 }
 
+// Prints the end-verification message to the appropriate output.
+void Verifier::log_end_verification(outputStream* st, const char* klassName, Symbol* exception_name, TRAPS) {
+  if (HAS_PENDING_EXCEPTION) {
+    st->print("Verification for %s has", klassName);
+    st->print_cr(" exception pending %s ",
+                 PENDING_EXCEPTION->klass()->external_name());
+  } else if (exception_name != NULL) {
+    st->print_cr("Verification for %s failed", klassName);
+  }
+  st->print_cr("End class verification for: %s", klassName);
+}
+
 bool Verifier::verify(instanceKlassHandle klass, Verifier::Mode mode, bool should_verify_class, TRAPS) {
   HandleMark hm;
   ResourceMark rm(THREAD);
@@ -155,9 +168,7 @@ bool Verifier::verify(instanceKlassHandle klass, Verifier::Mode mode, bool shoul
   bool can_failover = FailOverToOldVerifier &&
      klass->major_version() < NOFAILOVER_MAJOR_VERSION;
 
-  if (TraceClassInitialization) {
+  log_info(classinit)("Start class verification for: %s", klassName);
-    tty->print_cr("Start class verification for: %s", klassName);
-  }
   if (klass->major_version() >= STACKMAP_ATTRIBUTE_MAJOR_VERSION) {
     ClassVerifier split_verifier(klass, THREAD);
     split_verifier.verify_class(THREAD);
@@ -165,10 +176,10 @@ bool Verifier::verify(instanceKlassHandle klass, Verifier::Mode mode, bool shoul
     if (can_failover && !HAS_PENDING_EXCEPTION &&
         (exception_name == vmSymbols::java_lang_VerifyError() ||
          exception_name == vmSymbols::java_lang_ClassFormatError())) {
-      if (TraceClassInitialization || VerboseVerification) {
+      if (VerboseVerification) {
-        tty->print_cr(
+        tty->print_cr("Fail over class verification to old verifier for: %s", klassName);
-          "Fail over class verification to old verifier for: %s", klassName);
       }
+      log_info(classinit)("Fail over class verification to old verifier for: %s", klassName);
       exception_name = inference_verify(
         klass, message_buffer, message_buffer_len, THREAD);
     }
@@ -180,15 +191,11 @@ bool Verifier::verify(instanceKlassHandle klass, Verifier::Mode mode, bool shoul
         klass, message_buffer, message_buffer_len, THREAD);
   }
 
-  if (TraceClassInitialization || VerboseVerification) {
+  if (log_is_enabled(Info, classinit)){
-    if (HAS_PENDING_EXCEPTION) {
+    log_end_verification(LogHandle(classinit)::info_stream(), klassName, exception_name, THREAD);
-      tty->print("Verification for %s has", klassName);
-      tty->print_cr(" exception pending %s ",
-        PENDING_EXCEPTION->klass()->external_name());
-    } else if (exception_name != NULL) {
-      tty->print_cr("Verification for %s failed", klassName);
   }
-    tty->print_cr("End class verification for: %s", klassName);
+  if (VerboseVerification){
+    log_end_verification(tty, klassName, exception_name, THREAD);
   }
 
   if (HAS_PENDING_EXCEPTION) {
@@ -598,11 +605,14 @@ void ClassVerifier::verify_class(TRAPS) {
     verify_method(methodHandle(THREAD, m), CHECK_VERIFY(this));
   }
 
-  if (VerboseVerification || TraceClassInitialization) {
+  if (was_recursively_verified()){
-    if (was_recursively_verified())
+    if (VerboseVerification){
       tty->print_cr("Recursive verification detected for: %s",
                     _klass->external_name());
     }
+    log_info(classinit)("Recursive verification detected for: %s",
+                        _klass->external_name());
+  }
 }
 
 void ClassVerifier::verify_method(const methodHandle& m, TRAPS) {

hotspot/src/share/vm/classfile/verifier.hpp

@@ -50,6 +50,7 @@ class Verifier : AllStatic {
    * Otherwise, no exception is thrown and the return indicates the
    * error.
    */
+  static void log_end_verification(outputStream* st, const char* klassName, Symbol* exception_name, TRAPS);
   static bool verify(instanceKlassHandle klass, Mode mode, bool should_verify_class, TRAPS);
 
   // Return false if the class is loaded by the bootstrap loader,

hotspot/src/share/vm/logging/logTag.hpp

@@ -31,6 +31,7 @@
 // (The tags 'all', 'disable' and 'help' are special tags that can
 // not be used in log calls, and should not be listed below.)
 #define LOG_TAG_LIST \
+  LOG_TAG(classinit) \
   LOG_TAG(defaultmethods) \
   LOG_TAG(logging) \
   LOG_TAG(safepoint)

hotspot/src/share/vm/oops/instanceKlass.cpp

@@ -62,6 +62,7 @@
 #include "services/threadService.hpp"
 #include "utilities/dtrace.hpp"
 #include "utilities/macros.hpp"
+#include "logging/log.hpp"
 #ifdef COMPILER1
 #include "c1/c1_Compiler.hpp"
 #endif
@@ -492,9 +493,9 @@ void InstanceKlass::eager_initialize_impl(instanceKlassHandle this_k) {
     this_k->set_init_state (fully_initialized);
     this_k->fence_and_clear_init_lock();
     // trace
-    if (TraceClassInitialization) {
+    if (log_is_enabled(Info, classinit)) {
       ResourceMark rm(THREAD);
-      tty->print_cr("[Initialized %s without side effects]", this_k->external_name());
+      log_info(classinit)("[Initialized %s without side effects]", this_k->external_name());
     }
   }
 }
@@ -1127,10 +1128,12 @@ void InstanceKlass::call_class_initializer_impl(instanceKlassHandle this_k, TRAP
 
   methodHandle h_method(THREAD, this_k->class_initializer());
   assert(!this_k->is_initialized(), "we cannot initialize twice");
-  if (TraceClassInitialization) {
+  if (log_is_enabled(Info, classinit)) {
-    tty->print("%d Initializing ", call_class_initializer_impl_counter++);
+    ResourceMark rm;
-    this_k->name()->print_value();
+    outputStream* log = LogHandle(classinit)::info_stream();
-    tty->print_cr("%s (" INTPTR_FORMAT ")", h_method() == NULL ? "(no method)" : "", p2i(this_k()));
+    log->print("%d Initializing ", call_class_initializer_impl_counter++);
+    this_k->name()->print_value_on(log);
+    log->print_cr("%s (" INTPTR_FORMAT ")", h_method() == NULL ? "(no method)" : "", p2i(this_k()));
   }
   if (h_method() != NULL) {
     JavaCallArguments args; // No arguments

hotspot/src/share/vm/runtime/globals.hpp

@@ -1463,9 +1463,6 @@ public:
   develop(bool, TraceBytecodes, false,                                      \
           "Trace bytecode execution")                                       \
                                                                             \
-  develop(bool, TraceClassInitialization, false,                            \
-          "Trace class initialization")                                     \
-                                                                            \
   product(bool, TraceExceptions, false,                                     \
           "Trace exceptions")                                               \
                                                                             \

hotspot/test/runtime/logging/BadMap50.jasm

@@ -0,0 +1,156 @@
+/*
+ * Copyright (c) 2015, 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.
+ */
+
+/*
+ * This class should throw VerifyError because the StackMap for bytecode
+ * index 45 is incorrect. The stack maps for bytecode indexes 45 and 49 are
+ * incompatible because 45 doesn't supply enough locals to satisfy 49.
+ *
+ * The astore_2 bytecode at bytecode index 45 changes the type state,
+ * preventing the stackmap mismatch.  But, if the incoming type state is used,
+ * as required by JVM Spec 8, then the verifier will detected the stackmap
+ * mismatch, and throw VerifyError.
+ */
+
+super public class BadMap50
+    version 50:0
+{
+
+
+public Method "<init>":"()V"
+    stack 1 locals 1
+{
+        aload_0;
+        invokespecial    Method java/lang/Object."<init>":"()V";
+        return;
+}
+
+public static Method main:"([Ljava/lang/String;)V"
+    throws java/lang/Throwable
+    stack 0 locals 1
+{
+        return;
+}
+
+public static Method foo:"()V"
+    stack 3 locals 5
+{
+        iconst_0;
+        ifne    L5;
+        nop;
+        try t7;
+    L5:    stack_frame_type full;
+        aconst_null;
+        astore_0;
+        iconst_3;
+        istore_1;
+        try t0;
+        aconst_null;
+        astore_0;
+        endtry t0;
+        goto    L19;
+        catch t0 java/io/IOException;
+        stack_frame_type full;
+        locals_map class java/lang/Object, int;
+        stack_map class java/io/IOException;
+        astore_2;
+        aconst_null;
+        astore_0;
+        iconst_2;
+        istore_1;
+        try t1;
+    L19:    stack_frame_type full;
+        locals_map class java/lang/Object, int;
+        iconst_0;
+        istore_2;
+        endtry t1;
+        iload_1;
+        ifeq    L37;
+        nop;
+        goto    L37;
+        catch t1 #0;
+        catch t2 #0;
+        try t2;
+        stack_frame_type full;
+        locals_map class java/lang/Object, int;
+        stack_map class java/lang/Throwable;
+astore_3;
+iconst_2;
+istore_2;
+        endtry t2;
+        iload_1;
+        ifeq    L35;
+        nop;
+    L35:    stack_frame_type full;
+        locals_map class java/lang/Object, int, bogus, class java/lang/Throwable;
+aload_3;
+        athrow;
+        try t3, t4;
+    L37:    stack_frame_type full;
+        locals_map class java/lang/Object, int, int;
+        iload_2;
+        ifeq    L42;
+        nop;
+        endtry t3, t4;
+    L42:    stack_frame_type full;
+        locals_map class java/lang/Object, int, int;
+        goto    L54;
+        catch t3 java/lang/Exception;
+        try t5;
+        stack_frame_type full;
+        locals_map class java/lang/Object, int;
+        stack_map class java/lang/Exception;
+        // astore_2;                  // astore_2, at bci 45, that changes the type state.
+// pop;
+iconst_1;
+        istore_2;                  // astore_2, at bci 45, that changes the type state.
+        endtry t5;
+        goto    L54;
+        catch t4 #0;
+        catch t5 #0;
+        catch t6 #0;
+        try t6;
+      stack_frame_type full;
+      locals_map class java/lang/Object, int, int;
+      stack_map class java/lang/Throwable;
+// astore    3;
+ istore_1;
+        endtry t6;
+// aload    3;
+//         athrow;
+    L54:    stack_frame_type full;
+        locals_map class java/lang/Object, int, int;
+        goto    L57;
+    L57:    stack_frame_type full;
+        locals_map class java/lang/Object, int, int;
+        nop;
+        endtry t7;
+        return;
+        catch t7 #0;
+        stack_frame_type full;
+        stack_map class java/lang/Throwable;
+        nop;
+        athrow;
+}
+
+} // end Class BadMap50

hotspot/test/runtime/logging/ClassInitializationTest.java

@@ -0,0 +1,62 @@
+/*
+ * Copyright (c) 2015, 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 ClassInitializationTest
+ * @bug 8142976
+ * @library /testlibrary
+ * @compile BadMap50.jasm
+ * @run driver ClassInitializationTest
+ */
+
+import jdk.test.lib.*;
+
+public class ClassInitializationTest {
+
+    public static void main(String... args) throws Exception {
+
+        // (1)
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:classinit=info", "-Xverify:all", "-Xmx64m", "BadMap50");
+        OutputAnalyzer out = new OutputAnalyzer(pb.start());
+        out.shouldContain("Start class verification for:");
+        out.shouldContain("End class verification for:");
+        out.shouldContain("Initializing");
+        out.shouldContain("Verification for BadMap50 failed");
+        out.shouldContain("Fail over class verification to old verifier for: BadMap50");
+
+        // (2)
+        if (Platform.isDebugBuild()) {
+          pb = ProcessTools.createJavaProcessBuilder("-Xlog:classinit=info", "-Xverify:all", "-XX:+EagerInitialization", "-Xmx64m", "-version");
+          out = new OutputAnalyzer(pb.start());
+          out.shouldContain("[Initialized").shouldContain("without side effects]");
+          out.shouldHaveExitValue(0);
+        }
+        // (3) Ensure that VerboseVerification still triggers appropriate messages.
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+UnlockDiagnosticVMOptions", "-XX:+VerboseVerification", "-Xverify:all", "-Xmx64m", "BadMap50");
+        out = new OutputAnalyzer(pb.start());
+        out.shouldContain("End class verification for:");
+        out.shouldContain("Verification for BadMap50 failed");
+        out.shouldContain("Fail over class verification to old verifier for: BadMap50");
+    }
+}