8221350: more monitor logging updates from Async Monitor Deflation project

Reviewed-by: dholmes, coleenp
This commit is contained in:
Daniel D. Daugherty 2019-03-26 15:27:41 -04:00
parent 6efb59fad7
commit 6e84bce1b5
3 changed files with 49 additions and 25 deletions

@ -1270,6 +1270,21 @@ void ObjectSynchronizer::omFlush(Thread * Self) {
}
Thread::muxRelease(&gListLock);
LogStreamHandle(Debug, monitorinflation) lsh_debug;
LogStreamHandle(Info, monitorinflation) lsh_info;
LogStream * ls = NULL;
if (log_is_enabled(Debug, monitorinflation)) {
ls = &lsh_debug;
} else if ((tally != 0 || inUseTally != 0) &&
log_is_enabled(Info, monitorinflation)) {
ls = &lsh_info;
}
if (ls != NULL) {
ls->print_cr("omFlush: jt=" INTPTR_FORMAT ", free_monitor_tally=%d"
", in_use_monitor_tally=%d" ", omFreeProvision=%d",
p2i(Self), tally, inUseTally, Self->omFreeProvision);
}
}
static void post_monitor_inflate_event(EventJavaMonitorInflate* event,
@ -1665,24 +1680,18 @@ void ObjectSynchronizer::finish_deflate_idle_monitors(DeflateMonitorCounters* co
// 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);
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;
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 */);
} else if (log_is_enabled(Info, monitorinflation)) {
Thread::muxAcquire(&gListLock, "finish_deflate_idle_monitors");
log_info(monitorinflation)("gMonitorPopulation=%d, gOmInUseCount=%d, "
"gMonitorFreeCount=%d", gMonitorPopulation,
gOmInUseCount, gMonitorFreeCount);
Thread::muxRelease(&gListLock);
}
ForceMonitorScavenge = 0; // Reset
@ -1708,8 +1717,6 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
int deflated_count = deflate_monitor_list(thread->omInUseList_addr(), &freeHeadp, &freeTailp);
timer.stop();
Thread::muxAcquire(&gListLock, "deflate_thread_local_monitors");
// Adjust counters
@ -1718,8 +1725,6 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
counters->nScavenged += deflated_count;
counters->nInuse += thread->omInUseCount;
counters->perThreadScavenged += deflated_count;
// For now, we only care about cumulative per-thread deflation time.
counters->perThreadTimes += timer.seconds();
// Move the scavenged monitors back to the global free list.
if (freeHeadp != NULL) {
@ -1730,7 +1735,26 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
freeTailp->FreeNext = gFreeList;
gFreeList = freeHeadp;
}
timer.stop();
// Safepoint logging cares about cumulative perThreadTimes and
// we'll capture most of the cost, but not the muxRelease() which
// should be cheap.
counters->perThreadTimes += timer.seconds();
Thread::muxRelease(&gListLock);
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("jt=" INTPTR_FORMAT ": deflating per-thread idle monitors, %3.7f secs, %d monitors", p2i(thread), timer.seconds(), deflated_count);
}
}
// Monitor cleanup on JavaThread::exit
@ -1839,13 +1863,13 @@ void ObjectSynchronizer::audit_and_print_stats(bool on_exit) {
// Check gMonitorPopulation:
if (gMonitorPopulation == chkMonitorPopulation) {
ls->print_cr("gMonitorPopulation=%d equals chkMonitorPopulation=%d",
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++;
ls->print_cr("ERROR: gMonitorPopulation=%d is not equal to "
"chkMonitorPopulation=%d", gMonitorPopulation,
chkMonitorPopulation);
error_cnt++;
}
// Check gOmInUseList and gOmInUseCount:

@ -199,11 +199,11 @@ class ObjectSynchronizer : AllStatic {
static u_char* get_gvars_stwRandom_addr();
};
// ObjectLocker enforced balanced locking and can never thrown an
// ObjectLocker enforces balanced locking and can never throw an
// IllegalMonitorStateException. However, a pending exception may
// have to pass through, and we must also be able to deal with
// asynchronous exceptions. The caller is responsible for checking
// the threads pending exception if needed.
// the thread's pending exception if needed.
class ObjectLocker : public StackObj {
private:
Thread* _thread;

@ -4449,7 +4449,7 @@ void Threads::add(JavaThread* p, bool force_daemon) {
void Threads::remove(JavaThread* p) {
// Reclaim the objectmonitors from the omInUseList and omFreeList of the moribund thread.
// Reclaim the ObjectMonitors from the omInUseList and omFreeList of the moribund thread.
ObjectSynchronizer::omFlush(p);
// Extra scope needed for Thread_lock, so we can check