< prev index next >
src/hotspot/share/runtime/handshake.cpp
Print this page
rev 53789 : 8234742: Improve handshake logging
Reviewed-by: dholmes, pchilanomate
*** 30,40 ****
#include "runtime/interfaceSupport.inline.hpp"
#include "runtime/orderAccess.hpp"
#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"
--- 30,39 ----
*** 49,58 ****
--- 48,58 ----
public:
HandshakeThreadsOperation(HandshakeClosure* cl) : _handshake_cl(cl) {}
void do_handshake(JavaThread* thread);
bool thread_has_completed() { return _done.trywait(); }
+ const char* name() { return _handshake_cl->name(); }
#ifdef ASSERT
void check_state() {
assert(!_done.trywait(), "Must be zero");
}
*** 194,220 ****
}
log_stream.flush();
fatal("Handshake operation timed out");
}
class VM_HandshakeOneThread: public VM_Handshake {
JavaThread* _target;
bool _thread_alive;
public:
VM_HandshakeOneThread(HandshakeThreadsOperation* op, JavaThread* target) :
VM_Handshake(op), _target(target), _thread_alive(false) {}
void doit() {
- jlong start_time_ns = os::javaTimeNanos();
DEBUG_ONLY(_op->check_state();)
! TraceTime timer("Performing single-target operation (vmoperation doit)", TRACETIME_LOG(Info, handshake));
ThreadsListHandle tlh;
if (tlh.includes(_target)) {
set_handshake(_target);
_thread_alive = true;
} else {
return;
}
if (!UseMembar) {
os::serialize_thread_states();
--- 194,232 ----
}
log_stream.flush();
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 = NULL) {
+ 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%s",
+ name, targets,
+ targets - vmt_executed,
+ completion_time,
+ extra != NULL ? ", " : "",
+ extra != NULL ? extra : "");
+ }
+ }
+
class VM_HandshakeOneThread: public VM_Handshake {
JavaThread* _target;
bool _thread_alive;
public:
VM_HandshakeOneThread(HandshakeThreadsOperation* op, JavaThread* target) :
VM_Handshake(op), _target(target), _thread_alive(false) {}
void doit() {
DEBUG_ONLY(_op->check_state();)
! jlong start_time_ns = os::javaTimeNanos();
ThreadsListHandle tlh;
if (tlh.includes(_target)) {
set_handshake(_target);
_thread_alive = true;
} else {
+ log_handshake_info(start_time_ns, _op->name(), 0, 0, "(thread dead)");
return;
}
if (!UseMembar) {
os::serialize_thread_states();
*** 231,246 ****
// We need to re-think this with SMR ThreadsList.
// There is an assumption in the code that the Threads_lock should be
// locked during certain phases.
{
MutexLockerEx ml(Threads_lock, Mutex::_no_safepoint_check_flag);
! pr = _target->handshake_process_by_vmthread();
}
hsy.add_result(pr);
hsy.process();
} while (!poll_for_completed_thread());
DEBUG_ONLY(_op->check_state();)
}
VMOp_Type type() const { return VMOp_HandshakeOneThread; }
bool thread_alive() const { return _thread_alive; }
--- 243,259 ----
// We need to re-think this with SMR ThreadsList.
// There is an assumption in the code that the Threads_lock should be
// locked during certain phases.
{
MutexLockerEx ml(Threads_lock, Mutex::_no_safepoint_check_flag);
! pr = _target->handshake_try_process_by_vmThread(_op);
}
hsy.add_result(pr);
hsy.process();
} while (!poll_for_completed_thread());
DEBUG_ONLY(_op->check_state();)
+ log_handshake_info(start_time_ns, _op->name(), 1, (pr == HandshakeState::_success) ? 1 : 0);
}
VMOp_Type type() const { return VMOp_HandshakeOneThread; }
bool thread_alive() const { return _thread_alive; }
*** 249,279 ****
class VM_HandshakeAllThreads: public VM_Handshake {
public:
VM_HandshakeAllThreads(HandshakeThreadsOperation* op) : VM_Handshake(op) {}
void doit() {
- jlong start_time_ns = os::javaTimeNanos();
DEBUG_ONLY(_op->check_state();)
! TraceTime timer("Performing operation (vmoperation doit)", TRACETIME_LOG(Info, handshake));
JavaThreadIteratorWithHandle jtiwh;
int number_of_threads_issued = 0;
for (JavaThread *thr = jtiwh.next(); thr != NULL; thr = jtiwh.next()) {
set_handshake(thr);
number_of_threads_issued++;
}
if (number_of_threads_issued < 1) {
! log_debug(handshake)("No threads to handshake.");
return;
}
if (!UseMembar) {
os::serialize_thread_states();
}
! log_debug(handshake)("Threads signaled, begin processing blocked threads by VMThtread");
HandshakeSpinYield hsy(start_time_ns);
int number_of_threads_completed = 0;
do {
// Check if handshake operation has timed out
if (handshake_has_timed_out(start_time_ns)) {
--- 262,293 ----
class VM_HandshakeAllThreads: public VM_Handshake {
public:
VM_HandshakeAllThreads(HandshakeThreadsOperation* op) : VM_Handshake(op) {}
void doit() {
DEBUG_ONLY(_op->check_state();)
!
! jlong start_time_ns = os::javaTimeNanos();
! int handshake_executed_by_vm_thread = 0;
JavaThreadIteratorWithHandle jtiwh;
int number_of_threads_issued = 0;
for (JavaThread *thr = jtiwh.next(); thr != NULL; thr = jtiwh.next()) {
set_handshake(thr);
number_of_threads_issued++;
}
if (number_of_threads_issued < 1) {
! log_handshake_info(start_time_ns, _op->name(), 0, 0);
return;
}
if (!UseMembar) {
os::serialize_thread_states();
}
! log_trace(handshake)("Threads signaled, begin processing blocked threads by VMThread");
HandshakeSpinYield hsy(start_time_ns);
int number_of_threads_completed = 0;
do {
// Check if handshake operation has timed out
if (handshake_has_timed_out(start_time_ns)) {
*** 290,300 ****
jtiwh.rewind();
MutexLockerEx ml(Threads_lock, Mutex::_no_safepoint_check_flag);
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.
! HandshakeState::ProcessResult pr = thr->handshake_process_by_vmthread();
hsy.add_result(pr);
}
hsy.process();
}
--- 304,317 ----
jtiwh.rewind();
MutexLockerEx ml(Threads_lock, Mutex::_no_safepoint_check_flag);
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.
! HandshakeState::ProcessResult pr = thr->handshake_try_process_by_vmThread(_op);
! if (pr == HandshakeState::_success) {
! handshake_executed_by_vm_thread++;
! }
hsy.add_result(pr);
}
hsy.process();
}
*** 304,313 ****
--- 321,332 ----
}
} 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; }
};
*** 321,330 ****
--- 340,350 ----
_handshake_cl(cl), _target_thread(NULL), _all_threads(true) {}
VM_HandshakeFallbackOperation(HandshakeClosure* cl, Thread* target) :
_handshake_cl(cl), _target_thread(target), _all_threads(false) {}
void doit() {
+ 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) {
_thread_alive = true;
}
*** 336,357 ****
VMOp_Type type() const { return VMOp_HandshakeFallback; }
bool thread_alive() const { return _thread_alive; }
};
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));
// Only actually execute the operation for non terminated threads.
if (!thread->is_terminated()) {
_handshake_cl->do_thread(thread);
}
// Use the semaphore to inform the VM thread that we have completed the operation
_done.signal();
}
void Handshake::execute(HandshakeClosure* thread_cl) {
if (ThreadLocalHandshakes) {
HandshakeThreadsOperation cto(thread_cl);
--- 356,383 ----
VMOp_Type type() const { return VMOp_HandshakeFallback; }
bool thread_alive() const { return _thread_alive; }
};
void HandshakeThreadsOperation::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()) {
_handshake_cl->do_thread(thread);
}
// 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(HandshakeClosure* thread_cl) {
if (ThreadLocalHandshakes) {
HandshakeThreadsOperation cto(thread_cl);
*** 450,460 ****
}
_semaphore.signal();
return false;
}
! HandshakeState::ProcessResult 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()) {
--- 476,486 ----
}
_semaphore.signal();
return false;
}
! HandshakeState::ProcessResult HandshakeState::try_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()) {
< prev index next >