Given this code, that tries to listen to the event jdk.VirtualThreadPinned
when a virtual thread is pinned:
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 {
}
}
This is the output:
[INFO] Running com.example.general.JFRTest
Received StartEvent {
startTime = 10:37:46.830 (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: 6.215 s <<< FAILURE! - in com.example.general.JFRTest
[ERROR] com.example.general.JFRTest.pinnedVirtualThreads Time elapsed: 6.187 s <<< FAILURE!
java.lang.AssertionError: jdk.VirtualThreadPinned was not sent
As you can see, this part should trigger the event jdk.VirtualThreadPinned
, but it is not happening. On the other hand, the other event StartEvent
is caught:
Thread vt = Thread.ofVirtual().start(() -> {
synchronized (this) {
System.out.println("Virtual Thread is pinned");
}
});
I don't know why.
This is my JDK version is: 21.0.3+7-LTS-152
jdk.VirtualThreadPinned
is only fired when the runtime tries to park a thread that is pinned. You can trigger this for instance by calling Thread.sleep
with the virtual thread runnable:
Thread vt = Thread.ofVirtual().start(() -> {
synchronized (lock) {
System.out.println("Virtual Thread is pinned");
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
});
You also need to make sure the event stream is flushed, otherwise your callback for the jdk.VirtualThreadPinned
event will never be called. You can do this by calling .stop()
on the recording stream (close()
-ing the stream stops the recording abruptly, and doesn't wait for all events to be consumed). For instance, right before the end of the try
block:
vt.join();
recordingStream.stop();
} // end of try
With those 2 changes, I see the event being fired:
VirtualThreadPinned event detected!
Timestamp: jdk.VirtualThreadPinned {
startTime = 10:28:32.075 (2024-06-12)
duration = 998 ms
eventThread = "" (javaThreadId = 37, virtual)
stackTrace = [
java.lang.VirtualThread.parkOnCarrierThread(boolean, long) line: 689
java.lang.VirtualThread.parkNanos(long) line: 648
java.lang.VirtualThread.sleepNanos(long) line: 812
java.lang.Thread.sleepNanos(long) line: 489
java.lang.Thread.sleep(long) line: 522
...
]
}