# HG changeset patch # User dcubed # Date 1543361716 18000 # Node ID e7fdc9d9c37625f0582313d73faa825c6c6cd81d # Parent 10c6e9066819960cc601a82b489d37431d683163 8202415: Incorrect time logged for monitor deflation Summary: Add support for "deflating per-thread idle monitors" log mesgs. Reviewed-by: dholmes, coleenp diff -r 10c6e9066819 -r e7fdc9d9c376 src/hotspot/share/runtime/safepoint.cpp --- a/src/hotspot/share/runtime/safepoint.cpp Tue Nov 27 17:53:17 2018 -0500 +++ b/src/hotspot/share/runtime/safepoint.cpp Tue Nov 27 18:35:16 2018 -0500 @@ -616,7 +616,7 @@ 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); diff -r 10c6e9066819 -r e7fdc9d9c376 src/hotspot/share/runtime/synchronizer.cpp --- a/src/hotspot/share/runtime/synchronizer.cpp Tue Nov 27 17:53:17 2018 -0500 +++ b/src/hotspot/share/runtime/synchronizer.cpp Tue Nov 27 18:35:16 2018 -0500 @@ -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 @@ } 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::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 @@ 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 @@ 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) { diff -r 10c6e9066819 -r e7fdc9d9c376 src/hotspot/share/runtime/synchronizer.hpp --- a/src/hotspot/share/runtime/synchronizer.hpp Tue Nov 27 17:53:17 2018 -0500 +++ b/src/hotspot/share/runtime/synchronizer.hpp Tue Nov 27 18:35:16 2018 -0500 @@ -35,9 +35,10 @@ 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 { diff -r 10c6e9066819 -r e7fdc9d9c376 test/hotspot/jtreg/runtime/logging/SafepointCleanupTest.java --- a/test/hotspot/jtreg/runtime/logging/SafepointCleanupTest.java Tue Nov 27 17:53:17 2018 -0500 +++ b/test/hotspot/jtreg/runtime/logging/SafepointCleanupTest.java Tue Nov 27 18:35:16 2018 -0500 @@ -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 @@ 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");