--- old/src/share/vm/runtime/safepoint.cpp 2019-02-15 19:02:44.070601281 +0300 +++ new/src/share/vm/runtime/safepoint.cpp 2019-02-15 19:02:43.974604633 +0300 @@ -32,6 +32,7 @@ #include "code/scopeDesc.hpp" #include "gc_interface/collectedHeap.hpp" #include "interpreter/interpreter.hpp" +#include "jfr/jfrEvents.hpp" #include "memory/resourceArea.hpp" #include "memory/universe.inline.hpp" #include "oops/oop.inline.hpp" @@ -83,6 +84,73 @@ PRAGMA_FORMAT_MUTE_WARNINGS_FOR_GCC +template +static void set_current_safepoint_id(E* event, int adjustment = 0) { + assert(event != NULL, "invariant"); + event->set_safepointId(SafepointSynchronize::safepoint_counter() + adjustment); +} + +static void post_safepoint_begin_event(EventSafepointBegin* event, + int thread_count, + int critical_thread_count) { + assert(event != NULL, "invariant"); + assert(event->should_commit(), "invariant"); + set_current_safepoint_id(event); + event->set_totalThreadCount(thread_count); + event->set_jniCriticalThreadCount(critical_thread_count); + event->commit(); +} + +static void post_safepoint_cleanup_event(EventSafepointCleanup* event) { + assert(event != NULL, "invariant"); + assert(event->should_commit(), "invariant"); + set_current_safepoint_id(event); + event->commit(); +} + +static void post_safepoint_synchronize_event(EventSafepointStateSynchronization* event, + int initial_number_of_threads, + int threads_waiting_to_block, + unsigned int iterations) { + assert(event != NULL, "invariant"); + if (event->should_commit()) { + // Group this event together with the ones committed after the counter is increased + set_current_safepoint_id(event, 1); + event->set_initialThreadCount(initial_number_of_threads); + event->set_runningThreadCount(threads_waiting_to_block); + event->set_iterations(iterations); + event->commit(); + } +} + +static void post_safepoint_wait_blocked_event(EventSafepointWaitBlocked* event, + int initial_threads_waiting_to_block) { + assert(event != NULL, "invariant"); + assert(event->should_commit(), "invariant"); + set_current_safepoint_id(event); + event->set_runningThreadCount(initial_threads_waiting_to_block); + event->commit(); +} + +static void post_safepoint_cleanup_task_event(EventSafepointCleanupTask* event, + const char* name) { + assert(event != NULL, "invariant"); + if (event->should_commit()) { + set_current_safepoint_id(event); + event->set_name(name); + event->commit(); + } +} + +static void post_safepoint_end_event(EventSafepointEnd* event) { + assert(event != NULL, "invariant"); + if (event->should_commit()) { + // Group this event together with the ones committed before the counter increased + set_current_safepoint_id(event, -1); + event->commit(); + } +} + // -------------------------------------------------------------------------------------------------- // Implementation of Safepoint begin/end @@ -97,7 +165,7 @@ // Roll all threads forward to a safepoint and suspend them all void SafepointSynchronize::begin() { - + EventSafepointBegin begin_event; Thread* myThread = Thread::current(); assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint"); @@ -189,6 +257,9 @@ // between states, the safepointing code will wait for the thread to // block itself when it attempts transitions to a new state. // + EventSafepointStateSynchronization sync_event; + int initial_running = 0; + _state = _synchronizing; OrderAccess::fence(); @@ -243,8 +314,11 @@ } } - if (PrintSafepointStatistics && iterations == 0) { - begin_statistics(nof_threads, still_running); + if (iterations == 0) { + initial_running = still_running; + if (PrintSafepointStatistics) { + begin_statistics(nof_threads, still_running); + } } if (still_running > 0) { @@ -336,43 +410,56 @@ update_statistics_on_spin_end(); } + if (sync_event.should_commit()) { + post_safepoint_synchronize_event(&sync_event, initial_running, _waiting_to_block, iterations); + } + // wait until all threads are stopped - while (_waiting_to_block > 0) { - if (TraceSafepoint) tty->print_cr("Waiting for %d thread(s) to block", _waiting_to_block); - if (!SafepointTimeout || timeout_error_printed) { - Safepoint_lock->wait(true); // true, means with no safepoint checks - } else { - // Compute remaining time - jlong remaining_time = safepoint_limit_time - os::javaTimeNanos(); - - // If there is no remaining time, then there is an error - if (remaining_time < 0 || Safepoint_lock->wait(true, remaining_time / MICROUNITS)) { - print_safepoint_timeout(_blocking_timeout); + { + EventSafepointWaitBlocked wait_blocked_event; + int initial_waiting_to_block = _waiting_to_block; + + while (_waiting_to_block > 0) { + if (TraceSafepoint) tty->print_cr("Waiting for %d thread(s) to block", _waiting_to_block); + if (!SafepointTimeout || timeout_error_printed) { + Safepoint_lock->wait(true); // true, means with no safepoint checks + } else { + // Compute remaining time + jlong remaining_time = safepoint_limit_time - os::javaTimeNanos(); + + // If there is no remaining time, then there is an error + if (remaining_time < 0 || Safepoint_lock->wait(true, remaining_time / MICROUNITS)) { + print_safepoint_timeout(_blocking_timeout); + } } } - } - assert(_waiting_to_block == 0, "sanity check"); + assert(_waiting_to_block == 0, "sanity check"); #ifndef PRODUCT - if (SafepointTimeout) { - jlong current_time = os::javaTimeNanos(); - if (safepoint_limit_time < current_time) { - tty->print_cr("# SafepointSynchronize: Finished after " - INT64_FORMAT_W(6) " ms", - ((current_time - safepoint_limit_time) / MICROUNITS + - SafepointTimeoutDelay)); + if (SafepointTimeout) { + jlong current_time = os::javaTimeNanos(); + if (safepoint_limit_time < current_time) { + tty->print_cr("# SafepointSynchronize: Finished after " + INT64_FORMAT_W(6) " ms", + ((current_time - safepoint_limit_time) / MICROUNITS + + SafepointTimeoutDelay)); + } } - } #endif - assert((_safepoint_counter & 0x1) == 0, "must be even"); - assert(Threads_lock->owned_by_self(), "must hold Threads_lock"); - _safepoint_counter ++; + assert((_safepoint_counter & 0x1) == 0, "must be even"); + assert(Threads_lock->owned_by_self(), "must hold Threads_lock"); + _safepoint_counter ++; - // Record state - _state = _synchronized; + // Record state + _state = _synchronized; - OrderAccess::fence(); + OrderAccess::fence(); + + if (wait_blocked_event.should_commit()) { + post_safepoint_wait_blocked_event(&wait_blocked_event, initial_waiting_to_block); + } + } #ifdef ASSERT for (JavaThread *cur = Threads::first(); cur != NULL; cur = cur->next()) { @@ -395,12 +482,22 @@ } // Call stuff that needs to be run when a safepoint is just about to be completed - do_cleanup_tasks(); + { + EventSafepointCleanup cleanup_event; + do_cleanup_tasks(); + if (cleanup_event.should_commit()) { + post_safepoint_cleanup_event(&cleanup_event); + } + } if (PrintSafepointStatistics) { // Record how much time spend on the above cleanup tasks update_statistics_on_cleanup_end(os::javaTimeNanos()); } + + if (begin_event.should_commit()) { + post_safepoint_begin_event(&begin_event, nof_threads, _current_jni_active_count); + } } // Wake up all threads, so they are ready to resume execution after the safepoint @@ -409,6 +506,7 @@ assert(Threads_lock->owned_by_self(), "must hold Threads_lock"); assert((_safepoint_counter & 0x1) == 1, "must be odd"); + EventSafepointEnd event; _safepoint_counter ++; // memory fence isn't required here since an odd _safepoint_counter // value can do no harm and a fence is issued below anyway. @@ -494,6 +592,9 @@ // record this time so VMThread can keep track how much time has elasped // since last safepoint. _end_of_last_safepoint = os::javaTimeMillis(); + if (event.should_commit()) { + post_safepoint_end_event(&event); + } } bool SafepointSynchronize::is_cleanup_needed() { @@ -507,32 +608,62 @@ // Various cleaning tasks that should be done periodically at safepoints void SafepointSynchronize::do_cleanup_tasks() { { - TraceTime t1("deflating idle monitors", TraceSafepointCleanupTime); + const char* name = "deflating idle monitors"; + EventSafepointCleanupTask event; + TraceTime t1(name, TraceSafepointCleanupTime); ObjectSynchronizer::deflate_idle_monitors(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } { - TraceTime t2("updating inline caches", TraceSafepointCleanupTime); + const char* name = "updating inline caches"; + EventSafepointCleanupTask event; + TraceTime t2(name, TraceSafepointCleanupTime); InlineCacheBuffer::update_inline_caches(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } { - TraceTime t3("compilation policy safepoint handler", TraceSafepointCleanupTime); + const char* name = "compilation policy safepoint handler"; + EventSafepointCleanupTask event; + TraceTime t3(name, TraceSafepointCleanupTime); CompilationPolicy::policy()->do_safepoint_work(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } { - TraceTime t4("mark nmethods", TraceSafepointCleanupTime); + const char* name = "mark nmethods"; + EventSafepointCleanupTask event; + TraceTime t4(name, TraceSafepointCleanupTime); NMethodSweeper::mark_active_nmethods(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } if (SymbolTable::needs_rehashing()) { - TraceTime t5("rehashing symbol table", TraceSafepointCleanupTime); + const char* name = "rehashing symbol table"; + EventSafepointCleanupTask event; + TraceTime t5(name, TraceSafepointCleanupTime); SymbolTable::rehash_table(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } if (StringTable::needs_rehashing()) { - TraceTime t6("rehashing string table", TraceSafepointCleanupTime); + const char* name = "rehashing string table"; + EventSafepointCleanupTask event; + TraceTime t6(name, TraceSafepointCleanupTime); StringTable::rehash_table(); + if (event.should_commit()) { + post_safepoint_cleanup_task_event(&event, name); + } } // rotate log files?