8259808: Add JFR event to detect GC locker stall

Reviewed-by: sjohanss, tschatzl, egahlin
This commit is contained in:
Denghui Dong 2021-01-27 15:28:46 +00:00 committed by Thomas Schatzl
parent f353fcf256
commit 311a0a91ba
10 changed files with 224 additions and 0 deletions
src
hotspot/share
jdk.jfr/share/conf/jfr
test
jdk/jdk/jfr/event/gc/detailed
lib
jdk/test/lib/jfr
sun/hotspot

@ -25,6 +25,7 @@
#include "precompiled.hpp"
#include "gc/shared/collectedHeap.hpp"
#include "gc/shared/gcLocker.hpp"
#include "gc/shared/gcTrace.hpp"
#include "memory/resourceArea.hpp"
#include "memory/universe.hpp"
#include "logging/log.hpp"
@ -97,6 +98,7 @@ bool GCLocker::check_active_before_gc() {
if (is_active() && !_needs_gc) {
verify_critical_count();
_needs_gc = true;
GCLockerTracer::start_gc_locker(_jni_lock_count);
log_debug_jni("Setting _needs_gc.");
}
return is_active();
@ -107,6 +109,7 @@ void GCLocker::stall_until_clear() {
MonitorLocker ml(JNICritical_lock);
if (needs_gc()) {
GCLockerTracer::inc_stall_count();
log_debug_jni("Allocation failed. Thread stalled by JNI critical section.");
}
@ -152,6 +155,7 @@ void GCLocker::jni_unlock(JavaThread* thread) {
// getting the count, else there may be unnecessary GCLocker GCs.
_total_collections = Universe::heap()->total_collections();
_doing_gc = true;
GCLockerTracer::report_gc_locker();
{
// Must give up the lock while at a safepoint
MutexUnlocker munlock(JNICritical_lock);

@ -207,4 +207,19 @@ class DefNewTracer : public YoungGCTracer {
DefNewTracer() : YoungGCTracer(DefNew) {}
};
class GCLockerTracer : public AllStatic {
#if INCLUDE_JFR
private:
static Ticks _needs_gc_start_timestamp;
static volatile jint _jni_lock_count;
static volatile jint _stall_count;
#endif
static bool is_started() NOT_JFR_RETURN_(false);
public:
static void start_gc_locker(jint jni_lock_count) NOT_JFR_RETURN();
static void inc_stall_count() NOT_JFR_RETURN();
static void report_gc_locker() NOT_JFR_RETURN();
};
#endif // SHARE_GC_SHARED_GCTRACE_HPP

@ -344,3 +344,48 @@ void GCTracer::send_phase_events(TimePartitions* time_partitions) const {
phase->accept(&phase_reporter);
}
}
#if INCLUDE_JFR
Ticks GCLockerTracer::_needs_gc_start_timestamp;
volatile jint GCLockerTracer::_jni_lock_count = 0;
volatile jint GCLockerTracer::_stall_count = 0;
bool GCLockerTracer::is_started() {
return _needs_gc_start_timestamp != Ticks();
}
void GCLockerTracer::start_gc_locker(const jint jni_lock_count) {
assert(SafepointSynchronize::is_at_safepoint(), "sanity");
assert(!is_started(), "sanity");
assert(_jni_lock_count == 0, "sanity");
assert(_stall_count == 0, "sanity");
if (EventGCLocker::is_enabled()) {
_needs_gc_start_timestamp.stamp();
_jni_lock_count = jni_lock_count;
}
}
void GCLockerTracer::inc_stall_count() {
if (is_started()) {
_stall_count++;
}
}
void GCLockerTracer::report_gc_locker() {
if (is_started()) {
EventGCLocker event(UNTIMED);
if (event.should_commit()) {
event.set_starttime(_needs_gc_start_timestamp);
event.set_lockCount(_jni_lock_count);
event.set_stallCount(_stall_count);
event.commit();
}
// reset
_needs_gc_start_timestamp = Ticks();
_jni_lock_count = 0;
_stall_count = 0;
assert(!is_started(), "sanity");
}
}
#endif

@ -1090,6 +1090,11 @@
<Field type="boolean" name="onOutOfMemoryError" label="On Out of Memory Error" />
</Event>
<Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" label="GC Locker" startTime="true" thread="true" stackTrace="true">
<Field type="uint" name="lockCount" label="Lock Count" description="The number of Java threads in a critical section when the GC locker is started" />
<Field type="uint" name="stallCount" label="Stall Count" description="The number of Java threads stalled by the GC locker" />
</Event>
<Type name="DeoptimizationReason" label="Deoptimization Reason">
<Field type="string" name="reason" label="Reason" />
</Type>

@ -39,6 +39,7 @@
#include "compiler/directivesParser.hpp"
#include "gc/shared/concurrentGCBreakpoints.hpp"
#include "gc/shared/gcConfig.hpp"
#include "gc/shared/gcLocker.inline.hpp"
#include "gc/shared/genArguments.hpp"
#include "gc/shared/genCollectedHeap.hpp"
#include "jvmtifiles/jvmtiEnv.hpp"
@ -2318,6 +2319,14 @@ WB_ENTRY(jstring, WB_GetLibcName(JNIEnv* env, jobject o))
return info_string;
WB_END
WB_ENTRY(void, WB_LockCritical(JNIEnv* env, jobject wb))
GCLocker::lock_critical(thread);
WB_END
WB_ENTRY(void, WB_UnlockCritical(JNIEnv* env, jobject wb))
GCLocker::unlock_critical(thread);
WB_END
#define CC (char*)
static JNINativeMethod methods[] = {
@ -2581,6 +2590,9 @@ static JNINativeMethod methods[] = {
{CC"isJVMTIIncluded", CC"()Z", (void*)&WB_IsJVMTIIncluded},
{CC"waitUnsafe", CC"(I)V", (void*)&WB_WaitUnsafe},
{CC"getLibcName", CC"()Ljava/lang/String;", (void*)&WB_GetLibcName},
{CC"lockCritical", CC"()V", (void*)&WB_LockCritical},
{CC"unlockCritical", CC"()V", (void*)&WB_UnlockCritical},
};

@ -783,6 +783,11 @@
<setting name="period">5 s</setting>
</event>
<event name="jdk.GCLocker">
<setting name="enabled">true</setting>
<setting name="threshold">1 s</setting>
<setting name="stackTrace">true</setting>
</event>

@ -783,6 +783,11 @@
<setting name="period">5 s</setting>
</event>
<event name="jdk.GCLocker">
<setting name="enabled">true</setting>
<setting name="threshold">100 ms</setting>
<setting name="stackTrace">true</setting>
</event>

@ -0,0 +1,128 @@
/*
* Copyright (c) 2021, Alibaba Group Holding Limited. All Rights Reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation. Alibaba designates this
* particular file as subject to the "Classpath" exception as provided
* by Oracle in the LICENSE file that accompanied this code.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*/
/**
* @test TestGCLockerEvent
* @key jfr
* @requires vm.hasJFR
* @library /test/lib
* @build sun.hotspot.WhiteBox
* @run driver ClassFileInstaller sun.hotspot.WhiteBox
* @run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xmx32m -Xms32m -Xmn12m -XX:+UseG1GC jdk.jfr.event.gc.detailed.TestGCLockerEvent
*/
package jdk.jfr.event.gc.detailed;
import static jdk.test.lib.Asserts.assertTrue;
import java.util.concurrent.CountDownLatch;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.test.lib.jfr.EventNames;
import jdk.test.lib.jfr.Events;
import sun.hotspot.WhiteBox;
public class TestGCLockerEvent {
private static final String EVENT_NAME = EventNames.GCLocker;
private static final int CRITICAL_THREAD_COUNT = 4;
private static final CountDownLatch LOCK_COUNT_SIGNAL = new CountDownLatch(CRITICAL_THREAD_COUNT);
private static final CountDownLatch UNLOCK_SIGNAL = new CountDownLatch(1);
private static final CountDownLatch UNLOCK_COUNT_SIGNAL = new CountDownLatch(CRITICAL_THREAD_COUNT);
private static final String CRITICAL_THREAD_NAME_PREFIX = "Critical Thread ";
private static final int STALL_THREAD_COUNT = 8;
private static final CountDownLatch STALL_COUNT_SIGNAL = new CountDownLatch(STALL_THREAD_COUNT);
private static final int LOOP = 32;
private static final int M = 1024 * 1024;
public static void main(String[] args) throws Exception {
var recording = new Recording();
recording.enable(EVENT_NAME);
recording.start();
startCriticalThreads();
LOCK_COUNT_SIGNAL.await();
startStallThreads();
STALL_COUNT_SIGNAL.await();
// Wait threads to be stalled
Thread.sleep(1500);
UNLOCK_SIGNAL.countDown();
UNLOCK_COUNT_SIGNAL.await();
recording.stop();
// Verify recording
var all = Events.fromRecording(recording);
Events.hasEvents(all);
var event = all.get(0);
assertTrue(Events.isEventType(event, EVENT_NAME));
Events.assertField(event, "lockCount").equal(CRITICAL_THREAD_COUNT);
Events.assertField(event, "stallCount").atLeast(STALL_THREAD_COUNT);
assertTrue(event.getThread().getJavaName().startsWith(CRITICAL_THREAD_NAME_PREFIX));
recording.close();
}
private static void startCriticalThreads() {
for (var i = 0; i < CRITICAL_THREAD_COUNT; i++) {
new Thread(() -> {
try {
WhiteBox.getWhiteBox().lockCritical();
LOCK_COUNT_SIGNAL.countDown();
UNLOCK_SIGNAL.await();
WhiteBox.getWhiteBox().unlockCritical();
UNLOCK_COUNT_SIGNAL.countDown();
} catch (InterruptedException ex) {
}
}, CRITICAL_THREAD_NAME_PREFIX + i).start();
}
}
private static void startStallThreads() {
var ts = new Thread[STALL_THREAD_COUNT];
for (var i = 0; i < STALL_THREAD_COUNT; i++) {
ts[i] = new Thread(() -> {
STALL_COUNT_SIGNAL.countDown();
for (int j = 0; j < LOOP; j++) {
byte[] bytes = new byte[M];
}
});
}
for (Thread t : ts) {
t.start();
}
}
}

@ -149,6 +149,7 @@ public class EventNames {
public final static String ZRelocationSetGroup = PREFIX + "ZRelocationSetGroup";
public final static String ZUncommit = PREFIX + "ZUncommit";
public final static String ZUnmap = PREFIX + "ZUnmap";
public final static String GCLocker = PREFIX + "GCLocker";
// Compiler
public final static String Compilation = PREFIX + "Compilation";

@ -643,4 +643,8 @@ public class WhiteBox {
public native boolean isJVMTIIncluded();
public native void waitUnsafe(int time_ms);
public native void lockCritical();
public native void unlockCritical();
}