Virtual thread pinning with 5.0.0-alpha.12

[Packsolite]

https://github.com/square/okhttp/blob/bad2ebc296c8094370cf94291f571dd618ba7400/okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt#L376

This line causes virtual thread pinning in the latest alpha (5.0.0-alpha.12). Reason is the use of a ReentrantLock (in TaskQueue.schedule) inside a synchronized block when using a connection pool with a maxIdleConnection.

Log output with JVM argument -Djdk.tracePinnedThreads=full:

[13:36:10] [ForkJoinPool-2-worker-10/INFO]: Thread[#137,ForkJoinPool-2-worker-10,5,CarrierThreads]
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:183)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.lang.VirtualThread.park(VirtualThread.java:582) 
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.lang.System$2.parkVirtualThread(System.java:2639)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.concurrent.TaskQueue.schedule(TaskQueue.kt:66)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.concurrent.TaskQueue.schedule$default(TaskQueue.kt:65)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.RealConnectionPool.connectionBecameIdle(RealConnectionPool.kt:147)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.RealCall.releaseConnectionNoEvents$okhttp(RealCall.kt:405)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.RealCall.callDone(RealCall.kt:365)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]:  <== monitors:
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: 1 
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.RealCall.messageDone$okhttp(RealCall.kt:323)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]:  <== monitors:
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: 1
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.Exchange.bodyComplete(Exchange.kt:198)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.Exchange$ResponseBodySource.complete(Exchange.kt:329)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:300)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okio.RealBufferedSource.select(RealBufferedSource.kt:232)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.internal._UtilJvmKt.readBomAsCharset(-UtilJvm.kt:90)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: okhttp3.ResponseBody.string(ResponseBody.kt:72)
[13:36:10] [ForkJoinPool-2-worker-10/INFO]: test.TestOkHttpPinning.test(TestOkHttpPinning.java:22)

How to reproduce

1. Use the blocking OkHttpClient api from a virtual thread like this:

   Thread.ofVirtual().start(() -> {
   ConnectionPool pool = new ConnectionPool(5, 5, TimeUnit.MINUTES);
   OkHttpClient client = new OkHttpClient.Builder()
           .protocols(Collections.singletonList(Protocol.H2_PRIOR_KNOWLEDGE))
           .build();
   Request request = new Request.Builder()
           .url(url)
           .get()
           .build();
   
   Response response = client.newCall(request).execute();
   String response= response.body().string();
   });

2. Run the code with -Djdk.tracePinnedThreads=full

[yschimke]

Thanks, for the report, I'll take a look this weekend. And try to set up a test to automate this check.

[Packsolite]

Thanks, for the report, I'll take a look this weekend. And try to set up a test to automate this check.

Not quite sure how you would automate the detection of virtual thread pinning in a test without hacky hooks. Can you recommend any tool?

[yschimke]

I'm just capturing System.out

https://github.com/square/okhttp/pull/8289

[yschimke]

First set of core fixes https://github.com/square/okhttp/pull/8290

[Packsolite]

First set of core fixes #8290

Would it be possible to provide a build of the latest commit? You can call me lazy, but i can't build it myself due to not having android setup on my machine. Possibly providing a jar for every branch via github actions? Thanks alot!

[LoonyRules]

Just a note for others suffering from this same issue; this is still present in 5.0.0-alpha.14, I assume this is because https://github.com/square/okhttp/pull/8290 got reverted via https://github.com/square/okhttp/pull/8367, and https://github.com/square/okhttp/pull/8371 isn't part of an alpha release build yet.