8219436: Safepoint logs correction and misc

Reviewed-by: mdoerr, coleenp
This commit is contained in:
Robbin Ehn 2019-02-22 14:20:06 +01:00
parent 2133bed090
commit 74d466fd5f
16 changed files with 238 additions and 388 deletions

@ -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" />

@ -3953,9 +3953,6 @@ static jint JNI_CreateJavaVM_inner(JavaVM **vm, void **penv, void *args) {
}
#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);

@ -174,10 +174,7 @@ void exit_globals() {
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);

@ -103,16 +103,6 @@ static void post_safepoint_synchronize_event(EventSafepointStateSynchronization&
}
}
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 @@ int SafepointSynchronize::_waiting_to_block = 0;
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 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no
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 @@ int SafepointSynchronize::synchronize_threads(jlong safepoint_limit_time, int no
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 @@ void SafepointSynchronize::arm_safepoint() {
// 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 @@ void SafepointSynchronize::arm_safepoint() {
// 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 @@ void SafepointSynchronize::arm_safepoint() {
// 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 @@ void SafepointSynchronize::begin() {
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 @@ void SafepointSynchronize::begin() {
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 @@ void SafepointSynchronize::begin() {
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 @@ void SafepointSynchronize::begin() {
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 @@ void SafepointSynchronize::begin() {
// 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 @@ void SafepointSynchronize::begin() {
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 @@ void SafepointSynchronize::disarm_safepoint() {
}
} // ~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 @@ void SafepointSynchronize::end() {
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 @@ void SafepointSynchronize::handle_polling_page_exception(JavaThread *thread) {
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::handle_polling_page_exception(JavaThread *thread) {
}
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 @@ void SafepointSynchronize::print_safepoint_timeout(SafepointTimeoutReason reason
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 @@ void SafepointSynchronize::print_safepoint_timeout(SafepointTimeoutReason reason
// 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 @@ void ThreadSafepointState::handle_polling_page_exception() {
}
//
// 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
};
// -------------------------------------------------------------------------------------------------------
// Implementation of SafepointTracing
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;
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};
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;
}
}
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;
}
// 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 @@ static void print_header(outputStream* st) {
// 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);
}

@ -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 @@ class SafepointSynchronize : AllStatic {
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 @@ class SafepointSynchronize : AllStatic {
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 @@ public:
// 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 @@ class ThreadSafepointState: public CHeapObj<mtThread> {
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

@ -479,7 +479,7 @@ void TieredThresholdPolicy::update_rate(jlong t, Method* m) {
// 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 @@ void TieredThresholdPolicy::update_rate(jlong t, Method* m) {
// 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();

@ -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 @@ class VM_Operation: public CHeapObj<mtInternal> {
// 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 @@ class VM_Operation: public CHeapObj<mtInternal> {
#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

@ -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 @@ void VMOperationTimeoutTask::disarm() {
//------------------------------------------------------------------------------------------------------------------
// 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 @@ void VMThread::destroy() {
_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 @@ void VMThread::run() {
}
// 4526887 let VM thread exit at Safepoint
_no_op_reason = "Halt";
_cur_vm_operation = &halt_op;
SafepointSynchronize::begin();
if (VerifyBeforeExit) {
@ -435,24 +431,25 @@ void VMThread::evaluate_operation(VM_Operation* op) {
}
}
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 @@ void VMThread::loop() {
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 @@ void VMThread::loop() {
if (GCALotAtAllSafepoints) InterfaceSupport::check_gc_alot();
#endif
SafepointSynchronize::end();
_cur_vm_operation = NULL;
}
_cur_vm_operation = _vm_queue->remove_next();
@ -555,9 +553,7 @@ void VMThread::loop() {
_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 @@ void VMThread::loop() {
//
// 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;
}
}
}

@ -119,12 +119,11 @@ class VMThread: public NamedThread {
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 @@ class VMThread: public NamedThread {
// 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; }

@ -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::init() {
}
}
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());
}
_application_time_ticks->inc(app_ticks);
}
}
void RuntimeService::record_safepoint_synchronized() {
void RuntimeService::record_safepoint_synchronized(jlong sync_ticks) {
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();
_sync_time_ticks->inc(sync_ticks);
}
}
void RuntimeService::record_safepoint_end() {
void RuntimeService::record_safepoint_end(jlong safepoint_ticks) {
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();
if (UsePerfData) {
_safepoint_time_ticks->inc(_safepoint_timer.ticks_since_update());
_safepoint_time_ticks->inc(safepoint_ticks);
}
}
void RuntimeService::record_safepoint_epilog(const char* operation_name) {
if (!log_is_enabled(Info, safepoint, stats)) {
return;
}
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;

@ -35,12 +35,6 @@ private:
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 @@ public:
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

@ -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>

@ -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>

@ -41,8 +41,6 @@ public class SafepointTest {
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);
}

@ -55,7 +55,6 @@ public class TestSafepointEvents {
static final String[] EVENT_NAMES = new String[] {
EventNames.SafepointBegin,
EventNames.SafepointStateSynchronization,
EventNames.SafepointWaitBlocked,
EventNames.SafepointCleanup,
EventNames.SafepointCleanupTask,
EventNames.SafepointEnd

@ -66,7 +66,6 @@ public class EventNames {
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";