diff -r 5bce37d77dde -r f86707fd195a hotspot/src/share/vm/runtime/safepoint.cpp --- a/hotspot/src/share/vm/runtime/safepoint.cpp Tue Mar 02 12:09:40 2010 -0800 +++ b/hotspot/src/share/vm/runtime/safepoint.cpp Wed Mar 10 21:42:26 2010 -0800 @@ -30,8 +30,8 @@ SafepointSynchronize::SynchronizeState volatile SafepointSynchronize::_state = SafepointSynchronize::_not_synchronized; volatile int SafepointSynchronize::_waiting_to_block = 0; -jlong SafepointSynchronize::_last_safepoint = 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 TryingToBlock = 0 ; // proximate value -- for advisory use only static bool timeout_error_printed = false; @@ -42,7 +42,10 @@ Thread* myThread = Thread::current(); 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 if (UseConcMarkSweepGC) { @@ -320,6 +323,11 @@ // Call stuff that needs to be run when a safepoint is just about to be completed 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 @@ ConcurrentGCThread::safepoint_desynchronize(); } #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() { @@ -445,24 +456,23 @@ // Various cleaning tasks that should be done periodically at safepoints void SafepointSynchronize::do_cleanup_tasks() { - jlong cleanup_time; - - // Update fat-monitor pool, since this is a safepoint. - if (TraceSafepoint) { - cleanup_time = os::javaTimeNanos(); + { + TraceTime t1("deflating idle monitors", TraceSafepoint); + ObjectSynchronizer::deflate_idle_monitors(); } - ObjectSynchronizer::deflate_idle_monitors(); - InlineCacheBuffer::update_inline_caches(); + { + TraceTime t2("updating inline caches", TraceSafepoint); + InlineCacheBuffer::update_inline_caches(); + } + if(UseCounterDecay && CounterDecay::is_decay_needed()) { + TraceTime t3("decaying counter", TraceSafepoint); CounterDecay::decay(); } + + TraceTime t4("sweeping nmethods", TraceSafepoint); NMethodSweeper::sweep(); - - if (TraceSafepoint) { - tty->print_cr("do_cleanup_tasks takes "INT64_FORMAT_W(6) "ms", - (os::javaTimeNanos() - cleanup_time) / MICROUNITS); - } } @@ -979,17 +989,32 @@ // Statistics & Instrumentations // SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL; +jlong SafepointSynchronize::_safepoint_begin_time = 0; int SafepointSynchronize::_cur_stat_index = 0; julong SafepointSynchronize::_safepoint_reasons[VM_Operation::VMOp_Terminating]; julong SafepointSynchronize::_coalesced_vmop_count = 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 last_safepoint_start_time = 0; -static jlong sync_end_time = 0; +static jlong cleanup_end_time = 0; static bool need_to_track_page_armed_status = 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() { if (init_done) return; @@ -1016,19 +1041,6 @@ if (UseCompilerSafepoints && DeferPollingPageLoopCount >= 0) { 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; } @@ -1036,6 +1048,8 @@ assert(init_done, "safepoint statistics array hasn't been initialized"); SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; + spstat->_time_stamp = _ts_of_current_safepoint; + VM_Operation *op = VMThread::vm_operation(); spstat->_vmop_type = (op != NULL ? op->type() : -1); if (op != NULL) { @@ -1054,14 +1068,6 @@ } else { 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() { @@ -1097,18 +1103,31 @@ // 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 // 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) { _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) { SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; // 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 // PrintSafepointStatisticsTimeout will be printed out right away. // By default, it is -1 meaning all samples will be put into the list. @@ -1119,40 +1138,42 @@ } else { // The safepoint statistics will be printed out when the _safepoin_stats // array fills up. - if (_cur_stat_index != PrintSafepointStatisticsCount - 1) { - _cur_stat_index ++; - } else { + if (_cur_stat_index == PrintSafepointStatisticsCount - 1) { print_statistics(); _cur_stat_index = 0; - tty->print_cr(""); + } else { + _cur_stat_index++; } } } void SafepointSynchronize::print_statistics() { - int index; 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]; - tty->print("%-28s [" + tty->print("%.3f: ", sstats->_time_stamp); + tty->print("%-26s [" INT32_FORMAT_W(8)INT32_FORMAT_W(11)INT32_FORMAT_W(15) - "] ", + " ] ", sstats->_vmop_type == -1 ? "no vm operation" : VM_Operation::name(sstats->_vmop_type), sstats->_nof_total_threads, sstats->_nof_initial_running_threads, sstats->_nof_threads_wait_to_block); // "/ MICROUNITS " is to convert the unit from nanos to millis. - tty->print(" [" - INT64_FORMAT_W(6)INT64_FORMAT_W(6)INT64_FORMAT_W(6) - "] " - "["INT64_FORMAT_W(6)INT64_FORMAT_W(9) "] ", + tty->print(" [" + INT64_FORMAT_W(6)INT64_FORMAT_W(6) + INT64_FORMAT_W(6)INT64_FORMAT_W(6) + INT64_FORMAT_W(6)" ] ", sstats->_time_to_spin / MICROUNITS, sstats->_time_to_wait_to_block / MICROUNITS, sstats->_time_to_sync / MICROUNITS, - sstats->_time_to_exec_vmop / MICROUNITS, - sstats->_time_elapsed_since_last_safepoint / MICROUNITS); + sstats->_time_to_do_cleanups / MICROUNITS, + sstats->_time_to_exec_vmop / MICROUNITS); if (need_to_track_page_armed_status) { tty->print(INT32_FORMAT" ", sstats->_page_armed); @@ -1174,7 +1195,7 @@ // don't print it out. // Approximate the vm op time. _safepoint_stats[_cur_stat_index]._time_to_exec_vmop = - os::javaTimeNanos() - sync_end_time; + os::javaTimeNanos() - cleanup_end_time; if ( PrintSafepointStatisticsTimeout < 0 || spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) { @@ -1203,6 +1224,9 @@ _coalesced_vmop_count); tty->print_cr("Maximum sync time "INT64_FORMAT_W(5)" ms", _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); } // ------------------------------------------------------------------------------------------------