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

[Cay Horstmann]

Il 03/05/2022 09:32, Alan Bateman ha scritto:
> 
> I don't know the Tomcat architecture to explain what you are seeing. It 
> may lend a lot on thread locals on the assumption that the threads are 
> pooled and maybe what you are seeing is caused by this rather than 
> throttling. Looking at GC logs to compare the thread pool vs. thread per 
> request configuration may give some clues on that.
> 
> -Alan

Hi, I keep plugging away at this because it is so baffling and it seems 
like a credible example of what people may be up against when they want 
to take advantage of Loom.

Tomcat has two mechanisms for dispatching HTTP/1.1 requests, called Nio 
and Nio2. The opt-in Nio2 mechanism uses an executor that can't be 
configured, and I am not looking at it right now. The default Nio 
mechanism lets you plug a custom executor, and I use

       ThreadFactory myfactory = Thread.ofVirtual()
          .name("myfactory-", 1)
          .factory();
       exec = Executors.newThreadPerTaskExecutor(myfactory);

I record the times that a thread is submitted and is started in two 
ExtentLocal:

public class VirtualThreadExecutor
    extends org.apache.catalina.core.StandardThreadExecutor {

    private ExecutorService exec;
    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

It doesn't seem as if Tomcat is in the wrong on the submission end.
All tasks are submitted within 300 millis, but the 
newThreadPerTaskExecutor creates the last one 12 seconds (!) later.

FWIW, the thread IDs look like

VirtualThread[#242,myfactory-196]/runnable at ForkJoinPool-1-worker-8

where -worker- ranges from 1 to 8.

I am not yet done tracing what is happening between the start/end of 
"command" and the doGet method of the servlet, which just sleeps for 
about 500 millis. What should I look out for?

Cheers,

Cay

-- 

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