4

I'm using OpenJDK 19

openjdk 19 2022-09-20
OpenJDK Runtime Environment (build 19+36-2238)
OpenJDK 64-Bit Server VM (build 19+36-2238, mixed mode, sharing)

And the latest version of Tomcat (10.0.23)

var tomcat = new Tomcat();
var ctx = tomcat.addContext("", (new File(".")).getAbsolutePath());
Tomcat.addServlet(ctx, "Servlet", new HttpServlet() {
    @Override
    protected void service(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
        try {
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        resp.setStatus(200);
        resp.setHeader("Content-Type", "application/json");
    }
});
ctx.addServletMappingDecoded("/*", "Servlet");
var connector = new Connector();
var uri = new URI("http://0.0.0.0:8081");
connector.setProperty("address", uri.getHost());
connector.setPort(uri.getPort());
connector.setProperty("maxHttpHeaderSize", "16384");
connector.setProperty("connectionTimeout", Duration.ofSeconds(5L).toString());
connector.setProperty("maxKeepAliveRequests", "100");
connector.setProperty("useKeepAliveResponseHeader", "false");
connector.setProperty("socket.soLingerOn", "false");
connector.setEncodedSolidusHandling("passthrough");
connector.getProtocolHandler().setExecutor(Executors.newVirtualThreadPerTaskExecutor());
tomcat.getService().addConnector(connector);

tomcat.start();

In this line

connector.getProtocolHandler().setExecutor(Executors.newVirtualThreadPerTaskExecutor());

I tell Tomcat to use an executor of virtual threads, and then I have a simple Servlet where I sleep for 5 seconds before responding to the client.

I have this bash script to load test the server

function call {
        curl http://localhost:8081
}


function test_load {
        start_time=$(date +%s)
        call
        end_time=$(date +%s)
        elapsed=$(( end_time - start_time ))
        echo "done elapsed: ${elapsed} \n"
}

for i in {1..100}; do
        test_load &
done

sleep 100000

When I run the script, I expect to wait 5 seconds, and then see done elapsed: 5 repeated for 100 times. Because running Thread.sleep shouldn't block the underlying platform thread.
Instead, after 5 seconds, I see done elapsed: 5 printed 12 times. Then after another 5 seconds, I see done elapsed: 10 printed another 12 times, and so on...

When I try Executors.newThreadPerTaskExecutor() or Executors.newCachedThreadPool(), it works as I'd expect virtual thread per task to work (run all 100 calls in parallel)

12 is the number of cores I have (Runtime.getRuntime().availableProcessors())

Why does this happen?

Edit 1: After adding -Djdk.tracePinnedThreads=full, I see

Thread[#34,ForkJoinPool-1-worker-1,5,CarrierThreads]
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:180)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:398)
    java.base/jdk.internal.vm.Continuation.yield0(Continuation.java:390)
    java.base/jdk.internal.vm.Continuation.yield(Continuation.java:357)
    java.base/java.lang.VirtualThread.yieldContinuation(VirtualThread.java:370)
    java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:532)
    java.base/java.lang.VirtualThread.doSleepNanos(VirtualThread.java:713)
    java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:686)
    java.base/java.lang.Thread.sleep(Thread.java:451)
    org.example.Main$1.service(Main.java:64)
    jakarta.servlet.http.HttpServlet.service(HttpServlet.java:777)
    org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:223)
    org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:158)
    org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
    org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
    org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
    org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:119)
    org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
    org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:356)
    org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
    org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
    org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:867)
    org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1762)
    org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) <== monitors:1
    java.base/java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.run(ThreadPerTaskExecutor.java:314)
    java.base/java.lang.VirtualThread.run(VirtualThread.java:287)
    java.base/java.lang.VirtualThread$VThreadContinuation.lambda$new$0(VirtualThread.java:174)
    java.base/jdk.internal.vm.Continuation.enter0(Continuation.java:327)
    java.base/jdk.internal.vm.Continuation.enter(Continuation.java:320)

When I make a request. Looks like the call to Thread.sleep pins the carrier thread?
When I run a simple program (without Tomcat or any other web server) that just spawns a virtual thread and sleeps inside it, I don't see any pinning traces.

areller
  • 4,800
  • 9
  • 29
  • 57
  • @Holger updated the post. OpenJDK build 19+36-2238 – areller Sep 27 '22 at 16:52
  • 5
    You might want to set `-Djdk.tracePinnedThreads=full` (or `short`) to see if the carrier thread is pinned and why. – Ben Manes Sep 27 '22 at 18:41
  • 1
    @BenManes Added this arg and ran the test again (with just a single HTTP call). looks like it does pin the thread (attached stack trace), but can't make sense of it. Looks like `Thread.sleep` is the origin of the pin, and when I just run a virtual thread (outside of Tomcat or any other web server) and sleep in it, I don't get any pinning trace. – areller Sep 27 '22 at 21:13
  • 5
    Maybe try Tomcat 10.1.0-M16 or [above](https://tomcat.apache.org/tomcat-10.1-doc/changelog.html): _"Refactor synchronization blocks locking on SocketWrapper to use ReentrantLock to support users wishing to experiment with project Loom."_ – Ben Manes Sep 28 '22 at 01:00

0 Answers0