8221350: more monitor logging updates from Async Monitor Deflation project
authordcubed
Tue, 26 Mar 2019 15:27:41 -0400
changeset 54291 e6c86f6012bf
parent 54290 8af48416e31f
child 54292 c31faeacf00a
8221350: more monitor logging updates from Async Monitor Deflation project Reviewed-by: dholmes, coleenp
src/hotspot/share/runtime/synchronizer.cpp
src/hotspot/share/runtime/synchronizer.hpp
src/hotspot/share/runtime/thread.cpp
--- a/src/hotspot/share/runtime/synchronizer.cpp	Tue Mar 26 18:42:10 2019 +0100
+++ b/src/hotspot/share/runtime/synchronizer.cpp	Tue Mar 26 15:27:41 2019 -0400
@@ -1270,6 +1270,21 @@
   }
 
   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 @@
   // 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 @@
 
   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 @@
   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 @@
     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 @@
 
   // 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:
--- a/src/hotspot/share/runtime/synchronizer.hpp	Tue Mar 26 18:42:10 2019 +0100
+++ b/src/hotspot/share/runtime/synchronizer.hpp	Tue Mar 26 15:27:41 2019 -0400
@@ -199,11 +199,11 @@
   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;
--- a/src/hotspot/share/runtime/thread.cpp	Tue Mar 26 18:42:10 2019 +0100
+++ b/src/hotspot/share/runtime/thread.cpp	Tue Mar 26 15:27:41 2019 -0400
@@ -4449,7 +4449,7 @@
 
 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