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 <[email protected]> wrote: > According to this thread http://jetty.4.x6.nabble.com/ > Where-does-Jetty-dispatch-to-worker-thread-happens-td4963259.html, > > 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 <[email protected]>> > > > > 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 > [email protected] > To change your delivery options, retrieve your password, or unsubscribe > from this list, visit > https://dev.eclipse.org/mailman/listinfo/jetty-users > -- Greg Wilkins <[email protected]> CTO http://webtide.com
_______________________________________________ jetty-users mailing list [email protected] To change your delivery options, retrieve your password, or unsubscribe from this list, visit https://dev.eclipse.org/mailman/listinfo/jetty-users
