stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

8217659: monitor_logging updates from Async Monitor Deflation project

Browse Source 
Reviewed-by: dholmes, coleenp, rehn
This commit is contained in:
Daniel D. Daugherty 2019-01-31 11:19:58 -05:00
parent 73ccdf3557
commit 73733d6a18
5 changed files with 432 additions and 47 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
src/hotspot/share/runtime/arguments.cpp
View File

@ -579,7 +579,7 @@ static AliasedLoggingFlag const aliased_logging_flags[] = {
{ "TraceClassUnloading", LogLevel::Info, true, LOG_TAGS(class, unload) }, { "TraceClassUnloading", LogLevel::Info, true, LOG_TAGS(class, unload) },
{ "TraceExceptions", LogLevel::Info, true, LOG_TAGS(exceptions) }, { "TraceExceptions", LogLevel::Info, true, LOG_TAGS(exceptions) },
{ "TraceLoaderConstraints", LogLevel::Info, true, LOG_TAGS(class, loader, constraints) }, { "TraceLoaderConstraints", LogLevel::Info, true, LOG_TAGS(class, loader, constraints) },
{ "TraceMonitorInflation", LogLevel::Debug, true, LOG_TAGS(monitorinflation) }, { "TraceMonitorInflation", LogLevel::Trace, true, LOG_TAGS(monitorinflation) },
{ "TraceSafepointCleanupTime", LogLevel::Info, true, LOG_TAGS(safepoint, cleanup) }, { "TraceSafepointCleanupTime", LogLevel::Info, true, LOG_TAGS(safepoint, cleanup) },
{ "TraceJVMTIObjectTagging", LogLevel::Debug, true, LOG_TAGS(jvmti, objecttagging) }, { "TraceJVMTIObjectTagging", LogLevel::Debug, true, LOG_TAGS(jvmti, objecttagging) },
{ "TraceRedefineClasses", LogLevel::Info, false, LOG_TAGS(redefine, class) }, { "TraceRedefineClasses", LogLevel::Info, false, LOG_TAGS(redefine, class) },

9
src/hotspot/share/runtime/init.cpp
View File

@ -1,5 +1,5 @@
/* /*
* Copyright (c) 1997, 2018, Oracle and/or its affiliates. All rights reserved. * Copyright (c) 1997, 2019, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
* *
* This code is free software; you can redistribute it and/or modify it * This code is free software; you can redistribute it and/or modify it
@ -166,6 +166,13 @@ void exit_globals() {
static bool destructorsCalled = false; static bool destructorsCalled = false;
if (!destructorsCalled) { if (!destructorsCalled) {
destructorsCalled = true; destructorsCalled = true;
if (log_is_enabled(Info, monitorinflation)) {
// The ObjectMonitor subsystem uses perf counters so
// do this before perfMemory_exit().
// ObjectSynchronizer::finish_deflate_idle_monitors()'s call
// to audit_and_print_stats() is done at the Debug level.
ObjectSynchronizer::audit_and_print_stats(true /* on_exit */);
}
perfMemory_exit(); perfMemory_exit();
if (log_is_enabled(Debug, safepoint, stats)) { if (log_is_enabled(Debug, safepoint, stats)) {
// Print the collected safepoint statistics. // Print the collected safepoint statistics.

438
src/hotspot/share/runtime/synchronizer.cpp
View File

@ -25,6 +25,7 @@
#include "precompiled.hpp" #include "precompiled.hpp"
#include "classfile/vmSymbols.hpp" #include "classfile/vmSymbols.hpp"
#include "logging/log.hpp" #include "logging/log.hpp"
#include "logging/logStream.hpp"
#include "jfr/jfrEvents.hpp" #include "jfr/jfrEvents.hpp"
#include "memory/allocation.inline.hpp" #include "memory/allocation.inline.hpp"
#include "memory/metaspaceShared.hpp" #include "memory/metaspaceShared.hpp"
@ -1354,6 +1355,8 @@ ObjectMonitor* ObjectSynchronizer::inflate(Thread * Self,
// before or after the CAS(INFLATING) operation. // before or after the CAS(INFLATING) operation.
// See the comments in omAlloc(). // See the comments in omAlloc().
LogStreamHandle(Trace, monitorinflation) lsh;
if (mark->has_locker()) { if (mark->has_locker()) {
ObjectMonitor * m = omAlloc(Self); ObjectMonitor * m = omAlloc(Self);
// Optimistically prepare the objectmonitor - anticipate successful CAS // Optimistically prepare the objectmonitor - anticipate successful CAS
@ -1423,14 +1426,11 @@ ObjectMonitor* ObjectSynchronizer::inflate(Thread * Self,
// Hopefully the performance counters are allocated on distinct cache lines // Hopefully the performance counters are allocated on distinct cache lines
// to avoid false sharing on MP systems ... // to avoid false sharing on MP systems ...
OM_PERFDATA_OP(Inflations, inc()); OM_PERFDATA_OP(Inflations, inc());
if (log_is_enabled(Debug, monitorinflation)) { if (log_is_enabled(Trace, monitorinflation)) {
if (object->is_instance()) { ResourceMark rm(Self);
ResourceMark rm(Self); lsh.print_cr("inflate(has_locker): object=" INTPTR_FORMAT ", mark="
log_debug(monitorinflation)("inflate(has_locker): " INTPTR_FORMAT ", type='%s'", p2i(object),
"object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", p2i(object->mark()), object->klass()->external_name());
p2i(object), p2i(object->mark()),
object->klass()->external_name());
}
} }
if (event.should_commit()) { if (event.should_commit()) {
post_monitor_inflate_event(&event, object, cause); post_monitor_inflate_event(&event, object, cause);
@ -1474,14 +1474,11 @@ ObjectMonitor* ObjectSynchronizer::inflate(Thread * Self,
// Hopefully the performance counters are allocated on distinct // Hopefully the performance counters are allocated on distinct
// cache lines to avoid false sharing on MP systems ... // cache lines to avoid false sharing on MP systems ...
OM_PERFDATA_OP(Inflations, inc()); OM_PERFDATA_OP(Inflations, inc());
if (log_is_enabled(Debug, monitorinflation)) { if (log_is_enabled(Trace, monitorinflation)) {
if (object->is_instance()) { ResourceMark rm(Self);
ResourceMark rm(Self); lsh.print_cr("inflate(neutral): object=" INTPTR_FORMAT ", mark="
log_debug(monitorinflation)("inflate(neutral): " INTPTR_FORMAT ", type='%s'", p2i(object),
"object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", p2i(object->mark()), object->klass()->external_name());
p2i(object), p2i(object->mark()),
object->klass()->external_name());
}
} }
if (event.should_commit()) { if (event.should_commit()) {
post_monitor_inflate_event(&event, object, cause); post_monitor_inflate_event(&event, object, cause);
@ -1529,14 +1526,12 @@ bool ObjectSynchronizer::deflate_monitor(ObjectMonitor* mid, oop obj,
// Deflate the monitor if it is no longer being used // Deflate the monitor if it is no longer being used
// It's idle - scavenge and return to the global free list // It's idle - scavenge and return to the global free list
// plain old deflation ... // plain old deflation ...
if (log_is_enabled(Debug, monitorinflation)) { if (log_is_enabled(Trace, monitorinflation)) {
if (obj->is_instance()) { ResourceMark rm;
ResourceMark rm; log_trace(monitorinflation)("deflate_monitor: "
log_debug(monitorinflation)("deflate_monitor: " "object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'",
"object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", p2i(obj), p2i(obj->mark()),
p2i(obj), p2i(obj->mark()), obj->klass()->external_name());
obj->klass()->external_name());
}
} }
// Restore the header back to obj // Restore the header back to obj
@ -1602,10 +1597,11 @@ int ObjectSynchronizer::deflate_monitor_list(ObjectMonitor** listHeadp,
} }
void ObjectSynchronizer::prepare_deflate_idle_monitors(DeflateMonitorCounters* counters) { void ObjectSynchronizer::prepare_deflate_idle_monitors(DeflateMonitorCounters* counters) {
counters->nInuse = 0; // currently associated with objects counters->nInuse = 0; // currently associated with objects
counters->nInCirculation = 0; // extant counters->nInCirculation = 0; // extant
counters->nScavenged = 0; // reclaimed (global and per-thread) counters->nScavenged = 0; // reclaimed (global and per-thread)
counters->perThreadTimes = 0.0; // per-thread scavenge times counters->perThreadScavenged = 0; // per-thread scavenge total
counters->perThreadTimes = 0.0; // per-thread scavenge times
} }
void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters) { void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters) {
@ -1614,6 +1610,11 @@ void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters)
ObjectMonitor * freeHeadp = NULL; // Local SLL of scavenged monitors ObjectMonitor * freeHeadp = NULL; // Local SLL of scavenged monitors
ObjectMonitor * freeTailp = NULL; ObjectMonitor * freeTailp = NULL;
elapsedTimer timer;
if (log_is_enabled(Info, monitorinflation)) {
timer.start();
}
// Prevent omFlush from changing mids in Thread dtor's during deflation // Prevent omFlush from changing mids in Thread dtor's during deflation
// And in case the vm thread is acquiring a lock during a safepoint // And in case the vm thread is acquiring a lock during a safepoint
@ -1624,9 +1625,10 @@ void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters)
// a separate pass. See deflate_thread_local_monitors(). // a separate pass. See deflate_thread_local_monitors().
// For moribund threads, scan gOmInUseList // For moribund threads, scan gOmInUseList
int deflated_count = 0;
if (gOmInUseList) { if (gOmInUseList) {
counters->nInCirculation += gOmInUseCount; counters->nInCirculation += gOmInUseCount;
int deflated_count = deflate_monitor_list((ObjectMonitor **)&gOmInUseList, &freeHeadp, &freeTailp); deflated_count = deflate_monitor_list((ObjectMonitor **)&gOmInUseList, &freeHeadp, &freeTailp);
gOmInUseCount -= deflated_count; gOmInUseCount -= deflated_count;
counters->nScavenged += deflated_count; counters->nScavenged += deflated_count;
counters->nInuse += gOmInUseCount; counters->nInuse += gOmInUseCount;
@ -1641,29 +1643,53 @@ void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters)
gFreeList = freeHeadp; gFreeList = freeHeadp;
} }
Thread::muxRelease(&gListLock); Thread::muxRelease(&gListLock);
timer.stop();
LogStreamHandle(Debug, monitorinflation) lsh_debug;
LogStreamHandle(Info, monitorinflation) lsh_info;
LogStream * ls = NULL;
if (log_is_enabled(Debug, monitorinflation)) {
ls = &lsh_debug;
} else if (deflated_count != 0 && log_is_enabled(Info, monitorinflation)) {
ls = &lsh_info;
}
if (ls != NULL) {
ls->print_cr("deflating global idle monitors, %3.7f secs, %d monitors", timer.seconds(), deflated_count);
}
} }
void ObjectSynchronizer::finish_deflate_idle_monitors(DeflateMonitorCounters* counters) { void ObjectSynchronizer::finish_deflate_idle_monitors(DeflateMonitorCounters* counters) {
if (log_is_enabled(Info, safepoint, cleanup)) { // Report the cumulative time for deflating each thread's idle
// Report the cumulative time for deflating each thread's idle // monitors. Note: if the work is split among more than one
// monitors. Note: if the work is split among more than one // worker thread, then the reported time will likely be more
// worker thread, then the reported time will likely be more // than a beginning to end measurement of the phase.
// than a beginning to end measurement of the phase. log_info(safepoint, cleanup)("deflating per-thread idle monitors, %3.7f secs, monitors=%d", counters->perThreadTimes, counters->perThreadScavenged);
log_info(safepoint, cleanup)("deflating per-thread idle monitors, %3.7f secs", counters->perThreadTimes);
LogStreamHandle(Debug, monitorinflation) lsh_debug;
LogStreamHandle(Info, monitorinflation) lsh_info;
LogStream * ls = NULL;
if (log_is_enabled(Debug, monitorinflation)) {
ls = &lsh_debug;
} else if (counters->perThreadScavenged != 0 && log_is_enabled(Info, monitorinflation)) {
ls = &lsh_info;
}
if (ls != NULL) {
ls->print_cr("deflating per-thread idle monitors, %3.7f secs, %d monitors", counters->perThreadTimes, counters->perThreadScavenged);
} }
gMonitorFreeCount += counters->nScavenged; gMonitorFreeCount += counters->nScavenged;
// Consider: audit gFreeList to ensure that gMonitorFreeCount and list agree. if (log_is_enabled(Debug, monitorinflation)) {
// exit_globals()'s call to audit_and_print_stats() is done
// at the Info level.
ObjectSynchronizer::audit_and_print_stats(false /* on_exit */);
}
ForceMonitorScavenge = 0; // Reset ForceMonitorScavenge = 0; // Reset
OM_PERFDATA_OP(Deflations, inc(counters->nScavenged)); OM_PERFDATA_OP(Deflations, inc(counters->nScavenged));
OM_PERFDATA_OP(MonExtant, set_value(counters->nInCirculation)); OM_PERFDATA_OP(MonExtant, set_value(counters->nInCirculation));
// TODO: Add objectMonitor leak detection.
// Audit/inventory the objectMonitors -- make sure they're all accounted for.
GVars.stwRandom = os::random(); GVars.stwRandom = os::random();
GVars.stwCycle++; GVars.stwCycle++;
} }
@ -1675,7 +1701,8 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
ObjectMonitor * freeTailp = NULL; ObjectMonitor * freeTailp = NULL;
elapsedTimer timer; elapsedTimer timer;
if (log_is_enabled(Info, safepoint, cleanup)) { if (log_is_enabled(Info, safepoint, cleanup) ||
log_is_enabled(Info, monitorinflation)) {
timer.start(); timer.start();
} }
@ -1690,6 +1717,7 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
thread->omInUseCount -= deflated_count; thread->omInUseCount -= deflated_count;
counters->nScavenged += deflated_count; counters->nScavenged += deflated_count;
counters->nInuse += thread->omInUseCount; counters->nInuse += thread->omInUseCount;
counters->perThreadScavenged += deflated_count;
// For now, we only care about cumulative per-thread deflation time. // For now, we only care about cumulative per-thread deflation time.
counters->perThreadTimes += timer.seconds(); counters->perThreadTimes += timer.seconds();
@ -1782,6 +1810,338 @@ u_char* ObjectSynchronizer::get_gvars_stwRandom_addr() {
return (u_char*)&GVars.stwRandom; return (u_char*)&GVars.stwRandom;
} }
void ObjectSynchronizer::audit_and_print_stats(bool on_exit) {
assert(on_exit || SafepointSynchronize::is_at_safepoint(), "invariant");
LogStreamHandle(Debug, monitorinflation) lsh_debug;
LogStreamHandle(Info, monitorinflation) lsh_info;
LogStreamHandle(Trace, monitorinflation) lsh_trace;
LogStream * ls = NULL;
if (log_is_enabled(Trace, monitorinflation)) {
ls = &lsh_trace;
} else if (log_is_enabled(Debug, monitorinflation)) {
ls = &lsh_debug;
} else if (log_is_enabled(Info, monitorinflation)) {
ls = &lsh_info;
}
assert(ls != NULL, "sanity check");
if (!on_exit) {
// Not at VM exit so grab the global list lock.
Thread::muxAcquire(&gListLock, "audit_and_print_stats");
}
// Log counts for the global and per-thread monitor lists:
int chkMonitorPopulation = log_monitor_list_counts(ls);
int error_cnt = 0;
ls->print_cr("Checking global lists:");
// Check gMonitorPopulation:
if (gMonitorPopulation == chkMonitorPopulation) {
ls->print_cr("gMonitorPopulation=%d equals chkMonitorPopulation=%d",
gMonitorPopulation, chkMonitorPopulation);
} else {
ls->print_cr("ERROR: gMonitorPopulation=%d is not equal to "
"chkMonitorPopulation=%d", gMonitorPopulation,
chkMonitorPopulation);
error_cnt++;
}
// Check gOmInUseList and gOmInUseCount:
chk_global_in_use_list_and_count(ls, &error_cnt);
// Check gFreeList and gMonitorFreeCount:
chk_global_free_list_and_count(ls, &error_cnt);
if (!on_exit) {
Thread::muxRelease(&gListLock);
}
ls->print_cr("Checking per-thread lists:");
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *jt = jtiwh.next(); ) {
// Check omInUseList and omInUseCount:
chk_per_thread_in_use_list_and_count(jt, ls, &error_cnt);
// Check omFreeList and omFreeCount:
chk_per_thread_free_list_and_count(jt, ls, &error_cnt);
}
if (error_cnt == 0) {
ls->print_cr("No errors found in monitor list checks.");
} else {
log_error(monitorinflation)("found monitor list errors: error_cnt=%d", error_cnt);
}
if ((on_exit && log_is_enabled(Info, monitorinflation)) ||
(!on_exit && log_is_enabled(Trace, monitorinflation))) {
// When exiting this log output is at the Info level. When called
// at a safepoint, this log output is at the Trace level since
// there can be a lot of it.
log_in_use_monitor_details(ls, on_exit);
}
ls->flush();
guarantee(error_cnt == 0, "ERROR: found monitor list errors: error_cnt=%d", error_cnt);
}
// Check a free monitor entry; log any errors.
void ObjectSynchronizer::chk_free_entry(JavaThread * jt, ObjectMonitor * n,
outputStream * out, int *error_cnt_p) {
if (n->is_busy()) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": free per-thread monitor must not be busy.", p2i(jt),
p2i(n));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global monitor "
"must not be busy.", p2i(n));
}
*error_cnt_p = *error_cnt_p + 1;
}
if (n->header() != NULL) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": free per-thread monitor must have NULL _header "
"field: _header=" INTPTR_FORMAT, p2i(jt), p2i(n),
p2i(n->header()));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global monitor "
"must have NULL _header field: _header=" INTPTR_FORMAT,
p2i(n), p2i(n->header()));
}
*error_cnt_p = *error_cnt_p + 1;
}
if (n->object() != NULL) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": free per-thread monitor must have NULL _object "
"field: _object=" INTPTR_FORMAT, p2i(jt), p2i(n),
p2i(n->object()));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global monitor "
"must have NULL _object field: _object=" INTPTR_FORMAT,
p2i(n), p2i(n->object()));
}
*error_cnt_p = *error_cnt_p + 1;
}
}
// Check the global free list and count; log the results of the checks.
void ObjectSynchronizer::chk_global_free_list_and_count(outputStream * out,
int *error_cnt_p) {
int chkMonitorFreeCount = 0;
for (ObjectMonitor * n = gFreeList; n != NULL; n = n->FreeNext) {
chk_free_entry(NULL /* jt */, n, out, error_cnt_p);
chkMonitorFreeCount++;
}
if (gMonitorFreeCount == chkMonitorFreeCount) {
out->print_cr("gMonitorFreeCount=%d equals chkMonitorFreeCount=%d",
gMonitorFreeCount, chkMonitorFreeCount);
} else {
out->print_cr("ERROR: gMonitorFreeCount=%d is not equal to "
"chkMonitorFreeCount=%d", gMonitorFreeCount,
chkMonitorFreeCount);
*error_cnt_p = *error_cnt_p + 1;
}
}
// Check the global in-use list and count; log the results of the checks.
void ObjectSynchronizer::chk_global_in_use_list_and_count(outputStream * out,
int *error_cnt_p) {
int chkOmInUseCount = 0;
for (ObjectMonitor * n = gOmInUseList; n != NULL; n = n->FreeNext) {
chk_in_use_entry(NULL /* jt */, n, out, error_cnt_p);
chkOmInUseCount++;
}
if (gOmInUseCount == chkOmInUseCount) {
out->print_cr("gOmInUseCount=%d equals chkOmInUseCount=%d", gOmInUseCount,
chkOmInUseCount);
} else {
out->print_cr("ERROR: gOmInUseCount=%d is not equal to chkOmInUseCount=%d",
gOmInUseCount, chkOmInUseCount);
*error_cnt_p = *error_cnt_p + 1;
}
}
// Check an in-use monitor entry; log any errors.
void ObjectSynchronizer::chk_in_use_entry(JavaThread * jt, ObjectMonitor * n,
outputStream * out, int *error_cnt_p) {
if (n->header() == NULL) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": in-use per-thread monitor must have non-NULL _header "
"field.", p2i(jt), p2i(n));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global monitor "
"must have non-NULL _header field.", p2i(n));
}
*error_cnt_p = *error_cnt_p + 1;
}
if (n->object() == NULL) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": in-use per-thread monitor must have non-NULL _object "
"field.", p2i(jt), p2i(n));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global monitor "
"must have non-NULL _object field.", p2i(n));
}
*error_cnt_p = *error_cnt_p + 1;
}
const oop obj = (oop)n->object();
const markOop mark = obj->mark();
if (!mark->has_monitor()) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": in-use per-thread monitor's object does not think "
"it has a monitor: obj=" INTPTR_FORMAT ", mark="
INTPTR_FORMAT, p2i(jt), p2i(n), p2i((address)obj),
p2i((address)mark));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global "
"monitor's object does not think it has a monitor: obj="
INTPTR_FORMAT ", mark=" INTPTR_FORMAT, p2i(n),
p2i((address)obj), p2i((address)mark));
}
*error_cnt_p = *error_cnt_p + 1;
}
ObjectMonitor * const obj_mon = mark->monitor();
if (n != obj_mon) {
if (jt != NULL) {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
": in-use per-thread monitor's object does not refer "
"to the same monitor: obj=" INTPTR_FORMAT ", mark="
INTPTR_FORMAT ", obj_mon=" INTPTR_FORMAT, p2i(jt),
p2i(n), p2i((address)obj), p2i((address)mark),
p2i((address)obj_mon));
} else {
out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global "
"monitor's object does not refer to the same monitor: obj="
INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", obj_mon="
INTPTR_FORMAT, p2i(n), p2i((address)obj),
p2i((address)mark), p2i((address)obj_mon));
}
*error_cnt_p = *error_cnt_p + 1;
}
}
// Check the thread's free list and count; log the results of the checks.
void ObjectSynchronizer::chk_per_thread_free_list_and_count(JavaThread *jt,
outputStream * out,
int *error_cnt_p) {
int chkOmFreeCount = 0;
for (ObjectMonitor * n = jt->omFreeList; n != NULL; n = n->FreeNext) {
chk_free_entry(jt, n, out, error_cnt_p);
chkOmFreeCount++;
}
if (jt->omFreeCount == chkOmFreeCount) {
out->print_cr("jt=" INTPTR_FORMAT ": omFreeCount=%d equals "
"chkOmFreeCount=%d", p2i(jt), jt->omFreeCount, chkOmFreeCount);
} else {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ": omFreeCount=%d is not "
"equal to chkOmFreeCount=%d", p2i(jt), jt->omFreeCount,
chkOmFreeCount);
*error_cnt_p = *error_cnt_p + 1;
}
}
// Check the thread's in-use list and count; log the results of the checks.
void ObjectSynchronizer::chk_per_thread_in_use_list_and_count(JavaThread *jt,
outputStream * out,
int *error_cnt_p) {
int chkOmInUseCount = 0;
for (ObjectMonitor * n = jt->omInUseList; n != NULL; n = n->FreeNext) {
chk_in_use_entry(jt, n, out, error_cnt_p);
chkOmInUseCount++;
}
if (jt->omInUseCount == chkOmInUseCount) {
out->print_cr("jt=" INTPTR_FORMAT ": omInUseCount=%d equals "
"chkOmInUseCount=%d", p2i(jt), jt->omInUseCount,
chkOmInUseCount);
} else {
out->print_cr("ERROR: jt=" INTPTR_FORMAT ": omInUseCount=%d is not "
"equal to chkOmInUseCount=%d", p2i(jt), jt->omInUseCount,
chkOmInUseCount);
*error_cnt_p = *error_cnt_p + 1;
}
}
// Log details about ObjectMonitors on the in-use lists. The 'BHL'
// flags indicate why the entry is in-use, 'object' and 'object type'
// indicate the associated object and its type.
void ObjectSynchronizer::log_in_use_monitor_details(outputStream * out,
bool on_exit) {
if (!on_exit) {
// Not at VM exit so grab the global list lock.
Thread::muxAcquire(&gListLock, "log_in_use_monitor_details");
}
if (gOmInUseCount > 0) {
out->print_cr("In-use global monitor info:");
out->print_cr("(B -> is_busy, H -> has hashcode, L -> lock status)");
out->print_cr("%18s %s %18s %18s",
"monitor", "BHL", "object", "object type");
out->print_cr("================== === ================== ==================");
for (ObjectMonitor * n = gOmInUseList; n != NULL; n = n->FreeNext) {
const oop obj = (oop) n->object();
const markOop mark = n->header();
ResourceMark rm;
out->print_cr(INTPTR_FORMAT " %d%d%d " INTPTR_FORMAT " %s", p2i(n),
n->is_busy() != 0, mark->hash() != 0, n->owner() != NULL,
p2i(obj), obj->klass()->external_name());
}
}
if (!on_exit) {
Thread::muxRelease(&gListLock);
}
out->print_cr("In-use per-thread monitor info:");
out->print_cr("(B -> is_busy, H -> has hashcode, L -> lock status)");
out->print_cr("%18s %18s %s %18s %18s",
"jt", "monitor", "BHL", "object", "object type");
out->print_cr("================== ================== === ================== ==================");
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *jt = jtiwh.next(); ) {
for (ObjectMonitor * n = jt->omInUseList; n != NULL; n = n->FreeNext) {
const oop obj = (oop) n->object();
const markOop mark = n->header();
ResourceMark rm;
out->print_cr(INTPTR_FORMAT " " INTPTR_FORMAT " %d%d%d " INTPTR_FORMAT
" %s", p2i(jt), p2i(n), n->is_busy() != 0,
mark->hash() != 0, n->owner() != NULL, p2i(obj),
obj->klass()->external_name());
}
}
out->flush();
}
// Log counts for the global and per-thread monitor lists and return
// the population count.
int ObjectSynchronizer::log_monitor_list_counts(outputStream * out) {
int popCount = 0;
out->print_cr("%18s %10s %10s %10s",
"Global Lists:", "InUse", "Free", "Total");
out->print_cr("================== ========== ========== ==========");
out->print_cr("%18s %10d %10d %10d", "",
gOmInUseCount, gMonitorFreeCount, gMonitorPopulation);
popCount += gOmInUseCount + gMonitorFreeCount;
out->print_cr("%18s %10s %10s %10s",
"Per-Thread Lists:", "InUse", "Free", "Provision");
out->print_cr("================== ========== ========== ==========");
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *jt = jtiwh.next(); ) {
out->print_cr(INTPTR_FORMAT " %10d %10d %10d", p2i(jt),
jt->omInUseCount, jt->omFreeCount, jt->omFreeProvision);
popCount += jt->omInUseCount + jt->omFreeCount;
}
return popCount;
}
#ifndef PRODUCT #ifndef PRODUCT
// Check if monitor belongs to the monitor cache // Check if monitor belongs to the monitor cache

