src/hotspot/share/runtime/synchronizer.cpp

rev 54108 : Add logging to ObjectSynchronizer::omFlush(), add global count logging at Info level to ObjectSynchronizer::finish_deflate_idle_monitors(); for monitorinflation logging, switch from cumulative "deflating per-thread idle monitors" mesgs to per-thread "deflating per-thread idle monitors" mesgs; fix timer bug in deflate_thread_local_monitors() where time to acquire gListLock wasn't counted; fix misc typos.

@@ -1268,10 +1268,25 @@
     gOmInUseList = inUseList;
     gOmInUseCount += inUseTally;
   }
 
   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,
                                        const oop obj,
                                        ObjectSynchronizer::InflateCause cause) {

@@ -1663,28 +1678,22 @@
   // 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;
 
   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
 
   OM_PERFDATA_OP(Deflations, inc(counters->nScavenged));

@@ -1706,22 +1715,18 @@
     timer.start();
   }
 
   int deflated_count = deflate_monitor_list(thread->omInUseList_addr(), &freeHeadp, &freeTailp);
 
-  timer.stop();
-
-  Thread::muxAcquire(&gListLock, "deflate_thread_local_monitors");
+  Thread::muxAcquire(&gListLock, "deflate_thread_local_monitors(1)");
 
   // Adjust counters
   counters->nInCirculation += thread->omInUseCount;
   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();
 
   // Move the scavenged monitors back to the global free list.
   if (freeHeadp != NULL) {
     guarantee(freeTailp != NULL && deflated_count > 0, "invariant");
     assert(freeTailp->FreeNext == NULL, "invariant");

@@ -1729,10 +1734,32 @@
     // constant-time list splice - prepend scavenged segment to gFreeList
     freeTailp->FreeNext = gFreeList;
     gFreeList = freeHeadp;
   }
   Thread::muxRelease(&gListLock);
+
+  timer.stop();
+  if (log_is_enabled(Info, safepoint, cleanup)) {
+    // Only safepoint logging cares about cumulative perThreadTimes
+    // and we don't count this muxAcquire() that we have to do in
+    // order to safely update perThreadTimes.
+    Thread::muxAcquire(&gListLock, "deflate_thread_local_monitors(2)");
+    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
 
 // Iterate through monitor cache and attempt to release thread's monitors