changeset 10284:66a81854aa5d

8149383: Convert TraceBiasedLocking to Unified Logging Summary: The former -XX:+TraceBiasedLocking flag has been converted to the UL option -Xlog:biasedlocking=info and =trace, with the old option being aliased. Reviewed-by: dholmes, dcubed
author rprotacio
date Thu, 18 Feb 2016 17:10:48 -0500
parents dcfd41c9aee8
children 8c94907406e1
files src/share/vm/logging/logTag.hpp src/share/vm/runtime/arguments.cpp src/share/vm/runtime/biasedLocking.cpp src/share/vm/runtime/globals.hpp src/share/vm/runtime/thread.cpp test/runtime/logging/BiasedLockingTest.java
diffstat 6 files changed, 153 insertions(+), 60 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/logging/logTag.hpp	Thu Feb 18 14:56:53 2016 +0300
+++ b/src/share/vm/logging/logTag.hpp	Thu Feb 18 17:10:48 2016 -0500
@@ -34,6 +34,7 @@
   LOG_TAG(alloc) \
   LOG_TAG(age) \
   LOG_TAG(barrier) \
+  LOG_TAG(biasedlocking) \
   LOG_TAG(bot) \
   LOG_TAG(census) \
   LOG_TAG(classhisto) \
--- a/src/share/vm/runtime/arguments.cpp	Thu Feb 18 14:56:53 2016 +0300
+++ b/src/share/vm/runtime/arguments.cpp	Thu Feb 18 17:10:48 2016 -0500
@@ -409,6 +409,7 @@
   { "TraceClassResolution",      LogLevel::Info,  true,  LogTag::_classresolve },
   { "TraceExceptions",           LogLevel::Info,  true,  LogTag::_exceptions },
   { "TraceMonitorInflation",     LogLevel::Debug, true,  LogTag::_monitorinflation },
+  { "TraceBiasedLocking",        LogLevel::Info,  true,  LogTag::_biasedlocking },
   { NULL,                        LogLevel::Off,   false, LogTag::__NO_TAG }
 };
 
--- a/src/share/vm/runtime/biasedLocking.cpp	Thu Feb 18 14:56:53 2016 +0300
+++ b/src/share/vm/runtime/biasedLocking.cpp	Thu Feb 18 17:10:48 2016 -0500
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2005, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2005, 2016, 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,6 +23,8 @@
  */
 
 #include "precompiled.hpp"
+#include "logging/log.hpp"
+#include "memory/resourceArea.hpp"
 #include "oops/klass.inline.hpp"
 #include "oops/markOop.hpp"
 #include "oops/oop.inline.hpp"
@@ -60,9 +62,7 @@
     // Indicate that future instances should enable it as well
     _biased_locking_enabled = true;
 
-    if (TraceBiasedLocking) {
-      tty->print_cr("Biased locking enabled");
-    }
+    log_info(biasedlocking)("Biased locking enabled");
   }
 
   bool allow_nested_vm_operations() const        { return false; }
@@ -144,14 +144,14 @@
   return info;
 }
 
