8350313: Include timings for leaving safepoint in safepoint logging

Reviewed-by: shade, dholmes
This commit is contained in:
Xiaolong Peng 2025-02-26 17:29:12 +00:00 committed by Aleksey Shipilev
parent ec6624b54e
commit 9ec46968fb
2 changed files with 14 additions and 3 deletions

View File

@ -468,6 +468,8 @@ void SafepointSynchronize::disarm_safepoint() {
// operation has been carried out
void SafepointSynchronize::end() {
assert(Threads_lock->owned_by_self(), "must hold Threads_lock");
SafepointTracing::leave();
EventSafepointEnd event;
assert(Thread::current()->is_VM_thread(), "Only VM thread can execute a safepoint");
@ -862,6 +864,7 @@ void ThreadSafepointState::handle_polling_page_exception() {
jlong SafepointTracing::_last_safepoint_begin_time_ns = 0;
jlong SafepointTracing::_last_safepoint_sync_time_ns = 0;
jlong SafepointTracing::_last_safepoint_leave_time_ns = 0;
jlong SafepointTracing::_last_safepoint_end_time_ns = 0;
jlong SafepointTracing::_last_app_time_ns = 0;
int SafepointTracing::_nof_threads = 0;
@ -963,6 +966,10 @@ void SafepointTracing::synchronized(int nof_threads, int nof_running, int traps)
RuntimeService::record_safepoint_synchronized(_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns);
}
void SafepointTracing::leave() {
_last_safepoint_leave_time_ns = os::javaTimeNanos();
}
void SafepointTracing::end() {
_last_safepoint_end_time_ns = os::javaTimeNanos();
@ -981,12 +988,14 @@ void SafepointTracing::end() {
"Time since last: " JLONG_FORMAT " ns, "
"Reaching safepoint: " JLONG_FORMAT " ns, "
"At safepoint: " JLONG_FORMAT " ns, "
"Leaving safepoint: " JLONG_FORMAT " ns, "
"Total: " JLONG_FORMAT " ns",
VM_Operation::name(_current_type),
_last_app_time_ns,
_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns,
_last_safepoint_end_time_ns - _last_safepoint_sync_time_ns,
_last_safepoint_end_time_ns - _last_safepoint_begin_time_ns
_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns,
_last_safepoint_leave_time_ns - _last_safepoint_sync_time_ns,
_last_safepoint_end_time_ns - _last_safepoint_leave_time_ns,
_last_safepoint_end_time_ns - _last_safepoint_begin_time_ns
);
RuntimeService::record_safepoint_end(_last_safepoint_end_time_ns - _last_safepoint_sync_time_ns);

View File

@ -230,6 +230,7 @@ private:
// Absolute
static jlong _last_safepoint_begin_time_ns;
static jlong _last_safepoint_sync_time_ns;
static jlong _last_safepoint_leave_time_ns;
static jlong _last_safepoint_end_time_ns;
// Relative
@ -251,6 +252,7 @@ public:
static void begin(VM_Operation::VMOp_Type type);
static void synchronized(int nof_threads, int nof_running, int traps);
static void leave();
static void end();
static void statistics_exit_log();