8350313: Include timings for leaving safepoint in safepoint logging

Reviewed-by: shade, dholmes

Author: Xiaolong Peng

src/hotspot/share/runtime/safepoint.cpp

@@ -468,6 +468,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");
 
@@ -862,6 +864,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_leave_time_ns = 0;
 jlong SafepointTracing::_last_safepoint_end_time_ns = 0;
 jlong SafepointTracing::_last_app_time_ns = 0;
 int SafepointTracing::_nof_threads = 0;
@@ -963,6 +966,10 @@ void SafepointTracing::synchronized(int nof_threads, int nof_running, int traps)
   RuntimeService::record_safepoint_synchronized(_last_safepoint_sync_time_ns - _last_safepoint_begin_time_ns);
 }
 
+void SafepointTracing::leave() {
+  _last_safepoint_leave_time_ns = os::javaTimeNanos();
+}
+
 void SafepointTracing::end() {
   _last_safepoint_end_time_ns = os::javaTimeNanos();
 
@@ -981,12 +988,14 @@ void SafepointTracing::end() {
      "Time since last: " JLONG_FORMAT " ns, "
      "Reaching safepoint: " 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_end_time_ns     - _last_safepoint_sync_time_ns,
-      _last_safepoint_end_time_ns     - _last_safepoint_begin_time_ns
+      _last_safepoint_sync_time_ns  - _last_safepoint_begin_time_ns,
+      _last_safepoint_leave_time_ns - _last_safepoint_sync_time_ns,
+      _last_safepoint_end_time_ns   - _last_safepoint_leave_time_ns,
+      _last_safepoint_end_time_ns   - _last_safepoint_begin_time_ns
      );
 
   RuntimeService::record_safepoint_end(_last_safepoint_end_time_ns - _last_safepoint_sync_time_ns);

src/hotspot/share/runtime/safepoint.hpp

@@ -230,6 +230,7 @@ class SafepointTracing : public AllStatic {
   // Absolute
   static jlong _last_safepoint_begin_time_ns;
   static jlong _last_safepoint_sync_time_ns;
+  static jlong _last_safepoint_leave_time_ns;
   static jlong _last_safepoint_end_time_ns;
 
   // Relative
@@ -251,6 +252,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 leave();
   static void end();
 
   static void statistics_exit_log();