Skip to main content

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

Can you get a thread dump during the 10s pause?   Ideally could you also use JMX to get a server dump during the same period?


On 1 July 2017 at 01:53, Jing Yang <jingisgood@xxxxxxxxx> wrote:
It seems that, when the HttpConnection enters state FILLING, the worker thread should be invoked to execute the onFillable. In the debug logs, I can see that the HttpConnection enters state FILLING, but the actual onFillable is at 10 seconds later.

Seems like the QueuedThreadPool is no enough? but the profiling results shows threads are pretty free.

enters FILLING:
2017-06-29 19:09:26.633:DBUG:oeji.AbstractConnection:qtp1963485345-43-selector-ServerConnectorManager@14a6d5e4/2: FILL_INTERESTED-->FILLING HttpConnection@44ced19c{FILLING}

execute onFillable:
2017-06-29 19:09:37.006:DBUG:oejs.HttpConnection:qtp1963485345-5349: HttpConnection@44ced19c{FILLING} onFillable HttpChannelState@5860f278{s=IDLE i=true a=null}

Thanks,
Jing

> Date: Fri, 30 Jun 2017 17:42:55 +0000

> From: Jing Yang <jingisgood@xxxxxxxxx>
>
> Forgot to mention that, it's using the default QueuedThreadPool as well. I am having the same issue.
>
> Thanks,
> Jing
>
>
> Date: Fri, 30 Jun 2017 10:12:34 -0700
> From: Joakim Erdfelt <joakim@xxxxxxxxxxx>
>
> Changing selectors is appropriate and all, but
> Its far more important to have a proper ThreadPool configuration.
> A fixed thread pool (like what you get from a JVM Executor is a bad idea for high load)
> At least go back to the default QueuedThreadPool implementation and configuration.
>
> Joakim Erdfelt /Âjoakim@xxxxxxxxxxx

On Fri, Jun 30, 2017 at 9:48 AM, Jing YangÂ<jingisgood@xxxxxxxxx>Âwrote:
Thanks for the response Joakim.

I tried your config with 4 selectors, but there is no luck, same behavior. Any other ideas?

In the doc it says the onFillable "is called when this Connection is ready to read bytes from the EndPoint". What triggers this "is ready" signal? I am guess the trigger is getting delayed for some reason.

Thanks,
Jing

Date: Thu, 29 Jun 2017 16:53:11 -0700
From: Joakim Erdfelt <joakim@xxxxxxxxxxx>


>
> 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


That seems backwards for your desired goal.

Go with.
Acceptors: 1
Selectors: 4
ThreadPool: QueuedThreadPoolà (Don't use Executor for high load
configurations)

With your memory configuration you should be on Java 8 and Jetty 9.4.6.


Joakim Erdfelt /Âjoakim@xxxxxxxxxxx

On Thu, Jun 29, 2017 at 3:59 PM, Jing Yang <jingisgood@xxxxxxxxx> wrote:

> 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

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



--

Back to the top