8202415: Incorrect time logged for monitor deflation

Add support for "deflating per-thread idle monitors" log mesgs.

Reviewed-by: dholmes, coleenp

src/hotspot/share/runtime/safepoint.cpp

@@ -616,7 +616,7 @@ public:
     Threads::possibly_parallel_threads_do(true, &_cleanup_threads_cl);
 
     if (_subtasks.try_claim_task(SafepointSynchronize::SAFEPOINT_CLEANUP_DEFLATE_MONITORS)) {
-      const char* name = "deflating idle monitors";
+      const char* name = "deflating global idle monitors";
       EventSafepointCleanupTask event;
       TraceTime timer(name, TRACETIME_LOG(Info, safepoint, cleanup));
       ObjectSynchronizer::deflate_idle_monitors(_counters);

src/hotspot/share/runtime/synchronizer.cpp

@@ -45,6 +45,7 @@
 #include "runtime/stubRoutines.hpp"
 #include "runtime/synchronizer.hpp"
 #include "runtime/thread.inline.hpp"
+#include "runtime/timer.hpp"
 #include "runtime/vframe.hpp"
 #include "runtime/vmThread.hpp"
 #include "utilities/align.hpp"
@@ -1618,9 +1619,10 @@ int ObjectSynchronizer::deflate_monitor_list(ObjectMonitor** listHeadp,
 }
 
 void ObjectSynchronizer::prepare_deflate_idle_monitors(DeflateMonitorCounters* counters) {
-  counters->nInuse = 0;          // currently associated with objects
-  counters->nInCirculation = 0;  // extant
-  counters->nScavenged = 0;      // reclaimed
+  counters->nInuse = 0;            // currently associated with objects
+  counters->nInCirculation = 0;    // extant
+  counters->nScavenged = 0;        // reclaimed
+  counters->perThreadTimes = 0.0;  // per-thread scavenge times
 }
 
 void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters) {
@@ -1660,6 +1662,14 @@ void ObjectSynchronizer::deflate_idle_monitors(DeflateMonitorCounters* counters)
 }
 
 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);
+  }
+
   gMonitorFreeCount += counters->nScavenged;
 
   // Consider: audit gFreeList to ensure that gMonitorFreeCount and list agree.
@@ -1680,9 +1690,16 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
 
   ObjectMonitor * freeHeadp = NULL;  // Local SLL of scavenged monitors
   ObjectMonitor * freeTailp = NULL;
+  elapsedTimer timer;
+
+  if (log_is_enabled(Info, safepoint, cleanup)) {
+    timer.start();
+  }
 
   int deflated_count = deflate_monitor_list(thread->omInUseList_addr(), &freeHeadp, &freeTailp);
 
+  timer.stop();
+
   Thread::muxAcquire(&gListLock, "scavenge - return");
 
   // Adjust counters
@@ -1690,6 +1707,8 @@ void ObjectSynchronizer::deflate_thread_local_monitors(Thread* thread, DeflateMo
   thread->omInUseCount -= deflated_count;
   counters->nScavenged += deflated_count;
   counters->nInuse += thread->omInUseCount;
+  // 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) {

src/hotspot/share/runtime/synchronizer.hpp

@@ -35,9 +35,10 @@ class ObjectMonitor;
 class ThreadsList;
 
 struct DeflateMonitorCounters {
-  int nInuse;          // currently associated with objects
-  int nInCirculation;  // extant
-  int nScavenged;      // reclaimed
+  int nInuse;             // currently associated with objects
+  int nInCirculation;     // extant
+  int nScavenged;         // reclaimed
+  double perThreadTimes;  // per-thread scavenge times
 };
 
 class ObjectSynchronizer : AllStatic {

test/hotspot/jtreg/runtime/logging/SafepointCleanupTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2016, 2018, 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
@@ -39,7 +39,8 @@ public class SafepointCleanupTest {
         OutputAnalyzer output = new OutputAnalyzer(pb.start());
         output.shouldContain("[safepoint,cleanup]");
         output.shouldContain("safepoint cleanup tasks");
-        output.shouldContain("deflating idle monitors");
+        output.shouldContain("deflating global idle monitors");
+        output.shouldContain("deflating per-thread idle monitors");
         output.shouldContain("updating inline caches");
         output.shouldContain("compilation policy safepoint handler");
         output.shouldContain("purging class loader data graph");