# HG changeset patch
# User rehn
# Date 1574687202 -3600
#      Mon Nov 25 14:06:42 2019 +0100
# Node ID 6d2e7cf6e5503cc8d51b02a911182cc592a6a6de
# Parent  6ba3d8d4113522fb2951066f5d512ceab3c6f2c4
[mq]: handshake-logs

diff --git a/src/hotspot/share/gc/z/zHeap.cpp b/src/hotspot/share/gc/z/zHeap.cpp
--- a/src/hotspot/share/gc/z/zHeap.cpp
+++ b/src/hotspot/share/gc/z/zHeap.cpp
@@ -326,9 +326,10 @@
   _reference_processor.set_soft_reference_policy(clear);
 }
 
-class ZRendezvousClosure : public ThreadClosure {
+class ZRendezvousClosure : public HandshakeOperation {
 public:
-  virtual void do_thread(Thread* thread) {}
+  const char* name() { return "ZRendezvous"; };
+  void do_thread(JavaThread* thread) {}
 };
 
 void ZHeap::process_non_strong_references() {
@@ -349,8 +350,8 @@
   // this point the mutator could see the unblocked state and pass
   // this invalid oop through the normal barrier path, which would
   // incorrectly try to mark the oop.
-  ZRendezvousClosure cl;
-  Handshake::execute(&cl);
+  ZRendezvousClosure zr_hs;
+  Handshake::execute(&zr_hs);
 
   // Purge stale metadata and nmethods that were unlinked
   _unload.purge();
diff --git a/src/hotspot/share/gc/z/zMark.cpp b/src/hotspot/share/gc/z/zMark.cpp
--- a/src/hotspot/share/gc/z/zMark.cpp
+++ b/src/hotspot/share/gc/z/zMark.cpp
@@ -435,12 +435,23 @@
   }
 };
 
