diff -r 739eaf4ac4ad -r a5f46c4690f8 src/hotspot/share/runtime/synchronizer.cpp --- a/src/hotspot/share/runtime/synchronizer.cpp Thu Jan 31 10:29:53 2019 -0500 +++ b/src/hotspot/share/runtime/synchronizer.cpp Thu Jan 31 11:19:58 2019 -0500 @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "classfile/vmSymbols.hpp" #include "logging/log.hpp" +#include "logging/logStream.hpp" #include "jfr/jfrEvents.hpp" #include "memory/allocation.inline.hpp" #include "memory/metaspaceShared.hpp" @@ -1354,6 +1355,8 @@ // before or after the CAS(INFLATING) operation. // See the comments in omAlloc(). + LogStreamHandle(Trace, monitorinflation) lsh; + if (mark->has_locker()) { ObjectMonitor * m = omAlloc(Self); // Optimistically prepare the objectmonitor - anticipate successful CAS @@ -1423,14 +1426,11 @@ // Hopefully the performance counters are allocated on distinct cache lines // to avoid false sharing on MP systems ... OM_PERFDATA_OP(Inflations, inc()); - if (log_is_enabled(Debug, monitorinflation)) { - if (object->is_instance()) { - ResourceMark rm(Self); - log_debug(monitorinflation)("inflate(has_locker): " - "object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", - p2i(object), p2i(object->mark()), - object->klass()->external_name()); - } + if (log_is_enabled(Trace, monitorinflation)) { + ResourceMark rm(Self); + lsh.print_cr("inflate(has_locker): object=" INTPTR_FORMAT ", mark=" + INTPTR_FORMAT ", type='%s'", p2i(object), + p2i(object->mark()), object->klass()->external_name()); } if (event.should_commit()) { post_monitor_inflate_event(&event, object, cause); @@ -1474,14 +1474,11 @@ // Hopefully the performance counters are allocated on distinct // cache lines to avoid false sharing on MP systems ... OM_PERFDATA_OP(Inflations, inc()); - if (log_is_enabled(Debug, monitorinflation)) { - if (object->is_instance()) { - ResourceMark rm(Self); - log_debug(monitorinflation)("inflate(neutral): " - "object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", - p2i(object), p2i(object->mark()), - object->klass()->external_name()); - } + if (log_is_enabled(Trace, monitorinflation)) { + ResourceMark rm(Self); + lsh.print_cr("inflate(neutral): object=" INTPTR_FORMAT ", mark=" + INTPTR_FORMAT ", type='%s'", p2i(object), + p2i(object->mark()), object->klass()->external_name()); } if (event.should_commit()) { post_monitor_inflate_event(&event, object, cause); @@ -1529,14 +1526,12 @@ // Deflate the monitor if it is no longer being used // It's idle - scavenge and return to the global free list // plain old deflation ... - if (log_is_enabled(Debug, monitorinflation)) { - if (obj->is_instance()) { - ResourceMark rm; - log_debug(monitorinflation)("deflate_monitor: " - "object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", - p2i(obj), p2i(obj->mark()), - obj->klass()->external_name()); - } + if (log_is_enabled(Trace, monitorinflation)) { + ResourceMark rm; + log_trace(monitorinflation)("deflate_monitor: " + "object=" INTPTR_FORMAT ", mark=" INTPTR_FORMAT ", type='%s'", + p2i(obj), p2i(obj->mark()), + obj->klass()->external_name()); } // Restore the header back to obj @@ -1602,10 +1597,11 @@ } void ObjectSynchronizer::prepare_deflate_idle_monitors(DeflateMonitorCounters* counters) { - counters->nInuse = 0; // currently associated with objects - counters->nInCirculation = 0; // extant - counters->nScavenged = 0; // reclaimed (global and per-thread) - counters->perThreadTimes = 0.0; // per-thread scavenge times + counters->nInuse = 0; // currently associated with objects + counters->nInCirculation = 0; // extant + counters->nScavenged = 0; // reclaimed (global and per-thread) + counters->perThreadScavenged = 0; // per-thread scavenge total + counters->perThreadTimes = 0.0; // per-thread scavenge times } void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters) { @@ -1614,6 +1610,11 @@ ObjectMonitor * freeHeadp = NULL; // Local SLL of scavenged monitors ObjectMonitor * freeTailp = NULL; + elapsedTimer timer; + + if (log_is_enabled(Info, monitorinflation)) { + timer.start(); + } // Prevent omFlush from changing mids in Thread dtor's during deflation // And in case the vm thread is acquiring a lock during a safepoint @@ -1624,9 +1625,10 @@ // a separate pass. See deflate_thread_local_monitors(). // For moribund threads, scan gOmInUseList + int deflated_count = 0; if (gOmInUseList) { 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; counters->nScavenged += deflated_count; counters->nInuse += gOmInUseCount; @@ -1641,29 +1643,53 @@ gFreeList = freeHeadp; } 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) { - if (log_is_enabled(Info, safepoint, cleanup)) { - // Report the cumulative time for deflating each thread's idle - // monitors. Note: if the work is split among more than one - // worker thread, then the reported time will likely be more - // than a beginning to end measurement of the phase. - log_info(safepoint, cleanup)("deflating per-thread idle monitors, %3.7f secs", counters->perThreadTimes); + // Report the cumulative time for deflating each thread's idle + // monitors. Note: if the work is split among more than one + // worker thread, then the reported time will likely be more + // 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; - // 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 OM_PERFDATA_OP(Deflations, inc(counters->nScavenged)); 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.stwCycle++; } @@ -1675,7 +1701,8 @@ ObjectMonitor * freeTailp = NULL; elapsedTimer timer; - if (log_is_enabled(Info, safepoint, cleanup)) { + if (log_is_enabled(Info, safepoint, cleanup) || + log_is_enabled(Info, monitorinflation)) { timer.start(); } @@ -1690,6 +1717,7 @@ thread->omInUseCount -= deflated_count; 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(); @@ -1782,6 +1810,338 @@ 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 // Check if monitor belongs to the monitor cache