8325883: Move Monitor Deflation reporting out of safepoint cleanup

Reviewed-by: eosterlund, dcubed

src/hotspot/share/runtime/monitorDeflationThread.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2020, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2020, 2024, 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
@@ -26,6 +26,8 @@
 #include "classfile/javaClasses.hpp"
 #include "classfile/vmClasses.hpp"
 #include "classfile/vmSymbols.hpp"
+#include "logging/log.hpp"
+#include "logging/logStream.hpp"
 #include "memory/universe.hpp"
 #include "runtime/interfaceSupport.inline.hpp"
 #include "runtime/java.hpp"
@@ -95,5 +97,12 @@ void MonitorDeflationThread::monitor_deflation_thread_entry(JavaThread* jt, TRAP
     }
 
     (void)ObjectSynchronizer::deflate_idle_monitors();
+
+    if (log_is_enabled(Debug, monitorinflation)) {
+      // The VMThread calls do_final_audit_and_print_stats() which calls
+      // audit_and_print_stats() at the Info level at VM exit time.
+      LogStreamHandle(Debug, monitorinflation) ls;
+      ObjectSynchronizer::audit_and_print_stats(&ls, false /* on_exit */);
+    }
   }
 }

src/hotspot/share/runtime/safepoint.cpp

@@ -567,12 +567,6 @@ void SafepointSynchronize::do_cleanup_tasks() {
     // Serial cleanup using VMThread.
     cleanup.work(0);
   }
-
-  if (log_is_enabled(Debug, monitorinflation)) {
-    // The VMThread calls do_final_audit_and_print_stats() which calls
-    // audit_and_print_stats() at the Info level at VM exit time.
-    ObjectSynchronizer::audit_and_print_stats(false /* on_exit */);
-  }
 }
 
 // Methods for determining if a JavaThread is safepoint safe.

src/hotspot/share/runtime/synchronizer.cpp

@@ -1950,38 +1950,18 @@ void ObjectSynchronizer::do_final_audit_and_print_stats() {
   log_info(monitorinflation)("Starting the final audit.");
 
   if (log_is_enabled(Info, monitorinflation)) {
-    // The other audit_and_print_stats() call is done at the Debug
-    // level at a safepoint in SafepointSynchronize::do_cleanup_tasks.
-    audit_and_print_stats(true /* on_exit */);
+    LogStreamHandle(Info, monitorinflation) ls;
+    audit_and_print_stats(&ls, true /* on_exit */);
   }
 }
 
-// This function can be called at a safepoint or it can be called when
-// we are trying to exit the VM. When we are trying to exit the VM, the
-// list walker functions can run in parallel with the other list
-// operations so spin-locking is used for safety.
-//
+// This function can be called by the MonitorDeflationThread or it can be called when
+// we are trying to exit the VM. The list walker functions can run in parallel with
+// the other list operations.
 // Calls to this function can be added in various places as a debugging
-// aid; pass 'true' for the 'on_exit' parameter to have in-use monitor
-// details logged at the Info level and 'false' for the 'on_exit'
-// parameter to have in-use monitor details logged at the Trace level.
+// aid.
 //