26
src/hotspot/share/runtime/synchronizer.hpp
View File

@ -35,10 +35,11 @@ class ObjectMonitor;
class ThreadsList; class ThreadsList;
struct DeflateMonitorCounters { struct DeflateMonitorCounters {
int nInuse; // currently associated with objects int nInuse; // currently associated with objects
int nInCirculation; // extant int nInCirculation; // extant
int nScavenged; // reclaimed (global and per-thread) int nScavenged; // reclaimed (global and per-thread)
double perThreadTimes; // per-thread scavenge times int perThreadScavenged; // per-thread scavenge total
double perThreadTimes; // per-thread scavenge times
}; };
class ObjectSynchronizer : AllStatic { class ObjectSynchronizer : AllStatic {
@ -153,6 +154,23 @@ class ObjectSynchronizer : AllStatic {
static void thread_local_used_oops_do(Thread* thread, OopClosure* f); static void thread_local_used_oops_do(Thread* thread, OopClosure* f);
// debugging // debugging
static void audit_and_print_stats(bool on_exit);
static void chk_free_entry(JavaThread * jt, ObjectMonitor * n,
outputStream * out, int *error_cnt_p);
static void chk_global_free_list_and_count(outputStream * out,
int *error_cnt_p);
static void chk_global_in_use_list_and_count(outputStream * out,
int *error_cnt_p);
static void chk_in_use_entry(JavaThread * jt, ObjectMonitor * n,
outputStream * out, int *error_cnt_p);
static void chk_per_thread_in_use_list_and_count(JavaThread *jt,
outputStream * out,
int *error_cnt_p);
static void chk_per_thread_free_list_and_count(JavaThread *jt,
outputStream * out,
int *error_cnt_p);
static void log_in_use_monitor_details(outputStream * out, bool on_exit);
static int log_monitor_list_counts(outputStream * out);
static int verify_objmon_isinpool(ObjectMonitor *addr) PRODUCT_RETURN0; static int verify_objmon_isinpool(ObjectMonitor *addr) PRODUCT_RETURN0;
private: private:

4
test/hotspot/jtreg/runtime/logging/MonitorInflationTest.java
View File

@ -24,7 +24,7 @@
/* /*
* @test * @test
* @bug 8133885 * @bug 8133885
* @summary monitorinflation=debug should have logging from each of the statements in the code * @summary monitorinflation=trace should have logging from each of the statements in the code
* @library /test/lib * @library /test/lib
* @modules java.base/jdk.internal.misc * @modules java.base/jdk.internal.misc
* java.management * java.management
@ -50,7 +50,7 @@ public class MonitorInflationTest {
} }
public static void main(String[] args) throws Exception { public static void main(String[] args) throws Exception {
ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:monitorinflation=debug", ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:monitorinflation=trace",
InnerClass.class.getName()); InnerClass.class.getName());
analyzeOutputOn(pb); analyzeOutputOn(pb);