-
 static BiasedLocking::Condition revoke_bias(oop obj, bool allow_rebias, bool is_bulk, JavaThread* requesting_thread) {
   markOop mark = obj->mark();
   if (!mark->has_bias_pattern()) {
-    if (TraceBiasedLocking) {
+    if (log_is_enabled(Info, biasedlocking)) {
       ResourceMark rm;
-      tty->print_cr("  (Skipping revocation of object of type %s because it's no longer biased)",
-                    obj->klass()->external_name());
+      log_info(biasedlocking)("  (Skipping revocation of object of type %s "
+                              "because it's no longer biased)",
+                              obj->klass()->external_name());
     }
     return BiasedLocking::NOT_BIASED;
   }
@@ -160,10 +160,29 @@
   markOop   biased_prototype = markOopDesc::biased_locking_prototype()->set_age(age);
   markOop unbiased_prototype = markOopDesc::prototype()->set_age(age);
 
-  if (TraceBiasedLocking && (Verbose || !is_bulk)) {
+  // Log at "info" level if not bulk, else "trace" level
+  if (!is_bulk) {
     ResourceMark rm;
-    tty->print_cr("Revoking bias of object " INTPTR_FORMAT " , mark " INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT " , allow rebias %d , requesting thread " INTPTR_FORMAT,
-                  p2i((void *)obj), (intptr_t) mark, obj->klass()->external_name(), (intptr_t) obj->klass()->prototype_header(), (allow_rebias ? 1 : 0), (intptr_t) requesting_thread);
+    log_info(biasedlocking)("Revoking bias of object " INTPTR_FORMAT " , mark "
+                            INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT
+                            " , allow rebias %d , requesting thread " INTPTR_FORMAT,
+                            p2i((void *)obj),
+                            (intptr_t) mark,
+                            obj->klass()->external_name(),
+                            (intptr_t) obj->klass()->prototype_header(),
+                            (allow_rebias ? 1 : 0),
+                            (intptr_t) requesting_thread);
+  } else {
+    ResourceMark rm;
+    log_trace(biasedlocking)("Revoking bias of object " INTPTR_FORMAT " , mark "
+                             INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT
+                             " , allow rebias %d , requesting thread " INTPTR_FORMAT,
+                             p2i((void *)obj),
+                             (intptr_t) mark,
+                             obj->klass()->external_name(),
+                             (intptr_t) obj->klass()->prototype_header(),
+                             (allow_rebias ? 1 : 0),
+                             (intptr_t) requesting_thread);
   }
 
   JavaThread* biased_thread = mark->biased_locker();
@@ -174,8 +193,11 @@
     if (!allow_rebias) {
       obj->set_mark(unbiased_prototype);
     }
-    if (TraceBiasedLocking && (Verbose || !is_bulk)) {
-      tty->print_cr("  Revoked bias of anonymously-biased object");
+    // Log at "info" level if not bulk, else "trace" level
+    if (!is_bulk) {
+      log_info(biasedlocking)("  Revoked bias of anonymously-biased object");
+    } else {
+      log_trace(biasedlocking)("  Revoked bias of anonymously-biased object");
     }
     return BiasedLocking::BIAS_REVOKED;
   }
@@ -198,8 +220,11 @@
     } else {
       obj->set_mark(unbiased_prototype);
     }
-    if (TraceBiasedLocking && (Verbose || !is_bulk)) {
-      tty->print_cr("  Revoked bias of object biased toward dead thread");
+    // Log at "info" level if not bulk, else "trace" level
+    if (!is_bulk) {
+      log_info(biasedlocking)("  Revoked bias of object biased toward dead thread");
+    } else {
+      log_trace(biasedlocking)("  Revoked bias of object biased toward dead thread");
     }
     return BiasedLocking::BIAS_REVOKED;
   }
@@ -214,21 +239,17 @@
   for (int i = 0; i < cached_monitor_info->length(); i++) {
     MonitorInfo* mon_info = cached_monitor_info->at(i);
     if (mon_info->owner() == obj) {
-      if (TraceBiasedLocking && Verbose) {
-        tty->print_cr("   mon_info->owner (" PTR_FORMAT ") == obj (" PTR_FORMAT ")",
-                      p2i((void *) mon_info->owner()),
-                      p2i((void *) obj));
-      }
+      log_trace(biasedlocking)("   mon_info->owner (" PTR_FORMAT ") == obj (" PTR_FORMAT ")",
+                               p2i((void *) mon_info->owner()),
+                               p2i((void *) obj));
       // Assume recursive case and fix up highest lock later
       markOop mark = markOopDesc::encode((BasicLock*) NULL);
       highest_lock = mon_info->lock();
       highest_lock->set_displaced_header(mark);
     } else {
-      if (TraceBiasedLocking && Verbose) {
-        tty->print_cr("   mon_info->owner (" PTR_FORMAT ") != obj (" PTR_FORMAT ")",
-                      p2i((void *) mon_info->owner()),
-                      p2i((void *) obj));
-      }
+      log_trace(biasedlocking)("   mon_info->owner (" PTR_FORMAT ") != obj (" PTR_FORMAT ")",
+                               p2i((void *) mon_info->owner()),
+                               p2i((void *) obj));
     }
   }
   if (highest_lock != NULL) {
@@ -240,12 +261,18 @@
     // ordering (e.g. ppc).
     obj->release_set_mark(markOopDesc::encode(highest_lock));
     assert(!obj->mark()->has_bias_pattern(), "illegal mark state: stack lock used bias bit");
-    if (TraceBiasedLocking && (Verbose || !is_bulk)) {
-      tty->print_cr("  Revoked bias of currently-locked object");
+    // Log at "info" level if not bulk, else "trace" level
+    if (!is_bulk) {
+      log_info(biasedlocking)("  Revoked bias of currently-locked object");
+    } else {
+      log_trace(biasedlocking)("  Revoked bias of currently-locked object");
     }
   } else {
-    if (TraceBiasedLocking && (Verbose || !is_bulk)) {
-      tty->print_cr("  Revoked bias of currently-unlocked object");
+    // Log at "info" level if not bulk, else "trace" level
+    if (!is_bulk) {
+      log_info(biasedlocking)("  Revoked bias of currently-unlocked object");
+    } else {
+      log_trace(biasedlocking)("  Revoked bias of currently-unlocked object");
     }
     if (allow_rebias) {
       obj->set_mark(biased_prototype);
@@ -326,12 +353,12 @@
                                                                    JavaThread* requesting_thread) {
   assert(SafepointSynchronize::is_at_safepoint(), "must be done at safepoint");
 
-  if (TraceBiasedLocking) {
-    tty->print_cr("* Beginning bulk revocation (kind == %s) because of object "
-                  INTPTR_FORMAT " , mark " INTPTR_FORMAT " , type %s",
-                  (bulk_rebias ? "rebias" : "revoke"),
-                  p2i((void *) o), (intptr_t) o->mark(), o->klass()->external_name());
-  }
+  log_info(biasedlocking)("* Beginning bulk revocation (kind == %s) because of object "
+                          INTPTR_FORMAT " , mark " INTPTR_FORMAT " , type %s",
+                          (bulk_rebias ? "rebias" : "revoke"),
+                          p2i((void *) o),
+                          (intptr_t) o->mark(),
+                          o->klass()->external_name());
 
   jlong cur_time = os::javaTimeMillis();
   o->klass()->set_last_biased_lock_bulk_revocation_time(cur_time);
@@ -377,9 +404,9 @@
     // adjust the header of the given object to revoke its bias.
     revoke_bias(o, attempt_rebias_of_object && klass->prototype_header()->has_bias_pattern(), true, requesting_thread);
   } else {
-    if (TraceBiasedLocking) {
+    if (log_is_enabled(Info, biasedlocking)) {
       ResourceMark rm;
-      tty->print_cr("* Disabling biased locking for type %s", klass->external_name());
+      log_info(biasedlocking)("* Disabling biased locking for type %s", klass->external_name());
     }
 
     // Disable biased locking for this data type. Not only will this
@@ -407,9 +434,7 @@
     revoke_bias(o, false, true, requesting_thread);
   }
 
-  if (TraceBiasedLocking) {
-    tty->print_cr("* Ending bulk revocation");
-  }
+  log_info(biasedlocking)("* Ending bulk revocation");
 
   BiasedLocking::Condition status_code = BiasedLocking::BIAS_REVOKED;
 
@@ -420,9 +445,7 @@
                                            klass->prototype_header()->bias_epoch());
     o->set_mark(new_mark);
     status_code = BiasedLocking::BIAS_REVOKED_AND_REBIASED;
-    if (TraceBiasedLocking) {
-      tty->print_cr("  Rebiased object toward thread " INTPTR_FORMAT, (intptr_t) requesting_thread);
-    }
+    log_info(biasedlocking)("  Rebiased object toward thread " INTPTR_FORMAT, (intptr_t) requesting_thread);
   }
 
   assert(!o->mark()->has_bias_pattern() ||
@@ -485,16 +508,12 @@
 
   virtual void doit() {
     if (_obj != NULL) {
-      if (TraceBiasedLocking) {
-        tty->print_cr("Revoking bias with potentially per-thread safepoint:");
-      }
+      log_info(biasedlocking)("Revoking bias with potentially per-thread safepoint:");
       _status_code = revoke_bias((*_obj)(), false, false, _requesting_thread);
       clean_up_cached_monitor_info();
       return;
     } else {
-      if (TraceBiasedLocking) {
-        tty->print_cr("Revoking bias with global safepoint:");
-      }
+      log_info(biasedlocking)("Revoking bias with global safepoint:");
       BiasedLocking::revoke_at_safepoint(_objs);
     }
   }
@@ -608,9 +627,7 @@
       // can come in with a CAS to steal the bias of an object that has a
       // stale epoch.
       ResourceMark rm;
-      if (TraceBiasedLocking) {
-        tty->print_cr("Revoking bias by walking my own stack:");
-      }
+      log_info(biasedlocking)("Revoking bias by walking my own stack:");
       BiasedLocking::Condition cond = revoke_bias(obj(), false, false, (JavaThread*) THREAD);
       ((JavaThread*) THREAD)->set_cached_monitor_info(NULL);
       assert(cond == BIAS_REVOKED, "why not?");
--- a/src/share/vm/runtime/globals.hpp	Thu Feb 18 14:56:53 2016 +0300
+++ b/src/share/vm/runtime/globals.hpp	Thu Feb 18 17:10:48 2016 -0500
@@ -1488,9 +1488,6 @@
   develop(bool, TraceClearedExceptions, false,                              \
           "Print when an exception is forcibly cleared")                    \
                                                                             \
-  product(bool, TraceBiasedLocking, false,                                  \
-          "Trace biased locking in JVM")                                    \
-                                                                            \
   /* gc */                                                                  \
                                                                             \
   product(bool, UseSerialGC, false,                                         \
--- a/src/share/vm/runtime/thread.cpp	Thu Feb 18 14:56:53 2016 +0300
+++ b/src/share/vm/runtime/thread.cpp	Thu Feb 18 17:10:48 2016 -0500
@@ -170,11 +170,10 @@
     assert(((uintptr_t) aligned_addr + (uintptr_t) size) <=
            ((uintptr_t) real_malloc_addr + (uintptr_t) aligned_size),
            "JavaThread alignment code overflowed allocated storage");
-    if (TraceBiasedLocking) {
-      if (aligned_addr != real_malloc_addr) {
-        tty->print_cr("Aligned thread " INTPTR_FORMAT " to " INTPTR_FORMAT,
-                      p2i(real_malloc_addr), p2i(aligned_addr));
-      }
+    if (aligned_addr != real_malloc_addr) {
+      log_info(biasedlocking)("Aligned thread " INTPTR_FORMAT " to " INTPTR_FORMAT,
+                              p2i(real_malloc_addr),
+                              p2i(aligned_addr));
     }
     ((Thread*) aligned_addr)->_real_malloc_address = real_malloc_addr;
     return aligned_addr;
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/runtime/logging/BiasedLockingTest.java	Thu Feb 18 17:10:48 2016 -0500
@@ -0,0 +1,78 @@
+/*
+ * Copyright (c) 2016, 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 8149383
+ * @summary -Xlog:biasedlocking should have logging from statements in the source code
+ * @library /testlibrary
+ * @modules java.base/sun.misc
+ *          java.management
+ * @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
+ * @run driver BiasedLockingTest
+ */
+
+import jdk.test.lib.OutputAnalyzer;
+import jdk.test.lib.ProcessTools;
+
+public class BiasedLockingTest {
+    static void analyzeOutputOn(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldContain("Biased locking enabled");
+        output.shouldHaveExitValue(0);
+    }
+
+    static void analyzeOutputOff(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldNotContain("[biasedlocking]");
+        output.shouldHaveExitValue(0);
+    }
+
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:biasedlocking",
+                                                                  "-XX:BiasedLockingStartupDelay=0",
+                                                                  InnerClass.class.getName());
+        analyzeOutputOn(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+TraceBiasedLocking",
+                                                   "-XX:BiasedLockingStartupDelay=0",
+                                                   InnerClass.class.getName());
+        analyzeOutputOn(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-Xlog:biasedlocking=off",
+                                                   "-XX:BiasedLockingStartupDelay=0",
+                                                   InnerClass.class.getName());
+        analyzeOutputOff(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:-TraceBiasedLocking",
+                                                   "-XX:BiasedLockingStartupDelay=0",
+                                                   InnerClass.class.getName());
+        analyzeOutputOff(pb);
+    }
+
+    public static class InnerClass {
+        public static void main(String[] args) {
+            System.out.println("Biased Locking test");
+        }
+    }
+}