8350313: Include timings for leaving safepoint in safepoint logging

Reviewed-by: phh
Backport-of: 9ec46968fbfddf99a8349cb6903d24b1c2fdaf1d

Author: Xiaolong Peng

src/hotspot/share/runtime/safepoint.cpp

@@ -500,6 +500,8 @@ void SafepointSynchronize::disarm_safepoint() {
 // operation has been carried out
 void SafepointSynchronize::end() {
   assert(Threads_lock->owned_by_self(), "must hold Threads_lock");
+  SafepointTracing::leave();
+
   EventSafepointEnd event;
   assert(Thread::current()->is_VM_thread(), "Only VM thread can execute a safepoint");
 
@@ -1028,6 +1030,7 @@ void ThreadSafepointState::handle_polling_page_exception() {
 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_leave_time_ns = 0;
 jlong SafepointTracing::_last_safepoint_end_time_ns = 0;
 jlong SafepointTracing::_last_app_time_ns = 0;
 int SafepointTracing::_nof_threads = 0;
@@ -1139,6 +1142,10 @@ void SafepointTracing::cleanup() {
   _last_safepoint_cleanup_time_ns = os::javaTimeNanos();
 }
 
+void SafepointTracing::leave() {
+  _last_safepoint_leave_time_ns = os::javaTimeNanos();
+}
+
 void SafepointTracing::end() {
   _last_safepoint_end_time_ns = os::javaTimeNanos();
 
@@ -1161,12 +1168,14 @@ void SafepointTracing::end() {
      "Reaching safepoint: " JLONG_FORMAT " ns, "
      "Cleanup: " JLONG_FORMAT " ns, "
      "At safepoint: " JLONG_FORMAT " ns, "
+     "Leaving safepoint: " JLONG_FORMAT " ns, "
      "Total: " JLONG_FORMAT " ns",
       VM_Operation::name(_current_type),
       _last_app_time_ns,
       _last_safepoint_sync_time_ns    - _last_safepoint_begin_time_ns,
       _last_safepoint_cleanup_time_ns - _last_safepoint_sync_time_ns,
-      _last_safepoint_end_time_ns     - _last_safepoint_cleanup_time_ns,
+      _last_safepoint_leave_time_ns   - _last_safepoint_cleanup_time_ns,
+      _last_safepoint_end_time_ns     - _last_safepoint_leave_time_ns,
       _last_safepoint_end_time_ns     - _last_safepoint_begin_time_ns
      );
 

src/hotspot/share/runtime/safepoint.hpp

@@ -246,6 +246,7 @@ class SafepointTracing : public AllStatic {
   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_leave_time_ns;
   static jlong _last_safepoint_end_time_ns;
 
   // Relative
@@ -269,6 +270,7 @@ class SafepointTracing : public AllStatic {
   static void begin(VM_Operation::VMOp_Type type);
   static void synchronized(int nof_threads, int nof_running, int traps);
   static void cleanup();
+  static void leave();
   static void end();
 
   static void statistics_exit_log();