it returned in 10+ seconds; however when I look at the request log, the latency is logged as tens of milli seconds. I profiled my server and qtp threads are not under heavy load.
I turned on debug and found the following:
19:09:26.632:DBUG:oeji.SelectChannelEndPoint:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: Key interests updated 1 -> 0 on SelectChannelEndPoint@199c8743{/
127.0.0.1:46061<->8080,Open,in,out,R,-,7/30000,HttpConnection}{io=1,kio=0,kro=1}
19:09:26.633:DBUG:oeji.SelectChannelEndPoint:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: Local interests updating 1 -> 0 for
SelectChannelEndPoint@199c8743{/
127.0.0.1:46061<->8080,Open,in,out,R,-,8/30000,HttpConnection}{io=0,kio=0,kro=1}
19:09:26.633:DBUG:oeji.SelectorManager:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: Queued change org.eclipse.jetty.io.SelectChannelEndPoint$1@1712a18
19:09:26.633:DBUG:oeji.AbstractConnection:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: FILL_INTERESTED-->FILLING HttpConnection@44ced19c{FILLING}
19:09:26.634:DBUG:oeji.SelectorManager:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: Running change org.eclipse.jetty.io.SelectChannelEndPoint$1@1712a18
but after this, the onfillable happens after 10 seconds:
19:09:37.006:DBUG:oeji.ChannelEndPoint:qtp1963485345-5349: filled 99
SelectChannelEndPoint@199c8743{/
127.0.0.1:46061<->8080,Open,in,out,-,-,10381/30000,HttpConnection}{io=0,kio=0,kro=1}
Can any please help me fiture out what exactly happened after the HttpConnection turns into FILLING state and what caused the onfillable to be invoked after 10+ seconds?
My environment:
Server: 8 cores, 30 G memory
Jetty: 9.2x
Acceptor: 4 (default was 2, tried to increase to see difference but no help)
Selector: 16 (default was 8, tried to increase to see difference but no help)
Executor: 48
Thanks,
Jing