-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 = nullptr;
-  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 != nullptr, "sanity check");
-
+void ObjectSynchronizer::audit_and_print_stats(outputStream* ls, bool on_exit) {
   int error_cnt = 0;
 
   ls->print_cr("Checking in_use_list:");
@@ -1993,12 +1973,14 @@ void ObjectSynchronizer::audit_and_print_stats(bool on_exit) {
     log_error(monitorinflation)("found in_use_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 /* log_all */);
+  // When exiting, only log the interesting entries at the Info level.
+  // When called at intervals by the MonitorDeflationThread, log output
+  // at the Trace level since there can be a lot of it.
+  if (!on_exit && log_is_enabled(Trace, monitorinflation)) {
+    LogStreamHandle(Trace, monitorinflation) ls_tr;
+    log_in_use_monitor_details(&ls_tr, true /* log_all */);
+  } else if (on_exit) {
+    log_in_use_monitor_details(ls, false /* log_all */);
   }
 
   ls->flush();

src/hotspot/share/runtime/synchronizer.hpp

@@ -185,7 +185,7 @@ class ObjectSynchronizer : AllStatic {
   static jlong time_since_last_async_deflation_ms();
 
   // debugging
-  static void audit_and_print_stats(bool on_exit);
+  static void audit_and_print_stats(outputStream* out, bool on_exit);
   static void chk_in_use_list(outputStream* out, int* error_cnt_p);
   static void chk_in_use_entry(ObjectMonitor* n, outputStream* out,
                                int* error_cnt_p);

test/hotspot/jtreg/runtime/Monitor/MonitorUsedDeflationThresholdTest.java

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2021, 2023, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2021, 2024, 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
@@ -70,57 +70,99 @@ public static void usage() {
                            "MonitorUsedDeflationThresholdTest inflate_count");
     }
 
+
+    private static ProcessBuilder processCommand(String loggingLevel) {
+        return ProcessTools.createLimitedTestJavaProcessBuilder(
+            // Test doesn't need much Java heap:
+            "-Xmx100M",
+            // AvgMonitorsPerThreadEstimate == 1 means we'll start with
+            // an in_use_list_ceiling of <n-threads> plus a couple of
+            // of monitors for threads that call Object.wait().
+            "-XX:+UnlockDiagnosticVMOptions",
+            "-XX:AvgMonitorsPerThreadEstimate=1",
+            // MonitorUsedDeflationThreshold == 10 means we'll request
+            // deflations when 10% of monitors are used rather than the
+            // default 90%. This should allow the test to tolerate a burst
+            // of used monitors by threads not under this test's control.
+            "-XX:MonitorUsedDeflationThreshold=10",
+            // Enable monitorinflation logging so we can see that
+            // MonitorUsedDeflationThreshold and
+            // NoAsyncDeflationProgressMaxoption are working.
+            "-Xlog:monitorinflation=" + loggingLevel,
+            // Run the test with inflate_count == 33 since that
+            // reproduced the bug with JDK13. With inflate_count == 33, an
+            // initial ceiling == 12 and MonitorUsedDeflationThreshold == 10,
+            // we should hit NoAsyncDeflationProgressMax at least 3 times.
+            "MonitorUsedDeflationThresholdTest", "33");
+    }
+
+    private static void testProcess1() throws Exception {
+        ProcessBuilder pb = processCommand("info");
+
+        OutputAnalyzer output_detail = new OutputAnalyzer(pb.start());
+        output_detail.shouldHaveExitValue(0);
+
+        // This mesg means:
+        // - AvgMonitorsPerThreadEstimate == 1 reduced in_use_list_ceiling
+        //   to a small number.
+        // - and we crossed MonitorUsedDeflationThreshold:
+        output_detail.shouldMatch("begin deflating: .*");
+        System.out.println("Found beginning of a deflation cycle.");
+
+        // This mesg means we hit NoAsyncDeflationProgressMax and
+        // had to adjust the in_use_list_ceiling:
+        String too_many = output_detail.firstMatch("Too many deflations without progress; .*", 0);
+        if (too_many == null) {
+            output_detail.reportDiagnosticSummary();
+            throw new RuntimeException("Did not find too_many string in output.\n");
+        }
+        System.out.println("too_many='" + too_many + "'");
+        // Uncomment the following line for dumping test output in passing runs:
+        // output_detail.reportDiagnosticSummary();
+
+        System.out.println("PASSED.");
+    }
+
+    private static void testProcess2() throws Exception {
+        ProcessBuilder pb = processCommand("debug");
+        OutputAnalyzer output_detail = new OutputAnalyzer(pb.start());
+        output_detail.shouldHaveExitValue(0);
+
+        // Test that logging reports in_use_list with each iteration of the deflation thread in debug mode.
+        // but not monitor details with each report
+        output_detail.shouldMatch(   ".debug..monitorinflation. Checking in_use_list:");
+        output_detail.shouldNotMatch(".debug..monitorinflation. .*is_busy");
+
+        // Reporting stats at exit is in Info mode, and contains monitor details
+        output_detail.shouldMatch(".info ..monitorinflation. Checking in_use_list:");
+        output_detail.shouldMatch(".info ..monitorinflation. .*is_busy");
+
+        System.out.println("PASSED.");
+    }
+
+    private static void testProcess3() throws Exception {
+        ProcessBuilder pb = processCommand("trace");
+        OutputAnalyzer output_detail = new OutputAnalyzer(pb.start());
+        output_detail.shouldHaveExitValue(0);
+
+        // Test that logging reports in_use_list with each iteration of the deflation thread in debug mode.
+        // and monitor details with each report
+        output_detail.shouldMatch(".debug..monitorinflation. Checking in_use_list:");
+        output_detail.shouldMatch(".trace..monitorinflation. .*is_busy");
+
+        // Reporting stats at exit is in Info mode, and contains monitor details
+        output_detail.shouldMatch(".info ..monitorinflation. Checking in_use_list:");
+        output_detail.shouldMatch(".info ..monitorinflation. .*is_busy");
+
+        System.out.println("PASSED.");
+    }
+
     public static void main(String[] args) throws Exception {
         if (args.length == 0) {
-            // Without args we invoke the test in a java sub-process:
-            ProcessBuilder pb = ProcessTools.createLimitedTestJavaProcessBuilder(
-                // Test doesn't need much Java heap:
-                "-Xmx100M",
-                // AvgMonitorsPerThreadEstimate == 1 means we'll start with
-                // an in_use_list_ceiling of <n-threads> plus a couple of
-                // of monitors for threads that call Object.wait().
-                "-XX:+UnlockDiagnosticVMOptions",
-                "-XX:AvgMonitorsPerThreadEstimate=1",
-                // MonitorUsedDeflationThreshold == 10 means we'll request
-                // deflations when 10% of monitors are used rather than the
-                // default 90%. This should allow the test to tolerate a burst
-                // of used monitors by threads not under this test's control.
-                "-XX:MonitorUsedDeflationThreshold=10",
-                // Enable monitorinflation logging so we can see that
-                // MonitorUsedDeflationThreshold and
-                // NoAsyncDeflationProgressMaxoption are working.
-                "-Xlog:monitorinflation=info",
-                // Enable some safepoint logging for diagnostic purposes.
-                "-Xlog:safepoint+cleanup=info",
-                "-Xlog:safepoint+stats=debug",
-                // Run the test with inflate_count == 33 since that
-                // reproduced the bug with JDK13. With inflate_count == 33, an
-                // initial ceiling == 12 and MonitorUsedDeflationThreshold == 10,
-                // we should hit NoAsyncDeflationProgressMax at least 3 times.
-                "MonitorUsedDeflationThresholdTest", "33");
-
-            OutputAnalyzer output_detail = new OutputAnalyzer(pb.start());
-            output_detail.shouldHaveExitValue(0);
-
-            // This mesg means:
-            // - AvgMonitorsPerThreadEstimate == 1 reduced in_use_list_ceiling
-            //   to a small number.
-            // - and we crossed MonitorUsedDeflationThreshold:
-            output_detail.shouldMatch("begin deflating: .*");
-            System.out.println("Found beginning of a deflation cycle.");
-
-            // This mesg means we hit NoAsyncDeflationProgressMax and
-            // had to adjust the in_use_list_ceiling:
-            String too_many = output_detail.firstMatch("Too many deflations without progress; .*", 0);
-            if (too_many == null) {
-                output_detail.reportDiagnosticSummary();
-                throw new RuntimeException("Did not find too_many string in output.\n");
-            }
-            System.out.println("too_many='" + too_many + "'");
-            // Uncomment the following line for dumping test output in passing runs:
-            // output_detail.reportDiagnosticSummary();
-
-            System.out.println("PASSED.");
+            // Without args we invoke the tests in a java sub-process.
+            testProcess1();
+            testProcess2();
+            testProcess3();
             return;
         }
         // else we are the exec'd java subprocess, so run the actual test: