stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

6933402: RFE: Improve PrintSafepointStatistics output to track cleanup time

Browse Source 
Improve the usability of safepoint statistics data. See bug evaluation for more details.

Reviewed-by: ysr, dholmes
This commit is contained in:
Xiaobin Lu 2010-03-10 21:42:26 -08:00
parent 13ac3be829
commit 8742fc8e62
2 changed files with 96 additions and 66 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

136
hotspot/src/share/vm/runtime/safepoint.cpp
View File

@ -30,8 +30,8 @@
SafepointSynchronize::SynchronizeState volatile SafepointSynchronize::_state = SafepointSynchronize::_not_synchronized; SafepointSynchronize::SynchronizeState volatile SafepointSynchronize::_state = SafepointSynchronize::_not_synchronized;
volatile int SafepointSynchronize::_waiting_to_block = 0; volatile int SafepointSynchronize::_waiting_to_block = 0;
jlong SafepointSynchronize::_last_safepoint = 0;
volatile int SafepointSynchronize::_safepoint_counter = 0; volatile int SafepointSynchronize::_safepoint_counter = 0;
long SafepointSynchronize::_end_of_last_safepoint = 0;
static volatile int PageArmed = 0 ; // safepoint polling page is RO|RW vs PROT_NONE static volatile int PageArmed = 0 ; // safepoint polling page is RO|RW vs PROT_NONE
static volatile int TryingToBlock = 0 ; // proximate value -- for advisory use only static volatile int TryingToBlock = 0 ; // proximate value -- for advisory use only
static bool timeout_error_printed = false; static bool timeout_error_printed = false;
@ -42,7 +42,10 @@ void SafepointSynchronize::begin() {
Thread* myThread = Thread::current(); Thread* myThread = Thread::current();
assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint"); assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint");
_last_safepoint = os::javaTimeNanos(); if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) {
_safepoint_begin_time = os::javaTimeNanos();
_ts_of_current_safepoint = tty->time_stamp().seconds();
}
#ifndef SERIALGC #ifndef SERIALGC
if (UseConcMarkSweepGC) { if (UseConcMarkSweepGC) {
@ -320,6 +323,11 @@ void SafepointSynchronize::begin() {
// Call stuff that needs to be run when a safepoint is just about to be completed // Call stuff that needs to be run when a safepoint is just about to be completed
do_cleanup_tasks(); do_cleanup_tasks();
if (PrintSafepointStatistics) {
// Record how much time spend on the above cleanup tasks
update_statistics_on_cleanup_end(os::javaTimeNanos());
}
} }
} }
@ -411,6 +419,9 @@ void SafepointSynchronize::end() {
ConcurrentGCThread::safepoint_desynchronize(); ConcurrentGCThread::safepoint_desynchronize();
} }
#endif // SERIALGC #endif // SERIALGC
// record this time so VMThread can keep track how much time has elasped
// since last safepoint.
_end_of_last_safepoint = os::javaTimeMillis();
} }
bool SafepointSynchronize::is_cleanup_needed() { bool SafepointSynchronize::is_cleanup_needed() {
@ -445,24 +456,23 @@ void CounterDecay::decay() {
// Various cleaning tasks that should be done periodically at safepoints // Various cleaning tasks that should be done periodically at safepoints
void SafepointSynchronize::do_cleanup_tasks() { void SafepointSynchronize::do_cleanup_tasks() {
jlong cleanup_time; {
TraceTime t1("deflating idle monitors", TraceSafepoint);
// Update fat-monitor pool, since this is a safepoint. ObjectSynchronizer::deflate_idle_monitors();
if (TraceSafepoint) { }
cleanup_time = os::javaTimeNanos();
{
TraceTime t2("updating inline caches", TraceSafepoint);
InlineCacheBuffer::update_inline_caches();
} }
ObjectSynchronizer::deflate_idle_monitors();
InlineCacheBuffer::update_inline_caches();
if(UseCounterDecay && CounterDecay::is_decay_needed()) { if(UseCounterDecay && CounterDecay::is_decay_needed()) {
TraceTime t3("decaying counter", TraceSafepoint);
CounterDecay::decay(); CounterDecay::decay();
} }
NMethodSweeper::sweep();
if (TraceSafepoint) { TraceTime t4("sweeping nmethods", TraceSafepoint);
tty->print_cr("do_cleanup_tasks takes "INT64_FORMAT_W(6) "ms", NMethodSweeper::sweep();
(os::javaTimeNanos() - cleanup_time) / MICROUNITS);
}
} }
@ -979,17 +989,32 @@ void ThreadSafepointState::handle_polling_page_exception() {
// Statistics & Instrumentations // Statistics & Instrumentations
// //
SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL; SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL;
jlong SafepointSynchronize::_safepoint_begin_time = 0;
int SafepointSynchronize::_cur_stat_index = 0; int SafepointSynchronize::_cur_stat_index = 0;
julong SafepointSynchronize::_safepoint_reasons[VM_Operation::VMOp_Terminating]; julong SafepointSynchronize::_safepoint_reasons[VM_Operation::VMOp_Terminating];
julong SafepointSynchronize::_coalesced_vmop_count = 0; julong SafepointSynchronize::_coalesced_vmop_count = 0;
jlong SafepointSynchronize::_max_sync_time = 0; jlong SafepointSynchronize::_max_sync_time = 0;
jlong SafepointSynchronize::_max_vmop_time = 0;
float SafepointSynchronize::_ts_of_current_safepoint = 0.0f;
// last_safepoint_start_time records the start time of last safepoint. static jlong cleanup_end_time = 0;
static jlong last_safepoint_start_time = 0;
static jlong sync_end_time = 0;
static bool need_to_track_page_armed_status = false; static bool need_to_track_page_armed_status = false;
static bool init_done = false; static bool init_done = false;
// Helper method to print the header.
static void print_header() {
tty->print(" vmop "
"[threads: total initially_running wait_to_block] ");
tty->print("[time: spin block sync cleanup vmop] ");
// no page armed status printed out if it is always armed.
if (need_to_track_page_armed_status) {
tty->print("page_armed ");
}
tty->print_cr("page_trap_count");
}
void SafepointSynchronize::deferred_initialize_stat() { void SafepointSynchronize::deferred_initialize_stat() {
if (init_done) return; if (init_done) return;
@ -1016,19 +1041,6 @@ void SafepointSynchronize::deferred_initialize_stat() {
if (UseCompilerSafepoints && DeferPollingPageLoopCount >= 0) { if (UseCompilerSafepoints && DeferPollingPageLoopCount >= 0) {
need_to_track_page_armed_status = true; need_to_track_page_armed_status = true;
} }
tty->print(" vmop_name "
"[threads: total initially_running wait_to_block] ");
tty->print("[time: spin block sync] "
"[vmop_time time_elapsed] ");
// no page armed status printed out if it is always armed.
if (need_to_track_page_armed_status) {
tty->print("page_armed ");
}
tty->print_cr("page_trap_count");
init_done = true; init_done = true;
} }
@ -1036,6 +1048,8 @@ void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) {
assert(init_done, "safepoint statistics array hasn't been initialized"); assert(init_done, "safepoint statistics array hasn't been initialized");
SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
spstat->_time_stamp = _ts_of_current_safepoint;
VM_Operation *op = VMThread::vm_operation(); VM_Operation *op = VMThread::vm_operation();
spstat->_vmop_type = (op != NULL ? op->type() : -1); spstat->_vmop_type = (op != NULL ? op->type() : -1);
if (op != NULL) { if (op != NULL) {
@ -1054,14 +1068,6 @@ void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) {
} else { } else {
spstat->_time_to_spin = 0; spstat->_time_to_spin = 0;
} }
if (last_safepoint_start_time == 0) {
spstat->_time_elapsed_since_last_safepoint = 0;
} else {
spstat->_time_elapsed_since_last_safepoint = _last_safepoint -
last_safepoint_start_time;
}
last_safepoint_start_time = _last_safepoint;
} }
void SafepointSynchronize::update_statistics_on_spin_end() { void SafepointSynchronize::update_statistics_on_spin_end() {
@ -1097,18 +1103,31 @@ void SafepointSynchronize::update_statistics_on_sync_end(jlong end_time) {
// Records the end time of sync which will be used to calculate the total // Records the end time of sync which will be used to calculate the total
// vm operation time. Again, the real time spending in syncing will be deducted // vm operation time. Again, the real time spending in syncing will be deducted
// from the start of the sync time later when end_statistics is called. // from the start of the sync time later when end_statistics is called.
spstat->_time_to_sync = end_time - _last_safepoint; spstat->_time_to_sync = end_time - _safepoint_begin_time;
if (spstat->_time_to_sync > _max_sync_time) { if (spstat->_time_to_sync > _max_sync_time) {
_max_sync_time = spstat->_time_to_sync; _max_sync_time = spstat->_time_to_sync;
} }
sync_end_time = end_time;
spstat->_time_to_do_cleanups = end_time;
}
void SafepointSynchronize::update_statistics_on_cleanup_end(jlong end_time) {
SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
// Record how long spent in cleanup tasks.
spstat->_time_to_do_cleanups = end_time - spstat->_time_to_do_cleanups;
cleanup_end_time = end_time;
} }
void SafepointSynchronize::end_statistics(jlong vmop_end_time) { void SafepointSynchronize::end_statistics(jlong vmop_end_time) {
SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
// Update the vm operation time. // Update the vm operation time.
spstat->_time_to_exec_vmop = vmop_end_time - sync_end_time; spstat->_time_to_exec_vmop = vmop_end_time - cleanup_end_time;
if (spstat->_time_to_exec_vmop > _max_vmop_time) {
_max_vmop_time = spstat->_time_to_exec_vmop;
}
// Only the sync time longer than the specified // Only the sync time longer than the specified
// PrintSafepointStatisticsTimeout will be printed out right away. // PrintSafepointStatisticsTimeout will be printed out right away.
// By default, it is -1 meaning all samples will be put into the list. // By default, it is -1 meaning all samples will be put into the list.
@ -1119,40 +1138,42 @@ void SafepointSynchronize::end_statistics(jlong vmop_end_time) {
} else { } else {
// The safepoint statistics will be printed out when the _safepoin_stats // The safepoint statistics will be printed out when the _safepoin_stats
// array fills up. // array fills up.
if (_cur_stat_index != PrintSafepointStatisticsCount - 1) { if (_cur_stat_index == PrintSafepointStatisticsCount - 1) {
_cur_stat_index ++;
} else {
print_statistics(); print_statistics();
_cur_stat_index = 0; _cur_stat_index = 0;
tty->print_cr(""); } else {
_cur_stat_index++;
} }
} }
} }
void SafepointSynchronize::print_statistics() { void SafepointSynchronize::print_statistics() {
int index;
SafepointStats* sstats = _safepoint_stats; SafepointStats* sstats = _safepoint_stats;
for (index = 0; index <= _cur_stat_index; index++) { for (int index = 0; index <= _cur_stat_index; index++) {
if (index % 30 == 0) {
print_header();
}
sstats = &_safepoint_stats[index]; sstats = &_safepoint_stats[index];
tty->print("%-28s [" tty->print("%.3f: ", sstats->_time_stamp);
tty->print("%-26s ["
INT32_FORMAT_W(8)INT32_FORMAT_W(11)INT32_FORMAT_W(15) INT32_FORMAT_W(8)INT32_FORMAT_W(11)INT32_FORMAT_W(15)
"] ", " ] ",
sstats->_vmop_type == -1 ? "no vm operation" : sstats->_vmop_type == -1 ? "no vm operation" :
VM_Operation::name(sstats->_vmop_type), VM_Operation::name(sstats->_vmop_type),
sstats->_nof_total_threads, sstats->_nof_total_threads,
sstats->_nof_initial_running_threads, sstats->_nof_initial_running_threads,
sstats->_nof_threads_wait_to_block); sstats->_nof_threads_wait_to_block);
// "/ MICROUNITS " is to convert the unit from nanos to millis. // "/ MICROUNITS " is to convert the unit from nanos to millis.
tty->print(" [" tty->print(" ["
INT64_FORMAT_W(6)INT64_FORMAT_W(6)INT64_FORMAT_W(6) INT64_FORMAT_W(6)INT64_FORMAT_W(6)
"] " INT64_FORMAT_W(6)INT64_FORMAT_W(6)
"["INT64_FORMAT_W(6)INT64_FORMAT_W(9) "] ", INT64_FORMAT_W(6)" ] ",
sstats->_time_to_spin / MICROUNITS, sstats->_time_to_spin / MICROUNITS,
sstats->_time_to_wait_to_block / MICROUNITS, sstats->_time_to_wait_to_block / MICROUNITS,
sstats->_time_to_sync / MICROUNITS, sstats->_time_to_sync / MICROUNITS,
sstats->_time_to_exec_vmop / MICROUNITS, sstats->_time_to_do_cleanups / MICROUNITS,
sstats->_time_elapsed_since_last_safepoint / MICROUNITS); sstats->_time_to_exec_vmop / MICROUNITS);
if (need_to_track_page_armed_status) { if (need_to_track_page_armed_status) {
tty->print(INT32_FORMAT" ", sstats->_page_armed); tty->print(INT32_FORMAT" ", sstats->_page_armed);
@ -1174,7 +1195,7 @@ void SafepointSynchronize::print_stat_on_exit() {
// don't print it out. // don't print it out.
// Approximate the vm op time. // Approximate the vm op time.
_safepoint_stats[_cur_stat_index]._time_to_exec_vmop = _safepoint_stats[_cur_stat_index]._time_to_exec_vmop =
os::javaTimeNanos() - sync_end_time; os::javaTimeNanos() - cleanup_end_time;
if ( PrintSafepointStatisticsTimeout < 0 || if ( PrintSafepointStatisticsTimeout < 0 ||
spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) { spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) {
@ -1203,6 +1224,9 @@ void SafepointSynchronize::print_stat_on_exit() {
_coalesced_vmop_count); _coalesced_vmop_count);
tty->print_cr("Maximum sync time "INT64_FORMAT_W(5)" ms", tty->print_cr("Maximum sync time "INT64_FORMAT_W(5)" ms",
_max_sync_time / MICROUNITS); _max_sync_time / MICROUNITS);
tty->print_cr("Maximum vm operation time (except for Exit VM operation) "
INT64_FORMAT_W(5)" ms",
_max_vmop_time / MICROUNITS);
} }
// ------------------------------------------------------------------------------------------------ // ------------------------------------------------------------------------------------------------

26
hotspot/src/share/vm/runtime/safepoint.hpp
View File

@ -65,6 +65,7 @@ class SafepointSynchronize : AllStatic {
}; };
typedef struct { typedef struct {
float _time_stamp; // record when the current safepoint occurs in seconds
int _vmop_type; // type of VM operation triggers the safepoint int _vmop_type; // type of VM operation triggers the safepoint
int _nof_total_threads; // total number of Java threads int _nof_total_threads; // total number of Java threads
int _nof_initial_running_threads; // total number of initially seen running threads int _nof_initial_running_threads; // total number of initially seen running threads
@ -73,14 +74,14 @@ class SafepointSynchronize : AllStatic {
int _nof_threads_hit_page_trap; // total number of threads hitting the page trap int _nof_threads_hit_page_trap; // total number of threads hitting the page trap
jlong _time_to_spin; // total time in millis spent in spinning jlong _time_to_spin; // total time in millis spent in spinning
jlong _time_to_wait_to_block; // total time in millis spent in waiting for to block jlong _time_to_wait_to_block; // total time in millis spent in waiting for to block
jlong _time_to_do_cleanups; // total time in millis spent in performing cleanups
jlong _time_to_sync; // total time in millis spent in getting to _synchronized jlong _time_to_sync; // total time in millis spent in getting to _synchronized
jlong _time_to_exec_vmop; // total time in millis spent in vm operation itself jlong _time_to_exec_vmop; // total time in millis spent in vm operation itself
jlong _time_elapsed_since_last_safepoint; // time elasped since last safepoint
} SafepointStats; } SafepointStats;
private: private:
static volatile SynchronizeState _state; // Threads might read this flag directly, without acquireing the Threads_lock static volatile SynchronizeState _state; // Threads might read this flag directly, without acquireing the Threads_lock
static volatile int _waiting_to_block; // No. of threads we are waiting for to block. static volatile int _waiting_to_block; // number of threads we are waiting for to block
// This counter is used for fast versions of jni_Get<Primitive>Field. // This counter is used for fast versions of jni_Get<Primitive>Field.
// An even value means there is no ongoing safepoint operations. // An even value means there is no ongoing safepoint operations.
@ -91,19 +92,22 @@ class SafepointSynchronize : AllStatic {
public: public:
static volatile int _safepoint_counter; static volatile int _safepoint_counter;
private: private:
static long _end_of_last_safepoint; // Time of last safepoint in milliseconds
static jlong _last_safepoint; // Time of last safepoint
// statistics // statistics
static SafepointStats* _safepoint_stats; // array of SafepointStats struct static jlong _safepoint_begin_time; // time when safepoint begins
static int _cur_stat_index; // current index to the above array static SafepointStats* _safepoint_stats; // array of SafepointStats struct
static julong _safepoint_reasons[]; // safepoint count for each VM op static int _cur_stat_index; // current index to the above array
static julong _coalesced_vmop_count;// coalesced vmop count static julong _safepoint_reasons[]; // safepoint count for each VM op
static jlong _max_sync_time; // maximum sync time in nanos static julong _coalesced_vmop_count; // coalesced vmop count
static jlong _max_sync_time; // maximum sync time in nanos
static jlong _max_vmop_time; // maximum vm operation time in nanos
static float _ts_of_current_safepoint; // time stamp of current safepoint in seconds
static void begin_statistics(int nof_threads, int nof_running); static void begin_statistics(int nof_threads, int nof_running);
static void update_statistics_on_spin_end(); static void update_statistics_on_spin_end();
static void update_statistics_on_sync_end(jlong end_time); static void update_statistics_on_sync_end(jlong end_time);
static void update_statistics_on_cleanup_end(jlong end_time);
static void end_statistics(jlong end_time); static void end_statistics(jlong end_time);
static void print_statistics(); static void print_statistics();
inline static void inc_page_trap_count() { inline static void inc_page_trap_count() {
@ -140,7 +144,9 @@ public:
static void handle_polling_page_exception(JavaThread *thread); static void handle_polling_page_exception(JavaThread *thread);
// VM Thread interface for determining safepoint rate // VM Thread interface for determining safepoint rate
static long last_non_safepoint_interval() { return os::javaTimeMillis() - _last_safepoint; } static long last_non_safepoint_interval() {
return os::javaTimeMillis() - _end_of_last_safepoint;
}
static bool is_cleanup_needed(); static bool is_cleanup_needed();
static void do_cleanup_tasks(); static void do_cleanup_tasks();