8336299: Improve GCLocker stall diagnostics

Reviewed-by: ayang, shade, tschatzl
This commit is contained in:
Neethu Prasad 2024-08-27 16:45:34 +00:00
parent 2e96f159aa
commit 284c3cde5e

@ -33,11 +33,33 @@
#include "runtime/javaThread.inline.hpp"
#include "runtime/safepoint.hpp"
#include "runtime/threadSMR.hpp"
#include "utilities/ticks.hpp"
volatile jint GCLocker::_jni_lock_count = 0;
volatile bool GCLocker::_needs_gc = false;
unsigned int GCLocker::_total_collections = 0;
// GCLockerTimingDebugLogger tracks specific timing information for GC lock waits.
class GCLockerTimingDebugLogger : public StackObj {
const char* _log_message;
Ticks _start;
public:
GCLockerTimingDebugLogger(const char* log_message) : _log_message(log_message) {
assert(_log_message != nullptr, "GC locker debug message must be set.");
_start = Ticks::now();
}
~GCLockerTimingDebugLogger() {
Log(gc, jni) log;
if (log.is_debug()) {
ResourceMark rm; // JavaThread::name() allocates to convert to UTF8
const Tickspan elapsed_time = Ticks::now() - _start;
log.debug("%s Resumed after " UINT64_FORMAT "ms. Thread \"%s\".", _log_message, elapsed_time.milliseconds(), Thread::current()->name());
}
}
};
#ifdef ASSERT
volatile jint GCLocker::_debug_jni_lock_count = 0;
#endif
@ -110,11 +132,11 @@ void GCLocker::stall_until_clear() {
if (needs_gc()) {
GCLockerTracer::inc_stall_count();
log_debug_jni("Allocation failed. Thread stalled by JNI critical section.");
}
// Wait for _needs_gc to be cleared
while (needs_gc()) {
ml.wait();
GCLockerTimingDebugLogger logger("Thread stalled by JNI critical section.");
// Wait for _needs_gc to be cleared
while (needs_gc()) {
ml.wait();
}
}
}
@ -127,16 +149,20 @@ void GCLocker::jni_lock(JavaThread* thread) {
assert(!thread->in_critical(), "shouldn't currently be in a critical region");
MonitorLocker ml(JNICritical_lock);
// Block entering threads if there's a pending GC request.
while (needs_gc()) {
// There's at least one thread that has not left the critical region (CR)
// completely. When that last thread (no new threads can enter CR due to the
// blocking) exits CR, it calls `jni_unlock`, which sets `_needs_gc`
// to false and wakes up all blocked threads.
// We would like to assert #threads in CR to be > 0, `_jni_lock_count > 0`
// in the code, but it's too strong; it's possible that the last thread
// has called `jni_unlock`, but not yet finished the call, e.g. initiating
// a GCCause::_gc_locker GC.
ml.wait();
if (needs_gc()) {
log_debug_jni("Blocking thread as there is a pending GC request");
GCLockerTimingDebugLogger logger("Thread blocked to enter critical region.");
while (needs_gc()) {
// There's at least one thread that has not left the critical region (CR)
// completely. When that last thread (no new threads can enter CR due to the
// blocking) exits CR, it calls `jni_unlock`, which sets `_needs_gc`
// to false and wakes up all blocked threads.
// We would like to assert #threads in CR to be > 0, `_jni_lock_count > 0`
// in the code, but it's too strong; it's possible that the last thread
// has called `jni_unlock`, but not yet finished the call, e.g. initiating
// a GCCause::_gc_locker GC.
ml.wait();
}
}
thread->enter_critical();
_jni_lock_count++;
@ -148,6 +174,7 @@ void GCLocker::jni_unlock(JavaThread* thread) {
MutexLocker mu(JNICritical_lock);
_jni_lock_count--;
decrement_debug_jni_lock_count();
log_debug_jni("Thread exiting critical region.");
thread->exit_critical();
if (needs_gc() && !is_active_internal()) {
// We're the last thread out. Request a GC.
@ -161,7 +188,7 @@ void GCLocker::jni_unlock(JavaThread* thread) {
{
// Must give up the lock while at a safepoint
MutexUnlocker munlock(JNICritical_lock);
log_debug_jni("Performing GC after exiting critical section.");
log_debug_jni("Last thread exiting. Performing GC after exiting critical section.");
Universe::heap()->collect(GCCause::_gc_locker);
}
_needs_gc = false;