+class ZMarkFlushAndFreeStacksHandshake : public HandshakeOperation {
+  ZMarkFlushAndFreeStacksClosure* _cl;
+public:
+  ZMarkFlushAndFreeStacksHandshake(ZMarkFlushAndFreeStacksClosure* cl) : _cl(cl) {}
+  const char* name() { return "ZMarkFlushAndFreeStacks"; }
+  void do_thread(JavaThread* jt) {
+    _cl->do_thread(jt);
+  }
+};
+
 bool ZMark::flush(bool at_safepoint) {
   ZMarkFlushAndFreeStacksClosure cl(this);
   if (at_safepoint) {
     Threads::threads_do(&cl);
   } else {
-    Handshake::execute(&cl);
+    ZMarkFlushAndFreeStacksHandshake zmf_hs(&cl);
+    Handshake::execute(&zmf_hs);
   }
 
   // Returns true if more work is available
diff --git a/src/hotspot/share/prims/whitebox.cpp b/src/hotspot/share/prims/whitebox.cpp
--- a/src/hotspot/share/prims/whitebox.cpp
+++ b/src/hotspot/share/prims/whitebox.cpp
@@ -1995,12 +1995,12 @@
 #endif // INCLUDE_CDS
 
 WB_ENTRY(jint, WB_HandshakeWalkStack(JNIEnv* env, jobject wb, jobject thread_handle, jboolean all_threads))
-  class TraceSelfClosure : public ThreadClosure {
+  class TraceSelfHandshake : public HandshakeOperation {
     jint _num_threads_completed;
 
-    void do_thread(Thread* th) {
-      assert(th->is_Java_thread(), "sanity");
-      JavaThread* jt = (JavaThread*)th;
+   public:
+    const char* name() { return "WB_TraceSelf"; }
+    void do_thread(JavaThread* jt) {
       ResourceMark rm;
 
       jt->print_on(tty);
@@ -2009,23 +2009,22 @@
       Atomic::inc(&_num_threads_completed);
     }
 
-  public:
-    TraceSelfClosure() : _num_threads_completed(0) {}
+    TraceSelfHandshake() : _num_threads_completed(0) {}
 
     jint num_threads_completed() const { return _num_threads_completed; }
   };
-  TraceSelfClosure tsc;
+  TraceSelfHandshake ts_hs;
 
   if (all_threads) {
-    Handshake::execute(&tsc);
+    Handshake::execute(&ts_hs);
   } else {
     oop thread_oop = JNIHandles::resolve(thread_handle);
     if (thread_oop != NULL) {
       JavaThread* target = java_lang_Thread::thread(thread_oop);
-      Handshake::execute(&tsc, target);
+      Handshake::execute(&ts_hs, target);
     }
   }
-  return tsc.num_threads_completed();
+  return ts_hs.num_threads_completed();
 WB_END
 
 //Some convenience methods to deal with objects from java
diff --git a/src/hotspot/share/runtime/biasedLocking.cpp b/src/hotspot/share/runtime/biasedLocking.cpp
--- a/src/hotspot/share/runtime/biasedLocking.cpp
+++ b/src/hotspot/share/runtime/biasedLocking.cpp
@@ -504,7 +504,7 @@
 };
 
 
-class RevokeOneBias : public ThreadClosure {
+class RevokeOneBias : public HandshakeOperation {
 protected:
   Handle _obj;
   JavaThread* _requesting_thread;
@@ -520,7 +520,9 @@
     , _status_code(BiasedLocking::NOT_BIASED)
     , _biased_locker_id(0) {}
 
-  void do_thread(Thread* target) {
+  const char* name() { return "RevokeOneBias"; }
+
+  void do_thread(JavaThread* target) {
     assert(target == _biased_locker, "Wrong thread");
 
     oop o = _obj();
diff --git a/src/hotspot/share/runtime/deoptimization.cpp b/src/hotspot/share/runtime/deoptimization.cpp
--- a/src/hotspot/share/runtime/deoptimization.cpp
+++ b/src/hotspot/share/runtime/deoptimization.cpp
@@ -807,6 +807,15 @@
   }
 };
 
+class DeoptimizeMarkedHS : public HandshakeOperation {
+ public:
+  const char* name() { return "Deoptimize"; }
+  void do_thread(JavaThread* jt) {
+    jt->deoptimize_marked_methods();
+  }
+};
+
+
 void Deoptimization::deoptimize_all_marked() {
   ResourceMark rm;
   DeoptimizationMarker dm;
@@ -822,7 +831,7 @@
       MutexLocker mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
       CodeCache::make_marked_nmethods_not_entrant();
     }
-    DeoptimizeMarkedTC deopt;
+    DeoptimizeMarkedHS deopt;
     Handshake::execute(&deopt);
   }
 }
diff --git a/src/hotspot/share/runtime/handshake.cpp b/src/hotspot/share/runtime/handshake.cpp
--- a/src/hotspot/share/runtime/handshake.cpp
+++ b/src/hotspot/share/runtime/handshake.cpp
@@ -32,35 +32,12 @@
 #include "runtime/osThread.hpp"
 #include "runtime/semaphore.inline.hpp"
 #include "runtime/task.hpp"
-#include "runtime/timerTrace.hpp"
 #include "runtime/thread.hpp"
 #include "runtime/vmThread.hpp"
 #include "utilities/formatBuffer.hpp"
 #include "utilities/preserveException.hpp"
 
-class HandshakeOperation: public StackObj {
-public:
-  virtual void do_handshake(JavaThread* thread) = 0;
-};
-
-class HandshakeThreadsOperation: public HandshakeOperation {
-  static Semaphore _done;
-  ThreadClosure* _thread_cl;
-  bool _executed;
-public:
-  HandshakeThreadsOperation(ThreadClosure* cl) : _thread_cl(cl), _executed(false) {}
-  void do_handshake(JavaThread* thread);
-  bool thread_has_completed() { return _done.trywait(); }
-  bool executed() const { return _executed; }
-
-#ifdef ASSERT
-  void check_state() {
-    assert(!_done.trywait(), "Must be zero");
-  }
-#endif
-};
-
-Semaphore HandshakeThreadsOperation::_done(0);
+Semaphore HandshakeOperation::_done(0);
 
 class VM_Handshake: public VM_Operation {
   const jlong _handshake_timeout;
@@ -70,9 +47,9 @@
   bool evaluate_concurrently() const { return false; }
 
  protected:
-  HandshakeThreadsOperation* const _op;
+  HandshakeOperation* const _op;
 
-  VM_Handshake(HandshakeThreadsOperation* op) :
+  VM_Handshake(HandshakeOperation* op) :
       _handshake_timeout(TimeHelper::millis_to_counter(HandshakeTimeout)), _op(op) {}
 
   void set_handshake(JavaThread* target) {
@@ -108,28 +85,41 @@
   fatal("Handshake operation timed out");
 }
 
+static void log_handshake_info(jlong start_time_ns, const char* name, int targets, int vmt_executed, const char* extra) {
+  if (start_time_ns != 0) {
+    jlong completion_time = os::javaTimeNanos() - start_time_ns;
+    log_info(handshake)("Handshake \"%s\", Targeted threads: %d, Executed by targeted threads: %d, Total completion time: " JLONG_FORMAT " ns%s",
+                        name, targets, targets - vmt_executed, completion_time, extra);
+  }
+}
+
 class VM_HandshakeOneThread: public VM_Handshake {
   JavaThread* _target;
  public:
-  VM_HandshakeOneThread(HandshakeThreadsOperation* op, JavaThread* target) :
+  VM_HandshakeOneThread(HandshakeOperation* op, JavaThread* target) :
     VM_Handshake(op), _target(target) {}
 
   void doit() {
     DEBUG_ONLY(_op->check_state();)
-    TraceTime timer("Finished executing single-target operation (VM_HandshakeOneThread::doit)", TRACETIME_LOG(Info, handshake));
+
+    jlong start_time_ns = 0;
+    if (log_is_enabled(Info, handshake)) {
+      start_time_ns = os::javaTimeNanos();
+    }
 
     ThreadsListHandle tlh;
     if (tlh.includes(_target)) {
       set_handshake(_target);
     } else {
-      log_trace(handshake)("JavaThread " INTPTR_FORMAT " is not alive", p2i(_target));
+      log_handshake_info(start_time_ns, _op->name(), 0, 0, " (thread dead)");
       return;
     }
 
     log_trace(handshake)("JavaThread " INTPTR_FORMAT " signaled, begin attempt to process by VMThtread", p2i(_target));
-    jlong start_time = os::elapsed_counter();
+    jlong timeout_start_time = os::elapsed_counter();
+    bool by_vm_thread = false;
     do {
-      if (handshake_has_timed_out(start_time)) {
+      if (handshake_has_timed_out(timeout_start_time)) {
         handle_timeout();
       }
 
@@ -138,10 +128,11 @@
       // locked during certain phases.
       {
         MutexLocker ml(Threads_lock);
-        _target->handshake_process_by_vmthread();
+        by_vm_thread = _target->handshake_process_by_vmthread();
       }
     } while (!poll_for_completed_thread());
     DEBUG_ONLY(_op->check_state();)
+    log_handshake_info(start_time_ns, _op->name(), 1, by_vm_thread ? 1 : 0, "");
   }
 
   VMOp_Type type() const { return VMOp_HandshakeOneThread; }
@@ -151,11 +142,16 @@
 
 class VM_HandshakeAllThreads: public VM_Handshake {
  public:
-  VM_HandshakeAllThreads(HandshakeThreadsOperation* op) : VM_Handshake(op) {}
+  VM_HandshakeAllThreads(HandshakeOperation* op) : VM_Handshake(op) {}
 
   void doit() {
     DEBUG_ONLY(_op->check_state();)
-    TraceTime timer("Finished executing multi-target operation (VM_HandshakeAllThreads::doit)", TRACETIME_LOG(Info, handshake));
+
+    jlong start_time_ns = 0;
+    if (log_is_enabled(Info, handshake)) {
+      start_time_ns = os::javaTimeNanos();
+    }
+    int handshake_executed_by_vm_thread = 0;
 
     JavaThreadIteratorWithHandle jtiwh;
     int number_of_threads_issued = 0;
@@ -165,11 +161,11 @@
     }
 
     if (number_of_threads_issued < 1) {
-      log_debug(handshake)("No threads to handshake.");
+      log_trace(handshake)("No threads to handshake.");
       return;
     }
 
-    log_debug(handshake)("Threads signaled, begin processing blocked threads by VMThtread");
+    log_trace(handshake)("Threads signaled, begin processing blocked threads by VMThtread");
     const jlong start_time = os::elapsed_counter();
     int number_of_threads_completed = 0;
     do {
@@ -190,7 +186,9 @@
           for (JavaThread *thr = jtiwh.next(); thr != NULL; thr = jtiwh.next()) {
             // A new thread on the ThreadsList will not have an operation,
             // hence it is skipped in handshake_process_by_vmthread.
-            thr->handshake_process_by_vmthread();
+            if (thr->handshake_process_by_vmthread()) {
+              handshake_executed_by_vm_thread++;
+            }
           }
       }
 
@@ -202,30 +200,32 @@
     } while (number_of_threads_issued > number_of_threads_completed);
     assert(number_of_threads_issued == number_of_threads_completed, "Must be the same");
     DEBUG_ONLY(_op->check_state();)
+
+    log_handshake_info(start_time_ns, _op->name(), number_of_threads_issued, handshake_executed_by_vm_thread, "");
   }
 
   VMOp_Type type() const { return VMOp_HandshakeAllThreads; }
 };
 
 class VM_HandshakeFallbackOperation : public VM_Operation {
-  ThreadClosure* _thread_cl;
+  HandshakeOperation* _hs_op;
   Thread* _target_thread;
   bool _all_threads;
   bool _executed;
 public:
-  VM_HandshakeFallbackOperation(ThreadClosure* cl) :
-      _thread_cl(cl), _target_thread(NULL), _all_threads(true), _executed(false) {}
-  VM_HandshakeFallbackOperation(ThreadClosure* cl, Thread* target) :
-      _thread_cl(cl), _target_thread(target), _all_threads(false), _executed(false) {}
+  VM_HandshakeFallbackOperation(HandshakeOperation* hs_op) :
+      _hs_op(hs_op), _target_thread(NULL), _all_threads(true), _executed(false) {}
+  VM_HandshakeFallbackOperation(HandshakeOperation* hs_op, Thread* target) :
+      _hs_op(hs_op), _target_thread(target), _all_threads(false), _executed(false) {}
 
   void doit() {
-    log_trace(handshake)("VMThread executing VM_HandshakeFallbackOperation");
+    log_trace(handshake)("VMThread executing VM_HandshakeFallbackOperation, operation: %s", name());
     for (JavaThreadIteratorWithHandle jtiwh; JavaThread *t = jtiwh.next(); ) {
       if (_all_threads || t == _target_thread) {
         if (t == _target_thread) {
           _executed = true;
         }
-        _thread_cl->do_thread(t);
+        _hs_op->do_thread(t);
       }
     }
   }
@@ -234,41 +234,45 @@
   bool executed() const { return _executed; }
 };
 
-void HandshakeThreadsOperation::do_handshake(JavaThread* thread) {
-  ResourceMark rm;
-  FormatBufferResource message("Operation for thread " PTR_FORMAT ", is_vm_thread: %s",
-                               p2i(thread), BOOL_TO_STR(Thread::current()->is_VM_thread()));
-  TraceTime timer(message, TRACETIME_LOG(Debug, handshake, task));
+void HandshakeOperation::do_handshake(JavaThread* thread) {
+  jlong start_time_ns = 0;
+  if (log_is_enabled(Debug, handshake, task)) {
+    start_time_ns = os::javaTimeNanos();
+  }
 
   // Only actually execute the operation for non terminated threads.
   if (!thread->is_terminated()) {
-    _thread_cl->do_thread(thread);
+    do_thread(thread);
     _executed = true;
   }
 
   // Use the semaphore to inform the VM thread that we have completed the operation
   _done.signal();
+
+  if (start_time_ns != 0) {
+    jlong completion_time = os::javaTimeNanos() - start_time_ns;
+    log_debug(handshake, task)("Operation: %s for thread " PTR_FORMAT ", is_vm_thread: %s, completed in " JLONG_FORMAT " ns",
+                               name(), p2i(thread), BOOL_TO_STR(Thread::current()->is_VM_thread()), completion_time);
+  }
 }
 
-void Handshake::execute(ThreadClosure* thread_cl) {
+void Handshake::execute(HandshakeOperation* hs_op) {
   if (ThreadLocalHandshakes) {
-    HandshakeThreadsOperation cto(thread_cl);
-    VM_HandshakeAllThreads handshake(&cto);
+    VM_HandshakeAllThreads handshake(hs_op);
     VMThread::execute(&handshake);
   } else {
-    VM_HandshakeFallbackOperation op(thread_cl);
+    VM_HandshakeFallbackOperation op(hs_op);
     VMThread::execute(&op);
   }
 }
 
-bool Handshake::execute(ThreadClosure* thread_cl, JavaThread* target) {
+bool Handshake::execute(HandshakeOperation* hs_op, JavaThread* target) {
   if (ThreadLocalHandshakes) {
-    HandshakeThreadsOperation cto(thread_cl);
-    VM_HandshakeOneThread handshake(&cto, target);
+    VM_HandshakeOneThread handshake(hs_op, target);
     VMThread::execute(&handshake);
     return handshake.executed();
   } else {
-    VM_HandshakeFallbackOperation op(thread_cl, target);
+    VM_HandshakeFallbackOperation op(hs_op, target);
     VMThread::execute(&op);
     return op.executed();
   }
@@ -346,37 +350,41 @@
   return false;
 }
 
-void HandshakeState::process_by_vmthread(JavaThread* target) {
+bool HandshakeState::process_by_vmthread(JavaThread* target) {
   assert(Thread::current()->is_VM_thread(), "should call from vm thread");
   // Threads_lock must be held here, but that is assert()ed in
   // possibly_vmthread_can_process_handshake().
 
   if (!has_operation()) {
     // JT has already cleared its handshake
-    return;
+    return false;
   }
 
   if (!possibly_vmthread_can_process_handshake(target)) {
     // JT is observed in an unsafe state, it must notice the handshake itself
-    return;
+    return false;
   }
 
   // Claim the semaphore if there still an operation to be executed.
   if (!claim_handshake_for_vmthread()) {
-    return;
+    return false;
   }
 
   // If we own the semaphore at this point and while owning the semaphore
   // can observe a safe state the thread cannot possibly continue without
   // getting caught by the semaphore.
+  bool executed = false;
   if (vmthread_can_process_handshake(target)) {
     guarantee(!_semaphore.trywait(), "we should already own the semaphore");
     log_trace(handshake)("Processing handshake by VMThtread");
     _operation->do_handshake(target);
     // Disarm after VM thread have executed the operation.
     clear_handshake(target);
-    // Release the thread
+    executed = true;
   }
 
+  // Release the thread
   _semaphore.signal();
+
+  return executed;
 }
diff --git a/src/hotspot/share/runtime/handshake.hpp b/src/hotspot/share/runtime/handshake.hpp
--- a/src/hotspot/share/runtime/handshake.hpp
+++ b/src/hotspot/share/runtime/handshake.hpp
@@ -29,7 +29,6 @@
 #include "runtime/flags/flagSetting.hpp"
 #include "runtime/semaphore.hpp"
 
-class ThreadClosure;
 class JavaThread;
 
 // A handshake operation is a callback that is executed for each JavaThread
@@ -37,15 +36,34 @@
 // either by the thread itself or by the VM thread while keeping the thread
 // in a blocked state. A handshake can be performed with a single
 // JavaThread as well.
+class HandshakeOperation: public StackObj {
+  static Semaphore _done;
+  bool _executed;
+public:
+  HandshakeOperation() : _executed(false) {}
+
+  void do_handshake(JavaThread* thread);
+  bool thread_has_completed() { return _done.trywait(); }
+  bool executed() const { return _executed; }
+
+#ifdef ASSERT
+  void check_state() {
+    assert(!_done.trywait(), "Must be zero");
+  }
+#endif
+
+  // Impl
+  virtual void do_thread(JavaThread* thread) = 0;
+  virtual const char* name() = 0;
+};
+
 class Handshake : public AllStatic {
  public:
   // Execution of handshake operation
-  static void execute(ThreadClosure* thread_cl);
-  static bool execute(ThreadClosure* thread_cl, JavaThread* target);
+  static void execute(HandshakeOperation* hs_op);
+  static bool execute(HandshakeOperation* hs_op, JavaThread* target);
 };
 
-class HandshakeOperation;
-
 // The HandshakeState keep tracks of an ongoing handshake for one JavaThread.
 // VM thread and JavaThread are serialized with the semaphore making sure
 // the operation is only done by either VM thread on behalf of the JavaThread
@@ -78,7 +96,7 @@
     }
   }
 
-  void process_by_vmthread(JavaThread* target);
+  bool process_by_vmthread(JavaThread* target);
 };
 
 #endif // SHARE_RUNTIME_HANDSHAKE_HPP
diff --git a/src/hotspot/share/runtime/sweeper.cpp b/src/hotspot/share/runtime/sweeper.cpp
--- a/src/hotspot/share/runtime/sweeper.cpp
+++ b/src/hotspot/share/runtime/sweeper.cpp
@@ -311,6 +311,16 @@
   return &set_hotness_closure;
 }
 
+class NMethodMarkingHandshake : public HandshakeOperation {
+  NMethodMarkingThreadClosure* _cl;
+ public:
+  NMethodMarkingHandshake(NMethodMarkingThreadClosure* cl) : _cl(cl) {}
+  const char* name() { return "NMethodMarking";};
+  void do_thread(JavaThread* jt) {
+    _cl->do_thread(jt);
+  }
+};
+
 /**
   * This function triggers a VM operation that does stack scanning of active
   * methods. Stack scanning is mandatory for the sweeper to make progress.
@@ -326,7 +336,8 @@
       }
       if (code_cl != NULL) {
         NMethodMarkingThreadClosure tcl(code_cl);
-        Handshake::execute(&tcl);
+        NMethodMarkingHandshake nm_hs(&tcl);
+        Handshake::execute(&nm_hs);
       }
     } else {
       VM_MarkActiveNMethods op;
diff --git a/src/hotspot/share/runtime/thread.hpp b/src/hotspot/share/runtime/thread.hpp
--- a/src/hotspot/share/runtime/thread.hpp
+++ b/src/hotspot/share/runtime/thread.hpp
@@ -1329,8 +1329,8 @@
     _handshake.process_by_self(this);
   }
 
-  void handshake_process_by_vmthread() {
-    _handshake.process_by_vmthread(this);
+  bool handshake_process_by_vmthread() {
+    return _handshake.process_by_vmthread(this);
   }
 
   // Suspend/resume support for JavaThread
diff --git a/src/hotspot/share/runtime/vmThread.cpp b/src/hotspot/share/runtime/vmThread.cpp
--- a/src/hotspot/share/runtime/vmThread.cpp
+++ b/src/hotspot/share/runtime/vmThread.cpp
@@ -429,12 +429,11 @@
 static VM_None    safepointALot_op("SafepointALot");
 static VM_Cleanup cleanup_op;
 
-class HandshakeALotTC : public ThreadClosure {
+class HandshakeALotHS : public HandshakeOperation {
  public:
-  virtual void do_thread(Thread* thread) {
+  const char* name() { return "HandshakeALot"; };
+  void do_thread(JavaThread* jt) {
 #ifdef ASSERT
-    assert(thread->is_Java_thread(), "must be");
-    JavaThread* jt = (JavaThread*)thread;
     jt->verify_states_for_handshake();
 #endif
   }
@@ -443,8 +442,8 @@
 VM_Operation* VMThread::no_op_safepoint() {
   // Check for handshakes first since we may need to return a VMop.
   if (HandshakeALot) {
-    HandshakeALotTC haltc;
-    Handshake::execute(&haltc);
+    HandshakeALotHS halhs;
+    Handshake::execute(&halhs);
   }
   // Check for a cleanup before SafepointALot to keep stats correct.
   long interval_ms = SafepointTracing::time_since_last_safepoint_ms();