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
--- a/hotspot/src/share/vm/logging/logTag.hpp Thu Feb 18 14:56:53 2016 +0300
+++ b/hotspot/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/hotspot/src/share/vm/runtime/arguments.cpp Thu Feb 18 14:56:53 2016 +0300
+++ b/hotspot/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/hotspot/src/share/vm/runtime/biasedLocking.cpp Thu Feb 18 14:56:53 2016 +0300
+++ b/hotspot/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/hotspot/src/share/vm/runtime/globals.hpp Thu Feb 18 14:56:53 2016 +0300
+++ b/hotspot/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/hotspot/src/share/vm/runtime/thread.cpp Thu Feb 18 14:56:53 2016 +0300
+++ b/hotspot/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/hotspot/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");
+ }
+ }
+}