Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[jetty-users] Long processing time before HttpConnection.onFillable invoked

Hi There,

I noticed this issue during high load. A very simple example, I ran

curl "http://localhost:8080/heath"

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

Back to the top