Skip to content

Commit 311a0a9

Browse files
D-D-HThomas Schatzl
authored and
Thomas Schatzl
committedJan 27, 2021
8259808: Add JFR event to detect GC locker stall
Reviewed-by: sjohanss, tschatzl, egahlin
1 parent f353fcf commit 311a0a9

File tree

10 files changed

+224
-0
lines changed

10 files changed

+224
-0
lines changed
 

‎src/hotspot/share/gc/shared/gcLocker.cpp

+4
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@
2525
#include "precompiled.hpp"
2626
#include "gc/shared/collectedHeap.hpp"
2727
#include "gc/shared/gcLocker.hpp"
28+
#include "gc/shared/gcTrace.hpp"
2829
#include "memory/resourceArea.hpp"
2930
#include "memory/universe.hpp"
3031
#include "logging/log.hpp"
@@ -97,6 +98,7 @@ bool GCLocker::check_active_before_gc() {
9798
if (is_active() && !_needs_gc) {
9899
verify_critical_count();
99100
_needs_gc = true;
101+
GCLockerTracer::start_gc_locker(_jni_lock_count);
100102
log_debug_jni("Setting _needs_gc.");
101103
}
102104
return is_active();
@@ -107,6 +109,7 @@ void GCLocker::stall_until_clear() {
107109
MonitorLocker ml(JNICritical_lock);
108110

109111
if (needs_gc()) {
112+
GCLockerTracer::inc_stall_count();
110113
log_debug_jni("Allocation failed. Thread stalled by JNI critical section.");
111114
}
112115

@@ -152,6 +155,7 @@ void GCLocker::jni_unlock(JavaThread* thread) {
152155
// getting the count, else there may be unnecessary GCLocker GCs.
153156
_total_collections = Universe::heap()->total_collections();
154157
_doing_gc = true;
158+
GCLockerTracer::report_gc_locker();
155159
{
156160
// Must give up the lock while at a safepoint
157161
MutexUnlocker munlock(JNICritical_lock);

‎src/hotspot/share/gc/shared/gcTrace.hpp

+15
Original file line numberDiff line numberDiff line change
@@ -207,4 +207,19 @@ class DefNewTracer : public YoungGCTracer {
207207
DefNewTracer() : YoungGCTracer(DefNew) {}
208208
};
209209

210+
class GCLockerTracer : public AllStatic {
211+
#if INCLUDE_JFR
212+
private:
213+
static Ticks _needs_gc_start_timestamp;
214+
static volatile jint _jni_lock_count;
215+
static volatile jint _stall_count;
216+
#endif
217+
218+
static bool is_started() NOT_JFR_RETURN_(false);
219+
220+
public:
221+
static void start_gc_locker(jint jni_lock_count) NOT_JFR_RETURN();
222+
static void inc_stall_count() NOT_JFR_RETURN();
223+
static void report_gc_locker() NOT_JFR_RETURN();
224+
};
210225
#endif // SHARE_GC_SHARED_GCTRACE_HPP

‎src/hotspot/share/gc/shared/gcTraceSend.cpp

+45
Original file line numberDiff line numberDiff line change
@@ -344,3 +344,48 @@ void GCTracer::send_phase_events(TimePartitions* time_partitions) const {
344344
phase->accept(&phase_reporter);
345345
}
346346
}
347+
348+
#if INCLUDE_JFR
349+
Ticks GCLockerTracer::_needs_gc_start_timestamp;
350+
volatile jint GCLockerTracer::_jni_lock_count = 0;
351+
volatile jint GCLockerTracer::_stall_count = 0;
352+
353+
bool GCLockerTracer::is_started() {
354+
return _needs_gc_start_timestamp != Ticks();
355+
}
356+
357+
void GCLockerTracer::start_gc_locker(const jint jni_lock_count) {
358+
assert(SafepointSynchronize::is_at_safepoint(), "sanity");
359+
assert(!is_started(), "sanity");
360+
assert(_jni_lock_count == 0, "sanity");
361+
assert(_stall_count == 0, "sanity");
362+
if (EventGCLocker::is_enabled()) {
363+
_needs_gc_start_timestamp.stamp();
364+
_jni_lock_count = jni_lock_count;
365+
}
366+
}
367+
368+
void GCLockerTracer::inc_stall_count() {
369+
if (is_started()) {
370+
_stall_count++;
371+
}
372+
}
373+
374+
void GCLockerTracer::report_gc_locker() {
375+
if (is_started()) {
376+
EventGCLocker event(UNTIMED);
377+
if (event.should_commit()) {
378+
event.set_starttime(_needs_gc_start_timestamp);
379+
event.set_lockCount(_jni_lock_count);
380+
event.set_stallCount(_stall_count);
381+
event.commit();
382+
}
383+
// reset
384+
_needs_gc_start_timestamp = Ticks();
385+
_jni_lock_count = 0;
386+
_stall_count = 0;
387+
388+
assert(!is_started(), "sanity");
389+
}
390+
}
391+
#endif

‎src/hotspot/share/jfr/metadata/metadata.xml

+5
Original file line numberDiff line numberDiff line change
@@ -1090,6 +1090,11 @@
10901090
<Field type="boolean" name="onOutOfMemoryError" label="On Out of Memory Error" />
10911091
</Event>
10921092

1093+
<Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" label="GC Locker" startTime="true" thread="true" stackTrace="true">
1094+
<Field type="uint" name="lockCount" label="Lock Count" description="The number of Java threads in a critical section when the GC locker is started" />
1095+
<Field type="uint" name="stallCount" label="Stall Count" description="The number of Java threads stalled by the GC locker" />
1096+
</Event>
1097+
10931098
<Type name="DeoptimizationReason" label="Deoptimization Reason">
10941099
<Field type="string" name="reason" label="Reason" />
10951100
</Type>

‎src/hotspot/share/prims/whitebox.cpp

+12
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,7 @@
3939
#include "compiler/directivesParser.hpp"
4040
#include "gc/shared/concurrentGCBreakpoints.hpp"
4141
#include "gc/shared/gcConfig.hpp"
42+
#include "gc/shared/gcLocker.inline.hpp"
4243
#include "gc/shared/genArguments.hpp"
4344
#include "gc/shared/genCollectedHeap.hpp"
4445
#include "jvmtifiles/jvmtiEnv.hpp"
@@ -2318,6 +2319,14 @@ WB_ENTRY(jstring, WB_GetLibcName(JNIEnv* env, jobject o))
23182319
return info_string;
23192320
WB_END
23202321

2322+
WB_ENTRY(void, WB_LockCritical(JNIEnv* env, jobject wb))
2323+
GCLocker::lock_critical(thread);
2324+
WB_END
2325+
2326+
WB_ENTRY(void, WB_UnlockCritical(JNIEnv* env, jobject wb))
2327+
GCLocker::unlock_critical(thread);
2328+
WB_END
2329+
23212330
#define CC (char*)
23222331

23232332
static JNINativeMethod methods[] = {
@@ -2581,6 +2590,9 @@ static JNINativeMethod methods[] = {
25812590
{CC"isJVMTIIncluded", CC"()Z", (void*)&WB_IsJVMTIIncluded},
25822591
{CC"waitUnsafe", CC"(I)V", (void*)&WB_WaitUnsafe},
25832592
{CC"getLibcName", CC"()Ljava/lang/String;", (void*)&WB_GetLibcName},
2593+
2594+
{CC"lockCritical", CC"()V", (void*)&WB_LockCritical},
2595+
{CC"unlockCritical", CC"()V", (void*)&WB_UnlockCritical},
25842596
};
25852597

25862598

‎src/jdk.jfr/share/conf/jfr/default.jfc

+5
Original file line numberDiff line numberDiff line change
@@ -783,6 +783,11 @@
783783
<setting name="period">5 s</setting>
784784
</event>
785785

786+
<event name="jdk.GCLocker">
787+
<setting name="enabled">true</setting>
788+
<setting name="threshold">1 s</setting>
789+
<setting name="stackTrace">true</setting>
790+
</event>
786791

787792

788793

‎src/jdk.jfr/share/conf/jfr/profile.jfc

+5
Original file line numberDiff line numberDiff line change
@@ -783,6 +783,11 @@
783783
<setting name="period">5 s</setting>
784784
</event>
785785

786+
<event name="jdk.GCLocker">
787+
<setting name="enabled">true</setting>
788+
<setting name="threshold">100 ms</setting>
789+
<setting name="stackTrace">true</setting>
790+
</event>
786791

787792

788793

Original file line numberDiff line numberDiff line change
@@ -0,0 +1,128 @@
1+
/*
2+
* Copyright (c) 2021, Alibaba Group Holding Limited. All Rights Reserved.
3+
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4+
*
5+
* This code is free software; you can redistribute it and/or modify it
6+
* under the terms of the GNU General Public License version 2 only, as
7+
* published by the Free Software Foundation. Alibaba designates this
8+
* particular file as subject to the "Classpath" exception as provided
9+
* by Oracle in the LICENSE file that accompanied this code.
10+
*
11+
* This code is distributed in the hope that it will be useful, but WITHOUT
12+
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
13+
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
14+
* version 2 for more details (a copy is included in the LICENSE file that
15+
* accompanied this code).
16+
*
17+
* You should have received a copy of the GNU General Public License version
18+
* 2 along with this work; if not, write to the Free Software Foundation,
19+
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
20+
*/
21+
22+
/**
23+
* @test TestGCLockerEvent
24+
* @key jfr
25+
* @requires vm.hasJFR
26+
* @library /test/lib
27+
* @build sun.hotspot.WhiteBox
28+
* @run driver ClassFileInstaller sun.hotspot.WhiteBox
29+
* @run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xmx32m -Xms32m -Xmn12m -XX:+UseG1GC jdk.jfr.event.gc.detailed.TestGCLockerEvent
30+
*/
31+
32+
package jdk.jfr.event.gc.detailed;
33+
34+
import static jdk.test.lib.Asserts.assertTrue;
35+
36+
import java.util.concurrent.CountDownLatch;
37+
38+
import jdk.jfr.Recording;
39+
import jdk.jfr.consumer.RecordedEvent;
40+
import jdk.test.lib.jfr.EventNames;
41+
import jdk.test.lib.jfr.Events;
42+
43+
import sun.hotspot.WhiteBox;
44+
45+
public class TestGCLockerEvent {
46+
47+
private static final String EVENT_NAME = EventNames.GCLocker;
48+
49+
private static final int CRITICAL_THREAD_COUNT = 4;
50+
51+
private static final CountDownLatch LOCK_COUNT_SIGNAL = new CountDownLatch(CRITICAL_THREAD_COUNT);
52+
53+
private static final CountDownLatch UNLOCK_SIGNAL = new CountDownLatch(1);
54+
55+
private static final CountDownLatch UNLOCK_COUNT_SIGNAL = new CountDownLatch(CRITICAL_THREAD_COUNT);
56+
57+
private static final String CRITICAL_THREAD_NAME_PREFIX = "Critical Thread ";
58+
59+
private static final int STALL_THREAD_COUNT = 8;
60+
61+
private static final CountDownLatch STALL_COUNT_SIGNAL = new CountDownLatch(STALL_THREAD_COUNT);
62+
63+
private static final int LOOP = 32;
64+
65+
private static final int M = 1024 * 1024;
66+
67+
public static void main(String[] args) throws Exception {
68+
var recording = new Recording();
69+
recording.enable(EVENT_NAME);
70+
recording.start();
71+
72+
startCriticalThreads();
73+
LOCK_COUNT_SIGNAL.await();
74+
startStallThreads();
75+
STALL_COUNT_SIGNAL.await();
76+
77+
// Wait threads to be stalled
78+
Thread.sleep(1500);
79+
80+
UNLOCK_SIGNAL.countDown();
81+
UNLOCK_COUNT_SIGNAL.await();
82+
recording.stop();
83+
84+
// Verify recording
85+
var all = Events.fromRecording(recording);
86+
Events.hasEvents(all);
87+
var event = all.get(0);
88+
89+
assertTrue(Events.isEventType(event, EVENT_NAME));
90+
Events.assertField(event, "lockCount").equal(CRITICAL_THREAD_COUNT);
91+
Events.assertField(event, "stallCount").atLeast(STALL_THREAD_COUNT);
92+
assertTrue(event.getThread().getJavaName().startsWith(CRITICAL_THREAD_NAME_PREFIX));
93+
94+
recording.close();
95+
}
96+
97+
private static void startCriticalThreads() {
98+
for (var i = 0; i < CRITICAL_THREAD_COUNT; i++) {
99+
new Thread(() -> {
100+
try {
101+
WhiteBox.getWhiteBox().lockCritical();
102+
LOCK_COUNT_SIGNAL.countDown();
103+
104+
UNLOCK_SIGNAL.await();
105+
WhiteBox.getWhiteBox().unlockCritical();
106+
UNLOCK_COUNT_SIGNAL.countDown();
107+
} catch (InterruptedException ex) {
108+
}
109+
}, CRITICAL_THREAD_NAME_PREFIX + i).start();
110+
}
111+
}
112+
113+
private static void startStallThreads() {
114+
var ts = new Thread[STALL_THREAD_COUNT];
115+
for (var i = 0; i < STALL_THREAD_COUNT; i++) {
116+
ts[i] = new Thread(() -> {
117+
STALL_COUNT_SIGNAL.countDown();
118+
for (int j = 0; j < LOOP; j++) {
119+
byte[] bytes = new byte[M];
120+
}
121+
});
122+
}
123+
for (Thread t : ts) {
124+
t.start();
125+
}
126+
}
127+
}
128+

‎test/lib/jdk/test/lib/jfr/EventNames.java

+1
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,7 @@ public class EventNames {
149149
public final static String ZRelocationSetGroup = PREFIX + "ZRelocationSetGroup";
150150
public final static String ZUncommit = PREFIX + "ZUncommit";
151151
public final static String ZUnmap = PREFIX + "ZUnmap";
152+
public final static String GCLocker = PREFIX + "GCLocker";
152153

153154
// Compiler
154155
public final static String Compilation = PREFIX + "Compilation";

‎test/lib/sun/hotspot/WhiteBox.java

+4
Original file line numberDiff line numberDiff line change
@@ -643,4 +643,8 @@ public native int validateCgroup(String procCgroups,
643643
public native boolean isJVMTIIncluded();
644644

645645
public native void waitUnsafe(int time_ms);
646+
647+
public native void lockCritical();
648+
649+
public native void unlockCritical();
646650
}

0 commit comments

Comments
 (0)
Please sign in to comment.