--- a/src/hotspot/share/jfr/metadata/metadata.xml Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/jfr/metadata/metadata.xml Fri Feb 22 14:20:06 2019 +0100
@@ -533,12 +533,6 @@
<Field type="int" name="iterations" label="Iterations" description="Number of state check iterations" />
</Event>
- <Event name="SafepointWaitBlocked" category="Java Virtual Machine, Runtime, Safepoint" label="Safepoint Wait Blocked" description="Safepointing begin waiting on running threads to block"
- thread="true">
- <Field type="ulong" name="safepointId" label="Safepoint Identifier" relation="SafepointId" />
- <Field type="int" name="runningThreadCount" label="Running Threads" description="The number running of threads wait for safe point" />
- </Event>
-
<Event name="SafepointCleanup" category="Java Virtual Machine, Runtime, Safepoint" label="Safepoint Cleanup" description="Safepointing begin running cleanup tasks"
thread="true">
<Field type="ulong" name="safepointId" label="Safepoint Identifier" relation="SafepointId" />
--- a/src/hotspot/share/prims/jni.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/prims/jni.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -3953,9 +3953,6 @@
}
#endif
- // Tracks the time application was running before GC
- RuntimeService::record_application_start();
-
// Notify JVMTI
if (JvmtiExport::should_post_thread_life()) {
JvmtiExport::post_thread_start(thread);
--- a/src/hotspot/share/runtime/init.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/init.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -174,10 +174,7 @@
ObjectSynchronizer::audit_and_print_stats(true /* on_exit */);
}
perfMemory_exit();
- if (log_is_enabled(Debug, safepoint, stats)) {
- // Print the collected safepoint statistics.
- SafepointSynchronize::print_stat_on_exit();
- }
+ SafepointTracing::statistics_exit_log();
if (PrintStringTableStatistics) {
SymbolTable::dump(tty);
StringTable::dump(tty);
--- a/src/hotspot/share/runtime/safepoint.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/safepoint.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -103,16 +103,6 @@
}
}
-static void post_safepoint_wait_blocked_event(EventSafepointWaitBlocked& event,
- uint64_t safepoint_id,
- int initial_threads_waiting_to_block) {
- if (event.should_commit()) {
- event.set_safepointId(safepoint_id);
- event.set_runningThreadCount(initial_threads_waiting_to_block);
- event.commit();
- }
-}
-
static void post_safepoint_cleanup_task_event(EventSafepointCleanupTask& event,
uint64_t safepoint_id,
const char* name) {
@@ -138,27 +128,21 @@
volatile uint64_t SafepointSynchronize::_safepoint_counter = 0;
const uint64_t SafepointSynchronize::InactiveSafepointCounter = 0;
int SafepointSynchronize::_current_jni_active_count = 0;
-long SafepointSynchronize::_end_of_last_safepoint = 0;
WaitBarrier* SafepointSynchronize::_wait_barrier;
-// We need a place to save the desc since it is released before we need it.
-static char stopped_description[64] = "";
-static bool _vm_is_waiting = false;
-
static volatile bool PageArmed = false; // safepoint polling page is RO|RW vs PROT_NONE
static bool timeout_error_printed = false;
// Statistic related
-julong SafepointSynchronize::_coalesced_vmop_count = 0;
static jlong _safepoint_begin_time = 0;
-static float _ts_of_current_safepoint = 0.0f;
static volatile int _nof_threads_hit_polling_page = 0;
void SafepointSynchronize::init(Thread* vmthread) {
// WaitBarrier should never be destroyed since we will have
// threads waiting on it while exiting.
_wait_barrier = new WaitBarrier(vmthread);
+ SafepointTracing::init();
}
void SafepointSynchronize::increment_jni_active_count() {
@@ -244,16 +228,13 @@
DEBUG_ONLY(assert_list_is_valid(tss_head, still_running);)
*initial_running = still_running;
- if (log_is_enabled(Debug, safepoint, stats)) {
- begin_statistics(nof_threads, still_running);
- }
int iterations = 1; // The first iteration is above.
while (still_running > 0) {
// Check if this has taken too long:
if (SafepointTimeout && safepoint_limit_time < os::javaTimeNanos()) {
- print_safepoint_timeout(_spinning_timeout);
+ print_safepoint_timeout();
}
if (int(iterations) == -1) { // overflow - something is wrong.
// We can only overflow here when we are using global
@@ -291,9 +272,6 @@
assert(tss_head == NULL, "Must be empty");
- if (log_is_enabled(Debug, safepoint, stats)) {
- update_statistics_on_spin_end();
- }
return iterations;
}
@@ -303,8 +281,11 @@
// stopped by different mechanisms:
//
// 1. Running interpreted
- // The interpreter dispatch table is changed to force it to
- // check for a safepoint condition between bytecodes.
+ // When executing branching/returning byte codes interpreter
+ // checks if the poll is armed, if so blocks in SS::block().
+ // When using global polling the interpreter dispatch table
+ // is changed to force it to check for a safepoint condition
+ // between bytecodes.
// 2. Running in native code
// When returning from the native code, a Java thread must check
// the safepoint _state to see if we must block. If the
@@ -322,9 +303,9 @@
// block condition until the safepoint operation is complete.
// 5. In VM or Transitioning between states
// If a Java thread is currently running in the VM or transitioning
- // between states, the safepointing code will wait for the thread to
- // block itself when it attempts transitions to a new state.
- //
+ // between states, the safepointing code will poll the thread state
+ // until the thread blocks itself when it attempts transitions to a
+ // new state or locking a safepoint checked monitor.
// We must never miss a thread with correct safepoint id, so we must make sure we arm
// the wait barrier for the next safepoint id/counter.
@@ -363,17 +344,10 @@
// Roll all threads forward to a safepoint and suspend them all
void SafepointSynchronize::begin() {
- EventSafepointBegin begin_event;
assert(Thread::current()->is_VM_thread(), "Only VM thread may execute a safepoint");
- strncpy(stopped_description, VMThread::vm_safepoint_description(), sizeof(stopped_description) - 1);
- stopped_description[sizeof(stopped_description) - 1] = '\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;
- }
+ EventSafepointBegin begin_event;
+ SafepointTracing::begin(VMThread::vm_op_type());
Universe::heap()->safepoint_synchronize_begin();
@@ -385,9 +359,9 @@
int nof_threads = Threads::number_of_threads();
- log_debug(safepoint)("Safepoint synchronization initiated using %s wait barrier. (%d threads)", _wait_barrier->description(), nof_threads);
+ _nof_threads_hit_polling_page = 0;
- RuntimeService::record_safepoint_begin();
+ 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;
@@ -399,9 +373,9 @@
if (SafepointTimeout) {
// Set the limit time, so that it can be compared to see if this has taken
// too long to complete.
- safepoint_limit_time = os::javaTimeNanos() + (jlong)SafepointTimeoutDelay * MICROUNITS;
+ safepoint_limit_time = SafepointTracing::start_of_safepoint() + (jlong)SafepointTimeoutDelay * (NANOUNITS / MILLIUNITS);
+ timeout_error_printed = false;
}
- timeout_error_printed = false;
EventSafepointStateSynchronization sync_event;
int initial_running = 0;
@@ -413,20 +387,13 @@
int iterations = synchronize_threads(safepoint_limit_time, nof_threads, &initial_running);
assert(_waiting_to_block == 0, "No thread should be running");
- post_safepoint_synchronize_event(sync_event, _safepoint_counter, initial_running,
- _waiting_to_block, iterations);
-
- // Keep event from now.
- EventSafepointWaitBlocked wait_blocked_event;
-
#ifndef PRODUCT
- if (SafepointTimeout) {
+ if (safepoint_limit_time != 0) {
jlong current_time = os::javaTimeNanos();
if (safepoint_limit_time < current_time) {
log_warning(safepoint)("# SafepointSynchronize: Finished after "
INT64_FORMAT_W(6) " ms",
- (int64_t)((current_time - safepoint_limit_time) / MICROUNITS +
- (jlong)SafepointTimeoutDelay));
+ (int64_t)(current_time - SafepointTracing::start_of_safepoint()) / (NANOUNITS / MILLIUNITS));
}
}
#endif
@@ -438,8 +405,6 @@
OrderAccess::fence();
- post_safepoint_wait_blocked_event(wait_blocked_event, _safepoint_counter, 0);
-
#ifdef ASSERT
// Make sure all the threads were visited.
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *cur = jtiwh.next(); ) {
@@ -450,12 +415,12 @@
// Update the count of active JNI critical regions
GCLocker::set_jni_lock_count(_current_jni_active_count);
- log_info(safepoint)("Entering safepoint region: %s", stopped_description);
+ post_safepoint_synchronize_event(sync_event,
+ _safepoint_counter,
+ initial_running,
+ _waiting_to_block, iterations);
- RuntimeService::record_safepoint_synchronized();
- if (log_is_enabled(Debug, safepoint, stats)) {
- update_statistics_on_sync_end(os::javaTimeNanos());
- }
+ SafepointTracing::synchronized(nof_threads, initial_running, _nof_threads_hit_polling_page);
// We do the safepoint cleanup first since a GC related safepoint
// needs cleanup to be completed before running the GC op.
@@ -463,12 +428,8 @@
do_cleanup_tasks();
post_safepoint_cleanup_event(cleanup_event, _safepoint_counter);
- if (log_is_enabled(Debug, safepoint, stats)) {
- // Record how much time spend on the above cleanup tasks
- update_statistics_on_cleanup_end(os::javaTimeNanos());
- }
-
post_safepoint_begin_event(begin_event, _safepoint_counter, nof_threads, _current_jni_active_count);
+ SafepointTracing::cleanup();
}
void SafepointSynchronize::disarm_safepoint() {
@@ -520,10 +481,6 @@
}
} // ~JavaThreadIteratorWithHandle
- log_info(safepoint)("Leaving safepoint region");
-
- RuntimeService::record_safepoint_end();
-
// Release threads lock, so threads can be created/destroyed again.
Threads_lock->unlock();
@@ -539,19 +496,11 @@
uint64_t safepoint_id = _safepoint_counter;
assert(Thread::current()->is_VM_thread(), "Only VM thread can execute a safepoint");
- if (log_is_enabled(Debug, safepoint, stats)) {
- end_statistics(os::javaTimeNanos());
- }
-
disarm_safepoint();
- RuntimeService::record_safepoint_epilog(stopped_description);
-
Universe::heap()->safepoint_synchronize_end();
- // record this time so VMThread can keep track how much time has elapsed
- // since last safepoint.
- _end_of_last_safepoint = os::javaTimeMillis();
+ SafepointTracing::end();
post_safepoint_end_event(event, safepoint_id);
}
@@ -915,7 +864,7 @@
assert(SafepointSynchronize::is_synchronizing(), "polling encountered outside safepoint synchronization");
}
- if (log_is_enabled(Debug, safepoint, stats)) {
+ if (log_is_enabled(Info, safepoint, stats)) {
Atomic::inc(&_nof_threads_hit_polling_page);
}
@@ -925,7 +874,7 @@
}
-void SafepointSynchronize::print_safepoint_timeout(SafepointTimeoutReason reason) {
+void SafepointSynchronize::print_safepoint_timeout() {
if (!timeout_error_printed) {
timeout_error_printed = true;
// Print out the thread info which didn't reach the safepoint for debugging
@@ -937,20 +886,10 @@
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.");
- }
-
+ ls.print_cr("# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.");
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))) {
+ if (cur_thread->safepoint_state()->is_running()) {
ls.print("# ");
cur_thread->print_on(&ls);
ls.cr();
@@ -964,11 +903,10 @@
// ShowMessageBoxOnError.
if (AbortVMOnSafepointTimeout) {
fatal("Safepoint sync time longer than " INTX_FORMAT "ms detected when executing %s.",
- SafepointTimeoutDelay, VMThread::vm_safepoint_description());
+ SafepointTimeoutDelay, VMThread::vm_operation()->name());
}
}
-
// -------------------------------------------------------------------------------------------------------
// Implementation of ThreadSafepointState
@@ -1176,108 +1114,25 @@
}
-//
-// Statistics & Instrumentations
-//
-struct SafepointStats {
- float _time_stamp; // record when the current safepoint occurs in seconds
- int _vmop_type; // tyep of VM operation triggers the safepoint
- 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
-};
-
-static const int _statistics_header_count = 30;
-static int _cur_stat_index = 0;
-static SafepointStats safepoint_stats = {0}; // zero initialize
-static SafepointStats* spstat = &safepoint_stats;
-
-static julong _safepoint_reasons[VM_Operation::VMOp_Terminating];
-static jlong _max_sync_time = 0;
-static jlong _max_vmop_time = 0;
-
-static jlong cleanup_end_time = 0;
-
-void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) {
-
- spstat->_time_stamp = _ts_of_current_safepoint;
-
- VM_Operation *op = VMThread::vm_operation();
- spstat->_vmop_type = op != NULL ? op->type() : VM_Operation::VMOp_None;
- _safepoint_reasons[spstat->_vmop_type]++;
-
- spstat->_nof_total_threads = nof_threads;
- spstat->_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();
- } else {
- spstat->_time_to_spin = 0;
- }
-}
+// -------------------------------------------------------------------------------------------------------
+// Implementation of SafepointTracing
-void SafepointSynchronize::update_statistics_on_spin_end() {
- 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;
- }
-
- // 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;
- } else {
- spstat->_time_to_wait_to_block = 0;
- }
-}
-
-void SafepointSynchronize::update_statistics_on_sync_end(jlong end_time) {
-
- if (spstat->_nof_threads_wait_to_block != 0) {
- spstat->_time_to_wait_to_block = end_time -
- spstat->_time_to_wait_to_block;
- }
+jlong SafepointTracing::_last_safepoint_begin_time_ns = 0;
+jlong SafepointTracing::_last_safepoint_sync_time_ns = 0;
+jlong SafepointTracing::_last_safepoint_cleanup_time_ns = 0;
+jlong SafepointTracing::_last_safepoint_end_time_ns = 0;
+jlong SafepointTracing::_last_app_time_ns = 0;
+int SafepointTracing::_nof_threads = 0;
+int SafepointTracing::_nof_running = 0;
+int SafepointTracing::_page_trap = 0;
+VM_Operation::VMOp_Type SafepointTracing::_current_type;
+jlong SafepointTracing::_max_sync_time = 0;
+jlong SafepointTracing::_max_vmop_time = 0;
+uint64_t SafepointTracing::_op_count[VM_Operation::VMOp_Terminating] = {0};
- // 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;
- }
-
- spstat->_time_to_do_cleanups = end_time;
-}
-
-void SafepointSynchronize::update_statistics_on_cleanup_end(jlong end_time) {
-
- // 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) {
-
- // 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;
- }
-
- spstat->_nof_threads_hit_page_trap = _nof_threads_hit_polling_page;
-
- print_statistics();
+void SafepointTracing::init() {
+ // Application start
+ _last_safepoint_end_time_ns = os::javaTimeNanos();
}
// Helper method to print the header.
@@ -1285,66 +1140,121 @@
// The number of spaces is significant here, and should match the format
// specifiers in print_statistics().
- st->print(" vmop "
- "[ threads: total initially_running wait_to_block ]"
- "[ time: spin block sync cleanup vmop ] ");
+ st->print("VM Operation "
+ "[ threads: total initial_running ]"
+ "[ time: sync cleanup vmop total ]");
- st->print_cr("page_trap_count");
+ st->print_cr(" page_trap_count");
}
// This prints a nice table. To get the statistics to not shift due to the logging uptime
-// decorator, use the option as: -Xlog:safepoint+stats=debug:[outputfile]:none
-void SafepointSynchronize::print_statistics() {
- LogTarget(Debug, safepoint, stats) lt;
+// decorator, use the option as: -Xlog:safepoint+stats:[outputfile]:none
+void SafepointTracing::statistics_log() {
+ LogTarget(Info, safepoint, stats) lt;
assert (lt.is_enabled(), "should only be called when printing statistics is enabled");
LogStream ls(lt);
+ static int _cur_stat_index = 0;
+
// Print header every 30 entries
- if ((_cur_stat_index % _statistics_header_count) == 0) {
+ if ((_cur_stat_index % 30) == 0) {
print_header(&ls);
_cur_stat_index = 1; // wrap
} else {
_cur_stat_index++;
}
- ls.print("%8.3f: ", spstat->_time_stamp);
- ls.print("%-28s [ "
- INT32_FORMAT_W(8) " " INT32_FORMAT_W(17) " " INT32_FORMAT_W(13) " "
+ ls.print("%-28s [ "
+ INT32_FORMAT_W(8) " " INT32_FORMAT_W(8) " "
"]",
- VM_Operation::name(spstat->_vmop_type),
- spstat->_nof_total_threads,
- spstat->_nof_initial_running_threads,
- spstat->_nof_threads_wait_to_block);
- // "/ MICROUNITS " is to convert the unit from nanos to millis.
+ VM_Operation::name(_current_type),
+ _nof_threads,
+ _nof_running);
ls.print("[ "
- INT64_FORMAT_W(7) " " INT64_FORMAT_W(7) " "
- INT64_FORMAT_W(7) " " INT64_FORMAT_W(7) " "
- INT64_FORMAT_W(7) " ] ",
- (int64_t)(spstat->_time_to_spin / MICROUNITS),
- (int64_t)(spstat->_time_to_wait_to_block / MICROUNITS),
- (int64_t)(spstat->_time_to_sync / MICROUNITS),
- (int64_t)(spstat->_time_to_do_cleanups / MICROUNITS),
- (int64_t)(spstat->_time_to_exec_vmop / MICROUNITS));
+ INT64_FORMAT_W(10) " " INT64_FORMAT_W(10) " "
+ INT64_FORMAT_W(10) " " INT64_FORMAT_W(10) " ]",
+ (int64_t)(_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns),
+ (int64_t)(_last_safepoint_cleanup_time_ns - _last_safepoint_sync_time_ns),
+ (int64_t)(_last_safepoint_end_time_ns - _last_safepoint_cleanup_time_ns),
+ (int64_t)(_last_safepoint_end_time_ns - _last_safepoint_begin_time_ns));
- ls.print_cr(INT32_FORMAT_W(15) " ", spstat->_nof_threads_hit_page_trap);
+ ls.print_cr(INT32_FORMAT_W(16), _page_trap);
}
// 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() {
-
+void SafepointTracing::statistics_exit_log() {
+ if (!log_is_enabled(Info, safepoint, stats)) {
+ return;
+ }
for (int index = 0; index < VM_Operation::VMOp_Terminating; index++) {
- if (_safepoint_reasons[index] != 0) {
- log_debug(safepoint, stats)("%-28s" UINT64_FORMAT_W(10), VM_Operation::name(index),
- _safepoint_reasons[index]);
+ if (_op_count[index] != 0) {
+ log_info(safepoint, stats)("%-28s" UINT64_FORMAT_W(10), VM_Operation::name(index),
+ _op_count[index]);
}
}
- 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));
+ log_info(safepoint, stats)("VM operations coalesced during safepoint " INT64_FORMAT,
+ VMThread::get_coalesced_count());
+ log_info(safepoint, stats)("Maximum sync time " INT64_FORMAT" ns",
+ (int64_t)(_max_sync_time));
+ log_info(safepoint, stats)("Maximum vm operation time (except for Exit VM operation) "
+ INT64_FORMAT " ns",
+ (int64_t)(_max_vmop_time));
+}
+
+void SafepointTracing::begin(VM_Operation::VMOp_Type type) {
+ _op_count[type]++;
+ _current_type = type;
+
+ // update the time stamp to begin recording safepoint time
+ _last_safepoint_begin_time_ns = os::javaTimeNanos();
+ _last_safepoint_sync_time_ns = 0;
+ _last_safepoint_cleanup_time_ns = 0;
+
+ _last_app_time_ns = _last_safepoint_begin_time_ns - _last_safepoint_end_time_ns;
+ _last_safepoint_end_time_ns = 0;
+
+ RuntimeService::record_safepoint_begin(_last_app_time_ns);
+}
+
+void SafepointTracing::synchronized(int nof_threads, int nof_running, int traps) {
+ _last_safepoint_sync_time_ns = os::javaTimeNanos();
+ _nof_threads = nof_threads;
+ _nof_running = nof_running;
+ _page_trap = traps;
+ RuntimeService::record_safepoint_synchronized(_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns);
}
+
+void SafepointTracing::cleanup() {
+ _last_safepoint_cleanup_time_ns = os::javaTimeNanos();
+}
+
+void SafepointTracing::end() {
+ _last_safepoint_end_time_ns = os::javaTimeNanos();
+
+ if (_max_sync_time < (_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns)) {
+ _max_sync_time = _last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns;
+ }
+ if (_max_vmop_time < (_last_safepoint_end_time_ns - _last_safepoint_sync_time_ns)) {
+ _max_vmop_time = _last_safepoint_end_time_ns - _last_safepoint_sync_time_ns;
+ }
+ if (log_is_enabled(Info, safepoint, stats)) {
+ statistics_log();
+ }
+
+ log_info(safepoint)(
+ "Safepoint \"%s\", "
+ "Time since last: " JLONG_FORMAT " ns, "
+ "Reaching safepoint: " JLONG_FORMAT " ns, "
+ "At safepoint: " JLONG_FORMAT " ns, "
+ "Total: " JLONG_FORMAT " ns",
+ VM_Operation::name(_current_type),
+ _last_app_time_ns,
+ _last_safepoint_cleanup_time_ns - _last_safepoint_begin_time_ns,
+ _last_safepoint_end_time_ns - _last_safepoint_cleanup_time_ns,
+ _last_safepoint_end_time_ns - _last_safepoint_begin_time_ns
+ );
+
+ RuntimeService::record_safepoint_end(_last_safepoint_end_time_ns - _last_safepoint_cleanup_time_ns);
+}
--- a/src/hotspot/share/runtime/safepoint.hpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/safepoint.hpp Fri Feb 22 14:20:06 2019 +0100
@@ -28,6 +28,7 @@
#include "memory/allocation.hpp"
#include "runtime/os.hpp"
#include "runtime/thread.hpp"
+#include "runtime/vmOperations.hpp"
#include "utilities/ostream.hpp"
#include "utilities/waitBarrier.hpp"
@@ -77,11 +78,6 @@
friend class ThreadSafepointState;
friend class HandshakeState;
- enum SafepointTimeoutReason {
- _spinning_timeout = 0,
- _blocking_timeout = 1
- };
-
// Threads might read this flag directly, without acquiring the Threads_lock:
static volatile SynchronizeState _state;
// Number of threads we are waiting for to block:
@@ -110,7 +106,7 @@
static void print_statistics();
// For debug long safepoint
- static void print_safepoint_timeout(SafepointTimeoutReason timeout_reason);
+ static void print_safepoint_timeout();
// Helper methods for safepoint procedure:
static void arm_safepoint();
@@ -150,19 +146,9 @@
// Exception handling for page polling
static void handle_polling_page_exception(JavaThread *thread);
- // VM Thread interface for determining safepoint rate
- static long last_non_safepoint_interval() {
- return os::javaTimeMillis() - _end_of_last_safepoint;
- }
- static long end_of_last_safepoint() {
- return _end_of_last_safepoint;
- }
static bool is_cleanup_needed();
static void do_cleanup_tasks();
- static void print_stat_on_exit();
- static void inc_vmop_coalesced_count() { _coalesced_vmop_count++; }
-
static void set_is_at_safepoint() { _state = _synchronized; }
static void set_is_not_at_safepoint() { _state = _not_synchronized; }
@@ -247,6 +233,48 @@
static void destroy(JavaThread *thread);
};
+class SafepointTracing : public AllStatic {
+private:
+ // Absolute
+ static jlong _last_safepoint_begin_time_ns;
+ static jlong _last_safepoint_sync_time_ns;
+ static jlong _last_safepoint_cleanup_time_ns;
+ static jlong _last_safepoint_end_time_ns;
+ // Relative
+ static jlong _last_app_time_ns;
+ static int _nof_threads;
+ static int _nof_running;
+ static int _page_trap;
+
+ static VM_Operation::VMOp_Type _current_type;
+ static jlong _max_sync_time;
+ static jlong _max_vmop_time;
+ static uint64_t _op_count[VM_Operation::VMOp_Terminating];
+
+ static void statistics_log();
+
+public:
+ static void init();
+
+ static void begin(VM_Operation::VMOp_Type type);
+ static void synchronized(int nof_threads, int nof_running, int traps);
+ static void cleanup();
+ static void end();
+
+ static void statistics_exit_log();
+
+ static jlong time_since_last_safepoint_ms() {
+ return (os::javaTimeNanos() - _last_safepoint_end_time_ns) / (NANOUNITS / MILLIUNITS);
+ }
+
+ static jlong end_of_last_safepoint_ms() {
+ return _last_safepoint_end_time_ns / (NANOUNITS / MILLIUNITS);
+ }
+
+ static jlong start_of_safepoint() {
+ return _last_safepoint_begin_time_ns;
+ }
+};
#endif // SHARE_RUNTIME_SAFEPOINT_HPP
--- a/src/hotspot/share/runtime/tieredThresholdPolicy.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/tieredThresholdPolicy.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -479,7 +479,7 @@
// We don't update the rate if we've just came out of a safepoint.
// delta_s is the time since last safepoint in milliseconds.
- jlong delta_s = t - SafepointSynchronize::end_of_last_safepoint();
+ jlong delta_s = t - SafepointTracing::end_of_last_safepoint_ms();
jlong delta_t = t - (m->prev_time() != 0 ? m->prev_time() : start_time()); // milliseconds since the last measurement
// How many events were there since the last time?
int event_count = m->invocation_count() + m->backedge_count();
@@ -504,7 +504,7 @@
// Check if this method has been stale from a given number of milliseconds.
// See select_task().
bool TieredThresholdPolicy::is_stale(jlong t, jlong timeout, Method* m) {
- jlong delta_s = t - SafepointSynchronize::end_of_last_safepoint();
+ jlong delta_s = t - SafepointTracing::end_of_last_safepoint_ms();
jlong delta_t = t - m->prev_time();
if (delta_t > timeout && delta_s > timeout) {
int event_count = m->invocation_count() + m->backedge_count();
--- a/src/hotspot/share/runtime/vmOperations.hpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/vmOperations.hpp Fri Feb 22 14:20:06 2019 +0100
@@ -41,6 +41,7 @@
// Note: When new VM_XXX comes up, add 'XXX' to the template table.
#define VM_OPS_DO(template) \
template(None) \
+ template(Cleanup) \
template(ThreadStop) \
template(ThreadDump) \
template(PrintThreads) \
@@ -213,7 +214,7 @@
// Debugging
virtual void print_on_error(outputStream* st) const;
- const char* name() const { return _names[type()]; }
+ virtual const char* name() const { return _names[type()]; }
static const char* name(int type) {
assert(type >= 0 && type < VMOp_Terminating, "invalid VM operation type");
return _names[type];
@@ -223,6 +224,21 @@
#endif
};
+class VM_None: public VM_Operation {
+ const char* _reason;
+ public:
+ VM_None(const char* reason) : _reason(reason) {}
+ const char* name() const { return _reason; }
+ VMOp_Type type() const { return VMOp_None; }
+ void doit() {};
+};
+
+class VM_Cleanup: public VM_Operation {
+ public:
+ VMOp_Type type() const { return VMOp_Cleanup; }
+ void doit() {};
+};
+
class VM_ThreadStop: public VM_Operation {
private:
oop _thread; // The Thread that the Throwable is thrown against
--- a/src/hotspot/share/runtime/vmThread.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/vmThread.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -48,19 +48,13 @@
#include "utilities/vmError.hpp"
#include "utilities/xmlstream.hpp"
-// Dummy VM operation to act as first element in our circular double-linked list
-class VM_None: public VM_Operation {
- VMOp_Type type() const { return VMOp_None; }
- void doit() {};
-};
-
VMOperationQueue::VMOperationQueue() {
// The queue is a circular doubled-linked list, which always contains
// one element (i.e., one element means empty).
for(int i = 0; i < nof_priorities; i++) {
_queue_length[i] = 0;
_queue_counter = 0;
- _queue[i] = new VM_None();
+ _queue[i] = new VM_None("QueueHead");
_queue[i]->set_next(_queue[i]);
_queue[i]->set_prev(_queue[i]);
}
@@ -229,14 +223,14 @@
//------------------------------------------------------------------------------------------------------------------
// Implementation of VMThread stuff
-bool VMThread::_should_terminate = false;
+bool VMThread::_should_terminate = false;
bool VMThread::_terminated = false;
Monitor* VMThread::_terminate_lock = NULL;
VMThread* VMThread::_vm_thread = NULL;
VM_Operation* VMThread::_cur_vm_operation = NULL;
VMOperationQueue* VMThread::_vm_queue = NULL;
PerfCounter* VMThread::_perf_accumulated_vm_operation_time = NULL;
-const char* VMThread::_no_op_reason = NULL;
+uint64_t VMThread::_coalesced_count = 0;
VMOperationTimeoutTask* VMThread::_timeout_task = NULL;
@@ -283,6 +277,8 @@
_vm_thread = NULL; // VM thread is gone
}
+static VM_None halt_op("Halt");
+
void VMThread::run() {
assert(this == vm_thread(), "check");
@@ -320,7 +316,7 @@
}
// 4526887 let VM thread exit at Safepoint
- _no_op_reason = "Halt";
+ _cur_vm_operation = &halt_op;
SafepointSynchronize::begin();
if (VerifyBeforeExit) {
@@ -435,24 +431,25 @@
}
}
-bool VMThread::no_op_safepoint_needed(bool check_time) {
+static VM_None safepointALot_op("SafepointALot");
+static VM_Cleanup cleanup_op;
+
+VM_Operation* VMThread::no_op_safepoint(bool check_time) {
if (SafepointALot) {
- _no_op_reason = "SafepointALot";
- return true;
+ return &safepointALot_op;
}
if (!SafepointSynchronize::is_cleanup_needed()) {
- return false;
+ return NULL;
}
if (check_time) {
- long interval = SafepointSynchronize::last_non_safepoint_interval();
+ long interval_ms = SafepointTracing::time_since_last_safepoint_ms();
bool max_time_exceeded = GuaranteedSafepointInterval != 0 &&
- (interval > GuaranteedSafepointInterval);
+ (interval_ms > GuaranteedSafepointInterval);
if (!max_time_exceeded) {
- return false;
+ return NULL;
}
}
- _no_op_reason = "Cleanup";
- return true;
+ return &cleanup_op;
}
void VMThread::loop() {
@@ -494,7 +491,7 @@
exit(-1);
}
- if (timedout && VMThread::no_op_safepoint_needed(false)) {
+ if (timedout && (_cur_vm_operation = VMThread::no_op_safepoint(false)) != NULL) {
MutexUnlockerEx mul(VMOperationQueue_lock,
Mutex::_no_safepoint_check_flag);
// Force a safepoint since we have not had one for at least
@@ -506,6 +503,7 @@
if (GCALotAtAllSafepoints) InterfaceSupport::check_gc_alot();
#endif
SafepointSynchronize::end();
+ _cur_vm_operation = NULL;
}
_cur_vm_operation = _vm_queue->remove_next();
@@ -555,9 +553,7 @@
_vm_queue->set_drain_list(next);
evaluate_operation(_cur_vm_operation);
_cur_vm_operation = next;
- if (log_is_enabled(Debug, safepoint, stats)) {
- SafepointSynchronize::inc_vmop_coalesced_count();
- }
+ _coalesced_count++;
} while (_cur_vm_operation != NULL);
}
// There is a chance that a thread enqueued a safepoint op
@@ -622,10 +618,11 @@
//
// We want to make sure that we get to a safepoint regularly.
//
- if (VMThread::no_op_safepoint_needed(true)) {
+ if ((_cur_vm_operation = VMThread::no_op_safepoint(false)) != NULL) {
HandleMark hm(VMThread::vm_thread());
SafepointSynchronize::begin();
SafepointSynchronize::end();
+ _cur_vm_operation = NULL;
}
}
}
--- a/src/hotspot/share/runtime/vmThread.hpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/runtime/vmThread.hpp Fri Feb 22 14:20:06 2019 +0100
@@ -119,12 +119,11 @@
static bool _terminated;
static Monitor * _terminate_lock;
static PerfCounter* _perf_accumulated_vm_operation_time;
-
- static const char* _no_op_reason;
+ static uint64_t _coalesced_count;
static VMOperationTimeoutTask* _timeout_task;
- static bool no_op_safepoint_needed(bool check_time);
+ static VM_Operation* no_op_safepoint(bool check_time);
void evaluate_operation(VM_Operation* op);
@@ -155,9 +154,8 @@
// Returns the current vm operation if any.
static VM_Operation* vm_operation() { return _cur_vm_operation; }
-
- // Returns the current vm operation name or set reason
- static const char* vm_safepoint_description() { return _cur_vm_operation != NULL ? _cur_vm_operation->name() : _no_op_reason; };
+ static VM_Operation::VMOp_Type vm_op_type() { return _cur_vm_operation->type(); }
+ static uint64_t get_coalesced_count() { return _coalesced_count; }
// Returns the single instance of VMThread.
static VMThread* vm_thread() { return _vm_thread; }
--- a/src/hotspot/share/services/runtimeService.cpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/services/runtimeService.cpp Fri Feb 22 14:20:06 2019 +0100
@@ -25,7 +25,7 @@
#include "precompiled.hpp"
#include "classfile/classLoader.hpp"
#include "logging/log.hpp"
-#include "runtime/timer.hpp"
+#include "logging/logStream.hpp"
#include "runtime/vm_version.hpp"
#include "services/attachListener.hpp"
#include "services/management.hpp"
@@ -35,18 +35,12 @@
#include "utilities/macros.hpp"
#if INCLUDE_MANAGEMENT
-TimeStamp RuntimeService::_app_timer;
-TimeStamp RuntimeService::_safepoint_timer;
PerfCounter* RuntimeService::_sync_time_ticks = NULL;
PerfCounter* RuntimeService::_total_safepoints = NULL;
PerfCounter* RuntimeService::_safepoint_time_ticks = NULL;
PerfCounter* RuntimeService::_application_time_ticks = NULL;
-jlong RuntimeService::_last_safepoint_sync_time_ns = 0;
-jlong RuntimeService::_last_safepoint_end_time_ns = 0;
-jlong RuntimeService::_last_app_time_ns = 0;
void RuntimeService::init() {
-
if (UsePerfData) {
EXCEPTION_MARK;
@@ -87,85 +81,27 @@
}
}
-void RuntimeService::record_safepoint_begin() {
+void RuntimeService::record_safepoint_begin(jlong app_ticks) {
HS_PRIVATE_SAFEPOINT_BEGIN();
-
- // Print the time interval in which the app was executing
- if (_app_timer.is_updated()) {
- _last_app_time_ns = _app_timer.ticks_since_update();
- log_info(safepoint)("Application time: %3.7f seconds", TimeHelper::counter_to_seconds(_last_app_time_ns));
- }
-
- // update the time stamp to begin recording safepoint time
- _last_safepoint_sync_time_ns = 0;
- _last_safepoint_end_time_ns = 0;
- _safepoint_timer.update();
if (UsePerfData) {
_total_safepoints->inc();
- if (_app_timer.is_updated()) {
- _application_time_ticks->inc(_app_timer.ticks_since_update());
- }
- }
-}
-
-void RuntimeService::record_safepoint_synchronized() {
- if (UsePerfData) {
- _sync_time_ticks->inc(_safepoint_timer.ticks_since_update());
- }
- if (log_is_enabled(Info, safepoint) || log_is_enabled(Info, safepoint, stats)) {
- _last_safepoint_sync_time_ns = _safepoint_timer.ticks_since_update();
+ _application_time_ticks->inc(app_ticks);
}
}
-void RuntimeService::record_safepoint_end() {
- HS_PRIVATE_SAFEPOINT_END();
-
- // Logging of safepoint+stats=info needs _last_safepoint_end_time_ns to be set.
- // Logging of safepoint=info needs _last_safepoint_end_time_ns for following log.
- if (log_is_enabled(Info, safepoint) || log_is_enabled(Info, safepoint, stats)) {
- _last_safepoint_end_time_ns = _safepoint_timer.ticks_since_update();
- log_info(safepoint)(
- "Total time for which application threads were stopped: %3.7f seconds, "
- "Stopping threads took: %3.7f seconds",
- TimeHelper::counter_to_seconds(_last_safepoint_end_time_ns),
- TimeHelper::counter_to_seconds(_last_safepoint_sync_time_ns));
- }
-
- // update the time stamp to begin recording app time
- _app_timer.update();
+void RuntimeService::record_safepoint_synchronized(jlong sync_ticks) {
if (UsePerfData) {
- _safepoint_time_ticks->inc(_safepoint_timer.ticks_since_update());
+ _sync_time_ticks->inc(sync_ticks);
}
}
-void RuntimeService::record_safepoint_epilog(const char* operation_name) {
- if (!log_is_enabled(Info, safepoint, stats)) {
- return;
+void RuntimeService::record_safepoint_end(jlong safepoint_ticks) {
+ HS_PRIVATE_SAFEPOINT_END();
+ if (UsePerfData) {
+ _safepoint_time_ticks->inc(safepoint_ticks);
}
-
- log_info(safepoint, stats)(
- "Safepoint \"%s\", "
- "Time since last: " JLONG_FORMAT " ns; "
- "Reaching safepoint: " JLONG_FORMAT " ns; "
- "At safepoint: " JLONG_FORMAT " ns; "
- "Total: " JLONG_FORMAT " ns",
- operation_name,
- _last_app_time_ns,
- _last_safepoint_sync_time_ns,
- _last_safepoint_end_time_ns - _last_safepoint_sync_time_ns,
- _last_safepoint_end_time_ns
- );
}
-void RuntimeService::record_application_start() {
- // update the time stamp to begin recording app time
- _app_timer.update();
-}
-
-// Don't need to record application end because we currently
-// exit at a safepoint and record_safepoint_begin() handles updating
-// the application time counter at VM exit.
-
jlong RuntimeService::safepoint_sync_time_ms() {
return UsePerfData ?
Management::ticks_to_ms(_sync_time_ticks->get_value()) : -1;
--- a/src/hotspot/share/services/runtimeService.hpp Thu Feb 21 14:24:44 2019 +0100
+++ b/src/hotspot/share/services/runtimeService.hpp Fri Feb 22 14:20:06 2019 +0100
@@ -35,12 +35,6 @@
static PerfCounter* _safepoint_time_ticks; // Accumulated time at safepoints
static PerfCounter* _application_time_ticks; // Accumulated time not at safepoints
- static TimeStamp _safepoint_timer;
- static TimeStamp _app_timer;
- static jlong _last_safepoint_sync_time_ns;
- static jlong _last_safepoint_end_time_ns;
- static jlong _last_app_time_ns;
-
public:
static void init();
@@ -50,12 +44,9 @@
static jlong application_time_ms();
// callbacks
- static void record_safepoint_begin() NOT_MANAGEMENT_RETURN;
- static void record_safepoint_synchronized() NOT_MANAGEMENT_RETURN;
- static void record_safepoint_end() NOT_MANAGEMENT_RETURN;
- static void record_safepoint_epilog(const char* operation_name) NOT_MANAGEMENT_RETURN;
- static void record_application_start() NOT_MANAGEMENT_RETURN;
-
+ static void record_safepoint_begin(jlong app_ticks) NOT_MANAGEMENT_RETURN;
+ static void record_safepoint_synchronized(jlong sync_ticks) NOT_MANAGEMENT_RETURN;
+ static void record_safepoint_end(jlong safepoint_ticks) NOT_MANAGEMENT_RETURN;
};
#endif // SHARE_SERVICES_RUNTIMESERVICE_HPP
--- a/src/jdk.jfr/share/conf/jfr/default.jfc Thu Feb 21 14:24:44 2019 +0100
+++ b/src/jdk.jfr/share/conf/jfr/default.jfc Fri Feb 22 14:20:06 2019 +0100
@@ -133,11 +133,6 @@
<setting name="threshold">10 ms</setting>
</event>
- <event name="jdk.SafepointWaitBlocked">
- <setting name="enabled">false</setting>
- <setting name="threshold">10 ms</setting>
- </event>
-
<event name="jdk.SafepointCleanup">
<setting name="enabled">false</setting>
<setting name="threshold">10 ms</setting>
--- a/src/jdk.jfr/share/conf/jfr/profile.jfc Thu Feb 21 14:24:44 2019 +0100
+++ b/src/jdk.jfr/share/conf/jfr/profile.jfc Fri Feb 22 14:20:06 2019 +0100
@@ -133,11 +133,6 @@
<setting name="threshold">0 ms</setting>
</event>
- <event name="jdk.SafepointWaitBlocked">
- <setting name="enabled">false</setting>
- <setting name="threshold">0 ms</setting>
- </event>
-
<event name="jdk.SafepointCleanup">
<setting name="enabled">false</setting>
<setting name="threshold">0 ms</setting>
--- a/test/hotspot/jtreg/runtime/logging/SafepointTest.java Thu Feb 21 14:24:44 2019 +0100
+++ b/test/hotspot/jtreg/runtime/logging/SafepointTest.java Fri Feb 22 14:20:06 2019 +0100
@@ -41,8 +41,6 @@
InnerClass.class.getName());
OutputAnalyzer output = new OutputAnalyzer(pb.start());
output.shouldContain("Safepoint synchronization initiated");
- output.shouldContain("Entering safepoint region: ");
- output.shouldContain("Leaving safepoint region");
output.shouldHaveExitValue(0);
}
--- a/test/jdk/jdk/jfr/event/runtime/TestSafepointEvents.java Thu Feb 21 14:24:44 2019 +0100
+++ b/test/jdk/jdk/jfr/event/runtime/TestSafepointEvents.java Fri Feb 22 14:20:06 2019 +0100
@@ -55,7 +55,6 @@
static final String[] EVENT_NAMES = new String[] {
EventNames.SafepointBegin,
EventNames.SafepointStateSynchronization,
- EventNames.SafepointWaitBlocked,
EventNames.SafepointCleanup,
EventNames.SafepointCleanupTask,
EventNames.SafepointEnd
--- a/test/lib/jdk/test/lib/jfr/EventNames.java Thu Feb 21 14:24:44 2019 +0100
+++ b/test/lib/jdk/test/lib/jfr/EventNames.java Fri Feb 22 14:20:06 2019 +0100
@@ -66,7 +66,6 @@
public final static String ClassUnload = PREFIX + "ClassUnload";
public final static String SafepointBegin = PREFIX + "SafepointBegin";
public final static String SafepointStateSynchronization = PREFIX + "SafepointStateSynchronization";
- public final static String SafepointWaitBlocked = PREFIX + "SafepointWaitBlocked";
public final static String SafepointCleanup = PREFIX + "SafepointCleanup";
public final static String SafepointCleanupTask = PREFIX + "SafepointCleanupTask";
public final static String SafepointEnd = PREFIX + "SafepointEnd";