Open danielkec opened 4 weeks ago
I think JFR requires Oracle JDK. I guess the way to approach this is to include one script, with Oracle JDK, that executes the tests with the JVM args:
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=filename=flight.jfr
And then find events on the generated JRF file:
jfr print --events jdk.VirtualThreadPinned flight.jfr
If found, then error.
It seems from JDK 9 it is part of JDK, so we can use it in @HelidonTest
My idea is to create a new maven module: io.helidon.microprofile.testing:helidon-microprofile-testing-jrf
with a CDI extension for this purpose. Maybe t is worth to have it available for other purposes (not only testing).
I am trying to make a simple reproducer, but for some reason I don't catch the jdk.VirtualThreadPinned
event:
import static org.junit.Assert.assertTrue;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import jdk.jfr.Event;
import jdk.jfr.Name;
import jdk.jfr.consumer.RecordingStream;
import org.junit.Test;
public class JFRTest {
@Test
public void pinnedVirtualThreads() throws InterruptedException {
CountDownLatch stopListening = new CountDownLatch(1);
CountDownLatch startListening = new CountDownLatch(1);
try (RecordingStream recordingStream = new RecordingStream()) {
// Create and start the recording stream
startRecordingStream(recordingStream, startListening, stopListening);
// Make sure JFR listener is running before continue
while (true) {
new StartEvent().commit();
if (startListening.await(1, TimeUnit.SECONDS)) {
break;
}
}
// Simulate blocking operation
Thread vt = Thread.ofVirtual().start(() -> {
synchronized (this) {
System.out.println("Virtual Thread is pinned");
}
});
vt.join();
}
// Wait till the jdk.VirtualThreadPinned triggers
assertTrue("jdk.VirtualThreadPinned was not sent", stopListening.await(5, TimeUnit.SECONDS));
}
private void startRecordingStream(RecordingStream recordingStream, CountDownLatch startListening, CountDownLatch stopListening) {
// Enable the jdk.VirtualThreadPinned event
recordingStream.enable("jdk.VirtualThreadPinned").withStackTrace();
// Notify listener is running after receiving the StartEvent
recordingStream.onEvent("StartEvent", event -> {
System.out.println("Received " + event);
startListening.countDown();
});
// Set an event handler
recordingStream.onEvent("jdk.VirtualThreadPinned", event -> {
System.out.println("VirtualThreadPinned event detected!");
System.out.println("Timestamp: " + event);
stopListening.countDown();
});
// Start the recording stream
recordingStream.startAsync();
}
@Name("StartEvent")
private static class StartEvent extends Event {
}
}
It fails with:
[INFO] Running com.example.general.JFRTest
Received StartEvent {
startTime = 09:38:59.825 (2024-06-12)
eventThread = "main" (javaThreadId = 1)
stackTrace = [
com.example.general.JFRTest.pinnedVirtualThreads() line: 25
jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 103
java.lang.reflect.Method.invoke(Object, Object[]) line: 580
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall() line: 59
org.junit.internal.runners.model.ReflectiveCallable.run() line: 12
]
}
Virtual Thread is pinned
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 8.208 s <<< FAILURE! - in com.example.general.JFRTest
[ERROR] com.example.general.JFRTest.pinnedVirtualThreads Time elapsed: 8.183 s <<< FAILURE!
java.lang.AssertionError: jdk.VirtualThreadPinned was not sent
at org.junit.Assert.fail(Assert.java:89)
at org.junit.Assert.assertTrue(Assert.java:42)
at com.example.general.JFRTest.pinnedVirtualThreads(JFRTest.java:46)
You have to block the carrier thread for more than 20 millis(that is the default)
Thread vt = Thread.ofVirtual().start(() -> {
synchronized (this) {
Thread.sleep(50);
}
});
You have to block the carrier thread for more than 20 millis(that is the default)
Thread vt = Thread.ofVirtual().start(() -> { synchronized (this) { Thread.sleep(50); } });
I read that too, but I thought it means that be default jdk.VirtualThreadPinned
is disabled, unless it takes more than 20ms that becomes enabled. In my example I was explicitly enabling it, so I thought it is not needed to pin it more than 20ms.
Anyway, I added 2 seconds of sleep and still nothing.
The issue was the event was triggered but not flushed immediately. Closing the RecordingStream doesn't flush.
So I had to add before closing:
recordingStream.stop();
We should monitor JFR event
jdk.VirtualThreadPinned
in@HelidonTest
tests and fail the test causing the pinning