8325883: Move Monitor Deflation reporting out of safepoint cleanup

Reviewed-by: eosterlund, dcubed
This commit is contained in:
Coleen Phillimore 2024-03-28 19:30:55 +00:00
parent 7ac2f914aa
commit 341dd57fa1
5 changed files with 118 additions and 91 deletions

@ -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 */);
}
}
}

@ -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.

@ -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();

@ -185,7 +185,7 @@ public:
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);

@ -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 class MonitorUsedDeflationThresholdTest {
"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: