--- old/src/hotspot/share/runtime/safepoint.cpp 2018-07-09 13:25:26.858499055 -0400 +++ new/src/hotspot/share/runtime/safepoint.cpp 2018-07-09 13:25:26.098428335 -0400 @@ -156,9 +156,10 @@ Thread* myThread = Thread::current(); assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint"); - if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) { + if (log_is_enabled(Debug, safepoint, stats)) { _safepoint_begin_time = os::javaTimeNanos(); _ts_of_current_safepoint = tty->time_stamp().seconds(); + _nof_threads_hit_polling_page = 0; } Universe::heap()->safepoint_synchronize_begin(); @@ -190,14 +191,6 @@ jlong safepoint_limit_time = 0; timeout_error_printed = false; - // PrintSafepointStatisticsTimeout can be specified separately. When - // specified, PrintSafepointStatistics will be set to true in - // deferred_initialize_stat method. The initialization has to be done - // early enough to avoid any races. See bug 6880029 for details. - if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) { - deferred_initialize_stat(); - } - // Begin the process of bringing the system to a safepoint. // Java threads can be in several different states and are // stopped by different mechanisms: @@ -312,7 +305,7 @@ if (iterations == 0) { initial_running = still_running; - if (PrintSafepointStatistics) { + if (log_is_enabled(Debug, safepoint, stats)) { begin_statistics(nof_threads, still_running); } } @@ -403,7 +396,7 @@ } // ThreadsListHandle destroyed here. assert(still_running == 0, "sanity check"); - if (PrintSafepointStatistics) { + if (log_is_enabled(Debug, safepoint, stats)) { update_statistics_on_spin_end(); } if (sync_event.should_commit()) { @@ -436,7 +429,7 @@ if (SafepointTimeout) { jlong current_time = os::javaTimeNanos(); if (safepoint_limit_time < current_time) { - tty->print_cr("# SafepointSynchronize: Finished after " + log_warning(safepoint)("# SafepointSynchronize: Finished after " INT64_FORMAT_W(6) " ms", (int64_t)((current_time - safepoint_limit_time) / MICROUNITS + (jlong)SafepointTimeoutDelay)); @@ -470,7 +463,7 @@ log_info(safepoint)("Entering safepoint region: %s", VMThread::vm_safepoint_description()); RuntimeService::record_safepoint_synchronized(); - if (PrintSafepointStatistics) { + if (log_is_enabled(Debug, safepoint, stats)) { update_statistics_on_sync_end(os::javaTimeNanos()); } @@ -483,7 +476,7 @@ } } - if (PrintSafepointStatistics) { + if (log_is_enabled(Debug, safepoint, stats)) { // Record how much time spend on the above cleanup tasks update_statistics_on_cleanup_end(os::javaTimeNanos()); } @@ -506,7 +499,7 @@ DEBUG_ONLY(Thread* myThread = Thread::current();) assert(myThread->is_VM_thread(), "Only VM thread can execute a safepoint"); - if (PrintSafepointStatistics) { + if (log_is_enabled(Debug, safepoint, stats)) { end_statistics(os::javaTimeNanos()); } @@ -952,8 +945,8 @@ assert(SafepointSynchronize::is_synchronizing(), "polling encountered outside safepoint synchronization"); } - if (PrintSafepointStatistics) { - inc_page_trap_count(); + if (log_is_enabled(Debug, safepoint, stats)) { + Atomic::inc(&_nof_threads_hit_polling_page); } ThreadSafepointState* state = thread->safepoint_state(); @@ -967,29 +960,34 @@ timeout_error_printed = true; // Print out the thread info which didn't reach the safepoint for debugging // purposes (useful when there are lots of threads in the debugger). - tty->cr(); - tty->print_cr("# SafepointSynchronize::begin: Timeout detected:"); - if (reason == _spinning_timeout) { - tty->print_cr("# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint."); - } else if (reason == _blocking_timeout) { - tty->print_cr("# SafepointSynchronize::begin: Timed out while waiting for threads to stop."); - } - - tty->print_cr("# SafepointSynchronize::begin: Threads which did not reach the safepoint:"); - ThreadSafepointState *cur_state; - ResourceMark rm; - for (JavaThreadIteratorWithHandle jtiwh; JavaThread *cur_thread = jtiwh.next(); ) { - cur_state = cur_thread->safepoint_state(); + LogTarget(Warning, safepoint) lt; + if (lt.is_enabled()) { + ResourceMark rm; + LogStream ls(lt); + + ls.cr(); + ls.print_cr("# SafepointSynchronize::begin: Timeout detected:"); + if (reason == _spinning_timeout) { + ls.print_cr("# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint."); + } else if (reason == _blocking_timeout) { + ls.print_cr("# SafepointSynchronize::begin: Timed out while waiting for threads to stop."); + } - if (cur_thread->thread_state() != _thread_blocked && - ((reason == _spinning_timeout && cur_state->is_running()) || - (reason == _blocking_timeout && !cur_state->has_called_back()))) { - tty->print("# "); - cur_thread->print(); - tty->cr(); + ls.print_cr("# SafepointSynchronize::begin: Threads which did not reach the safepoint:"); + ThreadSafepointState *cur_state; + for (JavaThreadIteratorWithHandle jtiwh; JavaThread *cur_thread = jtiwh.next(); ) { + cur_state = cur_thread->safepoint_state(); + + if (cur_thread->thread_state() != _thread_blocked && + ((reason == _spinning_timeout && cur_state->is_running()) || + (reason == _blocking_timeout && !cur_state->has_called_back()))) { + ls.print("# "); + cur_thread->print_on(&ls); + ls.cr(); + } } + ls.print_cr("# SafepointSynchronize::begin: (End of list)"); } - tty->print_cr("# SafepointSynchronize::begin: (End of list)"); } // To debug the long safepoint, specify both DieOnSafepointTimeout & @@ -1239,216 +1237,157 @@ // // Statistics & Instrumentations // -SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL; +struct SafepointStats { + float _time_stamp; // record when the current safepoint occurs in seconds + int _nof_total_threads; // total number of Java threads + int _nof_initial_running_threads; // total number of initially seen running threads + int _nof_threads_wait_to_block; // total number of threads waiting for to block + bool _page_armed; // true if polling page is armed, false otherwise + 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_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_exec_vmop; // total time in millis spent in vm operation itself + const char* _safepoint_type; // printable type of VM operation that triggers the safepoint +}; + +SafepointStats safepoint_stats = {0}; // zero initialize + 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; +volatile int SafepointSynchronize::_nof_threads_hit_polling_page = 0; static jlong cleanup_end_time = 0; -static bool init_done = false; - -// Helper method to print the header. -static void print_header() { - // The number of spaces is significant here, and should match the format - // specifiers in print_statistics(). - - tty->print(" vmop " - "[ threads: total initially_running wait_to_block ]" - "[ time: spin block sync cleanup vmop ] "); - - tty->print_cr("page_trap_count"); -} - -void SafepointSynchronize::deferred_initialize_stat() { - if (init_done) return; - - // If PrintSafepointStatisticsTimeout is specified, the statistics data will - // be printed right away, in which case, _safepoint_stats will regress to - // a single element array. Otherwise, it is a circular ring buffer with default - // size of PrintSafepointStatisticsCount. - int stats_array_size; - if (PrintSafepointStatisticsTimeout > 0) { - stats_array_size = 1; - PrintSafepointStatistics = true; - } else { - stats_array_size = PrintSafepointStatisticsCount; - } - _safepoint_stats = (SafepointStats*)os::malloc(stats_array_size - * sizeof(SafepointStats), mtInternal); - guarantee(_safepoint_stats != NULL, - "not enough memory for safepoint instrumentation data"); - - init_done = true; -} void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) { - assert(init_done, "safepoint statistics array hasn't been initialized"); - SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; - - spstat->_time_stamp = _ts_of_current_safepoint; + safepoint_stats._time_stamp = _ts_of_current_safepoint; + safepoint_stats._safepoint_type = VMThread::vm_safepoint_description(); VM_Operation *op = VMThread::vm_operation(); - spstat->_vmop_type = (op != NULL ? op->type() : -1); if (op != NULL) { - _safepoint_reasons[spstat->_vmop_type]++; + _safepoint_reasons[op->type()]++; + } else { + _safepoint_reasons[VM_Operation::VMOp_None]++; } - spstat->_nof_total_threads = nof_threads; - spstat->_nof_initial_running_threads = nof_running; - spstat->_nof_threads_hit_page_trap = 0; + safepoint_stats._nof_total_threads = nof_threads; + safepoint_stats._nof_initial_running_threads = nof_running; // Records the start time of spinning. The real time spent on spinning // will be adjusted when spin is done. Same trick is applied for time // spent on waiting for threads to block. if (nof_running != 0) { - spstat->_time_to_spin = os::javaTimeNanos(); + safepoint_stats._time_to_spin = os::javaTimeNanos(); } else { - spstat->_time_to_spin = 0; + safepoint_stats._time_to_spin = 0; } } void SafepointSynchronize::update_statistics_on_spin_end() { - SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; jlong cur_time = os::javaTimeNanos(); - spstat->_nof_threads_wait_to_block = _waiting_to_block; - if (spstat->_nof_initial_running_threads != 0) { - spstat->_time_to_spin = cur_time - spstat->_time_to_spin; + safepoint_stats._nof_threads_wait_to_block = _waiting_to_block; + if (safepoint_stats._nof_initial_running_threads != 0) { + safepoint_stats._time_to_spin = cur_time - safepoint_stats._time_to_spin; } // Records the start time of waiting for to block. Updated when block is done. if (_waiting_to_block != 0) { - spstat->_time_to_wait_to_block = cur_time; + safepoint_stats._time_to_wait_to_block = cur_time; } else { - spstat->_time_to_wait_to_block = 0; + safepoint_stats._time_to_wait_to_block = 0; } } void SafepointSynchronize::update_statistics_on_sync_end(jlong end_time) { - SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; - if (spstat->_nof_threads_wait_to_block != 0) { - spstat->_time_to_wait_to_block = end_time - - spstat->_time_to_wait_to_block; + if (safepoint_stats._nof_threads_wait_to_block != 0) { + safepoint_stats._time_to_wait_to_block = end_time - + safepoint_stats._time_to_wait_to_block; } // 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 - _safepoint_begin_time; - if (spstat->_time_to_sync > _max_sync_time) { - _max_sync_time = spstat->_time_to_sync; + safepoint_stats._time_to_sync = end_time - _safepoint_begin_time; + if (safepoint_stats._time_to_sync > _max_sync_time) { + _max_sync_time = safepoint_stats._time_to_sync; } - spstat->_time_to_do_cleanups = end_time; + safepoint_stats._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; - + safepoint_stats._time_to_do_cleanups = end_time - safepoint_stats._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 - 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. - if ( PrintSafepointStatisticsTimeout > 0) { - if (spstat->_time_to_sync > (jlong)PrintSafepointStatisticsTimeout * MICROUNITS) { - print_statistics(); - } - } else { - // The safepoint statistics will be printed out when the _safepoin_stats - // array fills up. - if (_cur_stat_index == PrintSafepointStatisticsCount - 1) { - print_statistics(); - _cur_stat_index = 0; - } else { - _cur_stat_index++; - } + safepoint_stats._time_to_exec_vmop = vmop_end_time - cleanup_end_time; + if (safepoint_stats._time_to_exec_vmop > _max_vmop_time) { + _max_vmop_time = safepoint_stats._time_to_exec_vmop; } + + safepoint_stats._nof_threads_hit_page_trap = _nof_threads_hit_polling_page; + + print_statistics(); } void SafepointSynchronize::print_statistics() { - for (int index = 0; index <= _cur_stat_index; index++) { - if (index % 30 == 0) { - print_header(); - } - SafepointStats* sstats = &_safepoint_stats[index]; - tty->print("%8.3f: ", sstats->_time_stamp); - tty->print("%-30s [ " - INT32_FORMAT_W(8) " " INT32_FORMAT_W(17) " " INT32_FORMAT_W(13) " " - "]", - (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); + + LogTarget(Debug, safepoint, stats) lt; + if (lt.is_enabled()) { + ResourceMark rm; + LogStream ls(lt); + // The longest vmop is CollectForMetadataAllocation + ls.print("vmop: %-28s [" + "threads: total " INT32_FORMAT_W(5) " initial running " INT32_FORMAT_W(3) " waiting to block " + INT32_FORMAT_W(3) "]", + safepoint_stats._safepoint_type, + safepoint_stats._nof_total_threads, + safepoint_stats._nof_initial_running_threads, + safepoint_stats._nof_threads_wait_to_block); // "/ MICROUNITS " is to convert the unit from nanos to millis. - tty->print("[ " - INT64_FORMAT_W(7) " " INT64_FORMAT_W(7) " " - INT64_FORMAT_W(7) " " INT64_FORMAT_W(7) " " - INT64_FORMAT_W(7) " ] ", - (int64_t)(sstats->_time_to_spin / MICROUNITS), - (int64_t)(sstats->_time_to_wait_to_block / MICROUNITS), - (int64_t)(sstats->_time_to_sync / MICROUNITS), - (int64_t)(sstats->_time_to_do_cleanups / MICROUNITS), - (int64_t)(sstats->_time_to_exec_vmop / MICROUNITS)); - - tty->print_cr(INT32_FORMAT_W(15) " ", sstats->_nof_threads_hit_page_trap); + ls.print("[time: safepoint_begin %f spin " + INT64_FORMAT_W(2) "ms block " INT64_FORMAT_W(2) "ms sync " + INT64_FORMAT_W(2) "ms cleanup " INT64_FORMAT_W(2) "ms vmop " + INT64_FORMAT_W(4) "ms]", + safepoint_stats._time_stamp, + (int64_t)(safepoint_stats._time_to_spin / MICROUNITS), + (int64_t)(safepoint_stats._time_to_wait_to_block / MICROUNITS), + (int64_t)(safepoint_stats._time_to_sync / MICROUNITS), + (int64_t)(safepoint_stats._time_to_do_cleanups / MICROUNITS), + (int64_t)(safepoint_stats._time_to_exec_vmop / MICROUNITS)); + + ls.print_cr(" page trap count=" INT32_FORMAT, safepoint_stats._nof_threads_hit_page_trap); } } -// This method will be called when VM exits. It will first call -// print_statistics to print out the rest of the sampling. Then -// it tries to summarize the sampling. +// This method will be called when VM exits. This tries to summarize the sampling. +// Current thread may already be deleted, so don't use ResourceMark. void SafepointSynchronize::print_stat_on_exit() { - if (_safepoint_stats == NULL) return; - - SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; - - // During VM exit, end_statistics may not get called and in that - // case, if the sync time is less than PrintSafepointStatisticsTimeout, - // don't print it out. - // Approximate the vm op time. - _safepoint_stats[_cur_stat_index]._time_to_exec_vmop = - os::javaTimeNanos() - cleanup_end_time; - - if ( PrintSafepointStatisticsTimeout < 0 || - spstat->_time_to_sync > (jlong)PrintSafepointStatisticsTimeout * MICROUNITS) { - print_statistics(); - } - tty->cr(); - - // Print out polling page sampling status. - tty->print_cr("Polling page always armed"); for (int index = 0; index < VM_Operation::VMOp_Terminating; index++) { if (_safepoint_reasons[index] != 0) { - tty->print_cr("%-26s" UINT64_FORMAT_W(10), VM_Operation::name(index), - _safepoint_reasons[index]); + log_debug(safepoint, stats)("%-28s" UINT64_FORMAT_W(10), VM_Operation::name(index), + _safepoint_reasons[index]); } } - tty->print_cr(UINT64_FORMAT_W(5) " VM operations coalesced during safepoint", - _coalesced_vmop_count); - tty->print_cr("Maximum sync time " INT64_FORMAT_W(5) " ms", - (int64_t)(_max_sync_time / MICROUNITS)); - tty->print_cr("Maximum vm operation time (except for Exit VM operation) " - INT64_FORMAT_W(5) " ms", - (int64_t)(_max_vmop_time / MICROUNITS)); + log_debug(safepoint, stats)("VM operations coalesced during safepoint " INT64_FORMAT, + _coalesced_vmop_count); + log_debug(safepoint, stats)("Maximum sync time " INT64_FORMAT" ms", + (int64_t)(_max_sync_time / MICROUNITS)); + log_debug(safepoint, stats)("Maximum vm operation time (except for Exit VM operation) " + INT64_FORMAT " ms", + (int64_t)(_max_vmop_time / MICROUNITS)); }