From 1992b69a4794d1f2f65eaeb6dbb1e1e23a948b6e Mon Sep 17 00:00:00 2001 From: Aleksey Shipilev Date: Thu, 9 Oct 2025 18:47:43 +0000 Subject: [PATCH] 8369283: Improve trace logs in safepoint machinery Reviewed-by: fbredberg, dholmes, rehn --- src/hotspot/share/runtime/safepoint.cpp | 31 ++++++++++++++++----- src/hotspot/share/runtime/sharedRuntime.cpp | 10 +++++-- 2 files changed, 31 insertions(+), 10 deletions(-) diff --git a/src/hotspot/share/runtime/safepoint.cpp b/src/hotspot/share/runtime/safepoint.cpp index 051cc6261f8..b44a43bbfb1 100644 --- a/src/hotspot/share/runtime/safepoint.cpp +++ b/src/hotspot/share/runtime/safepoint.cpp @@ -161,11 +161,6 @@ bool SafepointSynchronize::thread_not_running(ThreadSafepointState *cur_state) { if (!cur_state->is_running()) { return true; } - LogTarget(Trace, safepoint) lt; - if (lt.is_enabled()) { - LogStream ls(lt); - cur_state->print_on(&ls); - } return false; } @@ -223,6 +218,8 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no *initial_running = still_running; + log_trace(safepoint)("%d total threads, waiting for %d threads to block", nof_threads, still_running); + // If there is no thread still running, we are already done. if (still_running <= 0) { assert(tss_head == nullptr, "Must be empty"); @@ -233,6 +230,8 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no int64_t start_time = os::javaTimeNanos(); do { + log_trace(safepoint)("Checking thread status"); + // Check if this has taken too long: if (SafepointTimeout && safepoint_limit_time < os::javaTimeNanos()) { print_safepoint_timeout(); @@ -243,12 +242,16 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no while (cur_tss != nullptr) { assert(cur_tss->is_running(), "Illegal initial state"); if (thread_not_running(cur_tss)) { + log_trace(safepoint)("Thread " INTPTR_FORMAT " [%d] is now blocked", + p2i(cur_tss->thread()), cur_tss->thread()->osthread()->thread_id()); --still_running; *p_prev = nullptr; ThreadSafepointState *tmp = cur_tss; cur_tss = cur_tss->get_next(); tmp->set_next(nullptr); } else { + log_trace(safepoint)("Thread " INTPTR_FORMAT " [%d] is still running", + p2i(cur_tss->thread()), cur_tss->thread()->osthread()->thread_id()); *p_prev = cur_tss; p_prev = cur_tss->next_ptr(); cur_tss = cur_tss->get_next(); @@ -258,6 +261,7 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no DEBUG_ONLY(assert_list_is_valid(tss_head, still_running);) if (still_running > 0) { + log_trace(safepoint)("Waiting for %d threads to block", still_running); back_off(start_time); } @@ -332,10 +336,12 @@ void SafepointSynchronize::begin() { EventSafepointBegin begin_event; SafepointTracing::begin(VMThread::vm_op_type()); + log_trace(safepoint)("Suspending GC threads"); Universe::heap()->safepoint_synchronize_begin(); // By getting the Threads_lock, we assure that no threads are about to start or // exit. It is released again in SafepointSynchronize::end(). + log_trace(safepoint)("Blocking threads from starting/exiting"); Threads_lock->lock(); assert( _state == _not_synchronized, "trying to safepoint synchronize with wrong state"); @@ -344,8 +350,6 @@ void SafepointSynchronize::begin() { _nof_threads_hit_polling_page = 0; - log_debug(safepoint)("Safepoint synchronization initiated using %s wait barrier. (%d threads)", _wait_barrier->description(), nof_threads); - // Reset the count of active JNI critical threads _current_jni_active_count = 0; @@ -364,6 +368,7 @@ void SafepointSynchronize::begin() { int initial_running = 0; // Arms the safepoint, _current_jni_active_count and _waiting_to_block must be set before. + log_trace(safepoint)("Arming safepoint using %s wait barrier", _wait_barrier->description()); arm_safepoint(); // Will spin until all threads are safe. @@ -471,8 +476,10 @@ void SafepointSynchronize::end() { EventSafepointEnd event; assert(Thread::current()->is_VM_thread(), "Only VM thread can execute a safepoint"); + log_trace(safepoint)("Disarming safepoint"); disarm_safepoint(); + log_trace(safepoint)("Resuming GC threads"); Universe::heap()->safepoint_synchronize_end(); SafepointTracing::end(); @@ -551,6 +558,9 @@ void SafepointSynchronize::block(JavaThread *thread) { // Threads shouldn't block if they are in the middle of printing, but... ttyLocker::break_tty_lock_for_safepoint(os::current_thread_id()); + log_trace(safepoint)("Blocking thread " INTPTR_FORMAT " [%d]", + p2i(thread), thread->osthread()->thread_id()); + // Only bail from the block() call if the thread is gone from the // thread list; starting to exit should still block. if (thread->is_terminated()) { @@ -594,6 +604,9 @@ void SafepointSynchronize::block(JavaThread *thread) { // cross_modify_fence is done by SafepointMechanism::process_if_requested // which is the only caller here. + + log_trace(safepoint)("Unblocking thread " INTPTR_FORMAT " [%d]", + p2i(thread), thread->osthread()->thread_id()); } // ------------------------------------------------------------------------------------------------------ @@ -955,6 +968,7 @@ void SafepointTracing::begin(VM_Operation::VMOp_Type type) { _last_safepoint_end_time_ns = 0; RuntimeService::record_safepoint_begin(_last_app_time_ns); + log_debug(safepoint)("Safepoint synchronization initiated"); } void SafepointTracing::synchronized(int nof_threads, int nof_running, int traps) { @@ -963,10 +977,12 @@ void SafepointTracing::synchronized(int nof_threads, int nof_running, int traps) _nof_running = nof_running; _page_trap = traps; RuntimeService::record_safepoint_synchronized(_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns); + log_debug(safepoint)("Safepoint synchronization complete"); } void SafepointTracing::leave() { _last_safepoint_leave_time_ns = os::javaTimeNanos(); + log_debug(safepoint)("Leaving safepoint"); } void SafepointTracing::end() { @@ -1001,4 +1017,5 @@ void SafepointTracing::end() { ); RuntimeService::record_safepoint_end(_last_safepoint_end_time_ns - _last_safepoint_sync_time_ns); + log_debug(safepoint)("Safepoint complete"); } diff --git a/src/hotspot/share/runtime/sharedRuntime.cpp b/src/hotspot/share/runtime/sharedRuntime.cpp index a8c9a64d63a..efc47dd11c6 100644 --- a/src/hotspot/share/runtime/sharedRuntime.cpp +++ b/src/hotspot/share/runtime/sharedRuntime.cpp @@ -67,6 +67,7 @@ #include "runtime/java.hpp" #include "runtime/javaCalls.hpp" #include "runtime/jniHandles.inline.hpp" +#include "runtime/osThread.hpp" #include "runtime/perfData.hpp" #include "runtime/sharedRuntime.hpp" #include "runtime/stackWatermarkSet.hpp" @@ -677,10 +678,13 @@ address SharedRuntime::get_poll_stub(address pc) { "polling page safepoint stub not created yet"); stub = SharedRuntime::polling_page_safepoint_handler_blob()->entry_point(); } - log_debug(safepoint)("... found polling page %s exception at pc = " - INTPTR_FORMAT ", stub =" INTPTR_FORMAT, + log_trace(safepoint)("Polling page exception: thread = " INTPTR_FORMAT " [%d], pc = " + INTPTR_FORMAT " (%s), stub = " INTPTR_FORMAT, + p2i(Thread::current()), + Thread::current()->osthread()->thread_id(), + p2i(pc), at_poll_return ? "return" : "loop", - (intptr_t)pc, (intptr_t)stub); + p2i(stub)); return stub; }