Fail HelidonTests by default when pinning jfr event is detected

[danielkec]

We should monitor JFR event jdk.VirtualThreadPinned in @HelidonTest tests and fail the test causing the pinning

[jbescos]

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.

[jbescos]

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).

[jbescos]

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)

[danielkec]

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);
                }
            });

[jbescos]

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.

[jbescos]

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();