Re: Naïve Tomcat experiment--does this indicate pinning?

Cay Horstmann cay at horstmann.com
Thu May 5 05:19:35 UTC 2022 

Il 04/05/2022 21:09, Cay Horstmann ha scritto:
> I use
> 
>  
> public class VirtualThreadExecutor
>     extends org.apache.catalina.core.StandardThreadExecutor {
> 
>     private ExecutorService exec = Executors.newThreadPerTaskExecutor(
 >        Thread.ofVirtual().name("myfactory-", 1).factory());>     
public static ExtentLocal<Instant> submissionTime =
> ExtentLocal.newInstance();
>     public static ExtentLocal<Instant> creationTime = 
> ExtentLocal.newInstance();
> 
>     public void execute(Runnable command) {
>        var smt = Instant.now();
>        exec.submit(() ->
>           ExtentLocal
>              .where(submissionTime, smt)
>              .where(creationTime, Instant.now())
>              .run(command));
>     }
>     ...
> }
> 
> In a servlet, I print out both times, as well as the thread IDs. When 
> invoking it 200 times, the first time I get
> 
> Submitted: 2022-05-04T18:28:49.467115874Z
> Created: 2022-05-04T18:28:49.469110411Z
> 
> After 200 requests:
> 
> Submitted: 2022-05-04T18:28:49.710324863Z
> Created: 2022-05-04T18:29:01.802042721Z
> 

The servlet sleeps for (int) (1000 * Math.random()) millis. I take a 
thread dump right after firing 200 requests. 9 threads park on sleep 
with a stack trace shown below. The rest show up as

          {
            "tid": 616,
            "name": "myfactory-562",
            "stack": [
            ]
          },

which I guess means "Not started yet". I could not see anything that 
Tomcat does wrong. Tomcat has launched the virtual threads for all 
requests, and none of them shows up as doing anything nefarious. I 
expected to see 200 sleeping virtual threads, or a bunch of messages 
about pinned threads. (I ran with -Djdk.tracePinnedThreads=full)

There were none in these runs. But wait, way back when, I did see a 
couple. And this time I happen to notice that line had a curious arrow 
like this:

org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) 
<== monitors:1

Looking at SocketProcessorBase.run, I found a synchronized block. 
Replacing it with a ReentrantLock solved the problem.

So there is a happy ending, but couldn't it have been happier? Would it 
be possible to report such a problem more clearly?

Cheers,

Cay


Typical stack trace of an active thread:

          {
            "tid": 492,
            "name": "myfactory-438",
            "stack": [
               "java.base\/jdk.internal.misc.Unsafe.park(Native Method)",
 
"java.base\/java.lang.VirtualThread.parkOnCarrierThread(VirtualThread.java:588)",
 
"java.base\/java.lang.VirtualThread.doParkNanos(VirtualThread.java:564)",
 
"java.base\/java.lang.VirtualThread.parkNanos(VirtualThread.java:523)",
 
"java.base\/java.lang.VirtualThread.doSleepNanos(VirtualThread.java:735)",
 
"java.base\/java.lang.VirtualThread.sleepNanos(VirtualThread.java:708)",
               "java.base\/java.lang.Thread.sleep(Thread.java:448)",
               "com.horstmann.MyServlet.doGet(MyServlet.java:23)",
 
"jakarta.servlet.http.HttpServlet.service(HttpServlet.java:668)",
 
"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.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)",
 
"org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)",
 
"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.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)",
 
"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:1715)",
 
"org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)",
 
"java.base\/jdk.internal.vm.ExtentLocalContainer.runWithoutScope(ExtentLocalContainer.java:114)",
 
"java.base\/jdk.internal.vm.ExtentLocalContainer.run(ExtentLocalContainer.java:100)",
 
"jdk.incubator.concurrent\/jdk.incubator.concurrent.ExtentLocal$Carrier.run(ExtentLocal.java:327)",
 
"com.horstmann.VirtualThreadExecutor.lambda$execute$0(VirtualThreadExecutor.java:25)",
 
"java.base\/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:577)",
 
"java.base\/java.util.concurrent.ThreadPerTaskExecutor$ThreadBoundFuture.run(ThreadPerTaskExecutor.java:344)",
 
"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:326)",
 
"java.base\/jdk.internal.vm.Continuation.enter(Continuation.java:319)"
            ]
          },

A pinning report:

Thread[#39,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:397)
     java.base/jdk.internal.vm.Continuation.yield0(Continuation.java:389)
     java.base/jdk.internal.vm.Continuation.yield(Continuation.java:356)
 
java.base/java.lang.VirtualThread.yieldContinuation(VirtualThread.java:370)
     java.base/java.lang.VirtualThread.doParkNanos(VirtualThread.java:552)
     java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:523)
     java.base/java.lang.VirtualThread.doSleepNanos(VirtualThread.java:735)
     java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:708)
     java.base/java.lang.Thread.sleep(Thread.java:448)
     com.horstmann.MyServlet.doGet(MyServlet.java:23)
     jakarta.servlet.http.HttpServlet.service(HttpServlet.java:668)
     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.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:185)
 
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.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
 
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:1716)
 
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) 
<== monitors:1
 
java.base/jdk.internal.vm.ExtentLocalContainer.runWithoutScope(ExtentLocalContainer.java:114)
 
java.base/jdk.internal.vm.ExtentLocalContainer.run(ExtentLocalContainer.java:100)
 
jdk.incubator.concurrent/jdk.incubator.concurrent.ExtentLocal$Carrier.run(ExtentLocal.java:327)
 
com.horstmann.VirtualThreadExecutor.lambda$execute$0(VirtualThreadExecutor.java:20)
 
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:577)
 
java.base/java.util.concurrent.ThreadPerTaskExecutor$ThreadBoundFuture.run(ThreadPerTaskExecutor.java:344)
     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:326)
     java.base/jdk.internal.vm.Continuation.enter(Continuation.java:319)

-- 

Cay S. Horstmann | http://horstmann.com | mailto:cay at horstmann.com

More information about the loom-dev mailing list