8217659: monitor_logging updates from Async Monitor Deflation project
authordcubed
Thu, 31 Jan 2019 11:19:58 -0500
changeset 53588 a5f46c4690f8
parent 53587 739eaf4ac4ad
child 53589 9ee67f08fdaa
8217659: monitor_logging updates from Async Monitor Deflation project Reviewed-by: dholmes, coleenp, rehn
src/hotspot/share/runtime/arguments.cpp
src/hotspot/share/runtime/init.cpp
src/hotspot/share/runtime/synchronizer.cpp
src/hotspot/share/runtime/synchronizer.hpp
test/hotspot/jtreg/runtime/logging/MonitorInflationTest.java
--- a/src/hotspot/share/runtime/arguments.cpp	Thu Jan 31 10:29:53 2019 -0500
+++ b/src/hotspot/share/runtime/arguments.cpp	Thu Jan 31 11:19:58 2019 -0500
@@ -579,7 +579,7 @@
   { "TraceClassUnloading",       LogLevel::Info,  true,  LOG_TAGS(class, unload) },
   { "TraceExceptions",           LogLevel::Info,  true,  LOG_TAGS(exceptions) },
   { "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) },
   { "TraceJVMTIObjectTagging",   LogLevel::Debug, true,  LOG_TAGS(jvmti, objecttagging) },
   { "TraceRedefineClasses",      LogLevel::Info,  false, LOG_TAGS(redefine, class) },
--- a/src/hotspot/share/runtime/init.cpp	Thu Jan 31 10:29:53 2019 -0500
+++ b/src/hotspot/share/runtime/init.cpp	Thu Jan 31 11:19:58 2019 -0500
@@ -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.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -166,6 +166,13 @@
   static bool destructorsCalled = false;
   if (!destructorsCalled) {
     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();
     if (log_is_enabled(Debug, safepoint, stats)) {
       // Print the collected safepoint statistics.
--- 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
--- a/src/hotspot/share/runtime/synchronizer.hpp	Thu Jan 31 10:29:53 2019 -0500
+++ b/src/hotspot/share/runtime/synchronizer.hpp	Thu Jan 31 11:19:58 2019 -0500
@@ -35,10 +35,11 @@
 class ThreadsList;
 
 struct DeflateMonitorCounters {
-  int nInuse;             // currently associated with objects
-  int nInCirculation;     // extant
-  int nScavenged;         // reclaimed (global and per-thread)
-  double perThreadTimes;  // per-thread scavenge times
+  int nInuse;              // currently associated with objects
+  int nInCirculation;      // extant
+  int nScavenged;          // reclaimed (global and per-thread)
+  int perThreadScavenged;  // per-thread scavenge total
+  double perThreadTimes;   // per-thread scavenge times
 };
 
 class ObjectSynchronizer : AllStatic {
@@ -153,6 +154,23 @@
   static void thread_local_used_oops_do(Thread* thread, OopClosure* f);
 
   // 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;
 
  private:
--- a/test/hotspot/jtreg/runtime/logging/MonitorInflationTest.java	Thu Jan 31 10:29:53 2019 -0500
+++ b/test/hotspot/jtreg/runtime/logging/MonitorInflationTest.java	Thu Jan 31 11:19:58 2019 -0500
@@ -24,7 +24,7 @@
 /*
  * @test
  * @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
  * @modules java.base/jdk.internal.misc
  *          java.management
@@ -50,7 +50,7 @@
     }
 
     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());
         analyzeOutputOn(pb);