Re: [jetty-users] [jetty-9.1.0] Scheduler thread hang cause connections

[Zen Zhong <zenzhong8383@xxxxxxxxx>]

Hi,

1) Scheduler thread cost much CPU, I enabled monitor module, there're stack traces of busy threads:
16:07:42.560:WARN:oejm.ThreadMonitor:Thread-13:
org.eclipse.jetty.monitor.thread.ThreadMonitorException: Thread 'Scheduler-225690927'[RUNNABLE,id:34,cpu:92.65%] STACK TRACE
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:225)
        at sun.nio.ch.IOUtil.read(IOUtil.java:198)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:375)
        at org.eclipse.jetty.io.ChannelEndPoint.fill(ChannelEndPoint.java:136)
        at org.eclipse.jetty.server.HttpInputOverHTTP.nextContent(HttpInputOverHTTP.java:104)
        at org.eclipse.jetty.server.HttpInputOverHTTP.nextContent(HttpInputOverHTTP.java:30)
        at org.eclipse.jetty.server.HttpInput.getNextContent(HttpInput.java:110)
        at org.eclipse.jetty.server.HttpInput.consumeAll(HttpInput.java:245)
        at org.eclipse.jetty.server.HttpConnection.completed(HttpConnection.java:327)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:401)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:238)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1159)
        at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:440)
        at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:92)
        at my.web.async.BasicAsyncListener.onTimeout(BasicAsyncListener.java:34)
        at org.eclipse.jetty.server.HttpChannelState.expired(HttpChannelState.java:396)
        at org.eclipse.jetty.server.HttpChannelState$AsyncTimeout.run(HttpChannelState.java:699)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)

16:18:18.738:WARN:oejm.ThreadMonitor:Thread-13:
org.eclipse.jetty.monitor.thread.ThreadMonitorException: Thread 'Scheduler-225690927'[RUNNABLE,id:34,cpu:92.94%] STACK TRACE
        at sun.nio.ch.NativeThread.current(Native Method)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:321)
        at org.eclipse.jetty.io.ChannelEndPoint.fill(ChannelEndPoint.java:136)
        at org.eclipse.jetty.server.HttpInputOverHTTP.nextContent(HttpInputOverHTTP.java:104)
        at org.eclipse.jetty.server.HttpInputOverHTTP.nextContent(HttpInputOverHTTP.java:30)
        at org.eclipse.jetty.server.HttpInput.getNextContent(HttpInput.java:110)
        at org.eclipse.jetty.server.HttpInput.consumeAll(HttpInput.java:245)
        at org.eclipse.jetty.server.HttpConnection.completed(HttpConnection.java:327)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:401)
        at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:238)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1159)
        at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:440)
        at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:92)
        at my.web.async.BasicAsyncListener.onTimeout(BasicAsyncListener.java:34)
        at org.eclipse.jetty.server.HttpChannelState.expired(HttpChannelState.java:396)
        at org.eclipse.jetty.server.HttpChannelState$AsyncTimeout.run(HttpChannelState.java:699)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
        at java.util.concurrent.FutureTask.run(FutureTask.java:166)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)

2) There's no blockForContent() in stack trace this time. I've found blockForContent() before I set a customized ReadListener.

3) I did a test later to verify whether jetty hold correct state or not. I changed org.eclipse.jetty.server.HttpConnection.completed method, line 325-327:
        else if (_parser.inContentState() && _generator.isPersistent()) {
            LOG.warn(String.format("req=%s, _parser=%s, _parser.eof=%s", _channel.getRequest(), _parser, _parser.isAtEOF()), new Exception("testparserstate")); // Complete reading the request
            _channel.getRequest().getHttpInput().consumeAll(); }

and also my.web.async.BasicAsyncListener.onTimeout
    public void onTimeout(AsyncEvent event) throws IOException {
        logger.debug("onTimeout> req={}, params={}", asyncCtx.getRequest(), (reqInfoHolder != null ? reqInfoHolder.getParameterMap() : null));

reqInfoHolder will be initialized in myReadListener.onAllDataRead().

​I got some output soon (not in connections leak state):
11:26:21.730:WARN:oejs.HttpConnection:Scheduler-1639539799: req=[POST /api/user/msg/send]@624993057 org.eclipse.jetty.server.Request@2540a321, _parser=HttpParser{s=CONTENT,0 of 48}, _parser.eof=false
11:26:21,729 DEBUG [Scheduler-1639539799] my.web.async.BasicAsyncListener: onTimeout> req=[POST /api/user/msg/send]@624993057 org.eclipse.jetty.server.Request@2540a321, params=null
​

Looks jetty hold correct state.

​

4) This issue won't occur soon, once I get debug log for HttpInput and HttpInputOverHTTP, I'll reply again.

2014/1/15 Simone Bordet <sbordet@xxxxxxxxxxx>

Hi,

On Tue, Jan 14, 2014 at 2:13 PM, Zen Zhong <zenzhong8383@xxxxxxxxx> wrote:
> Hi,
>
> I found there's connections leak in jetty. Environment: CentOS 6 x86_64, JDK
> 7u25 x86_64, jetty-9.1.0.

You have 3 stack dumps that look almost the same.
Since reads are non blocking, the timer thread was caught at that
point in all 3 times.
Did you experience 100% CPU usage for 1 core ?

Otherwise it can be explained with a really slow client.
Method consumedAll() reads from the client, and it always reads
something. Had it read 0 bytes, you would have seen a stack dump
waiting in blockForContent().

If you can reproduce this problem, can you enable debug logging for
HttpInput and HttpInputOverHTTP ?
That should tell us what's going on.

Thanks !

--
Simone Bordet
----
http://cometd.org
http://webtide.com
http://intalio.com
Developer advice, training, services and support
from the Jetty & CometD experts.
Intalio, the modern way to build business applications.
_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/jetty-users