Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] [jetty-9.1.0] Scheduler thread hang cause connections leak
Hi,

It's CentOS.

# /usr/sbin/sestatus
SELinux status:                 disabled



2014/1/18 Joakim Erdfelt <joakim@xxxxxxxxxxx>
What linux distribution are you running?  Curious if selinux is active on your system.

--
Joakim Erdfelt <joakim@xxxxxxxxxxx>
Expert advice, services and support from from the Jetty & CometD experts


On Thu, Jan 16, 2014 at 7:45 PM, Zen Zhong <zenzhong8383@xxxxxxxxx> wrote:
Hi, Simone

I enabled debug logging for HttpInput and HttpInputOverHttp. I found java process was killed by kernel today, I'm not sure whether the issue was reproduced or not this time, but Scheduler thread really cost much time to read data from one connection, some logs as following:

In /var/log/messages, there're many "Out of socket memory" and "possible SYN flooding on port 80. Sending cookies.", and one "Jan 16 19:35:01 <hostname> kernel: Out of memory: Kill process 30279 (java) score 367 or sacrifice child".

tail -n 10000000 /data/jetty/logs/2014_01_16.stderrout.log > temp
less -N temp
      1 2014-01-16 19:29:56.442:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@fa92e29 filled 0
      2 2014-01-16 19:29:56.442:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@fa92e29 filled 0
      3 2014-01-16 19:29:56.442:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@fa92e29 filled 0
...<repeat>
3868890 2014-01-16 19:31:25.810:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@713f72e1 filled 0
3868891 2014-01-16 19:31:25.810:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@713f72e1 filled -1
3868892 2014-01-16 19:31:25.810:DBUG:oejs.HttpInput:Scheduler-1456460106: HttpInputOverHTTP@713f72e1 early EOF
3868893 2014-01-16 19:31:25.810:DBUG:oejs.HttpInput:Scheduler-1456460106: HttpInputOverHTTP@713f72e1 eof EARLY_EOF
...<ignore some timeout exception>
3868952 2014-01-16 19:31:27.076:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
3868953 2014-01-16 19:31:27.076:WARN:oejs.HttpConnection:Scheduler-1456460106: req=[POST /api/oauth2/token]@955987031 org.eclipse.jetty.server.Request@38fb3453868953 7, _parser=HttpParser{s=CONTENT,0 of 61}, _parser.eof=false
3868954 java.lang.Exception: testparserstate
3868955         at org.eclipse.jetty.server.HttpConnection.completed(HttpConnection.java:326)
3868956         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:401)
3868957         at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:238)
3868958         at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1159)
3868959         at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:440)
3868960         at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:92)
3868961         at my.web.async.BasicAsyncListener.onTimeout(BasicAsyncListener.java:36)
3868962         at org.eclipse.jetty.server.HttpChannelState.expired(HttpChannelState.java:396)
3868963         at org.eclipse.jetty.server.HttpChannelState$AsyncTimeout.run(HttpChannelState.java:699)
3868964         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
3868965         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
3868966         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
3868967         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
3868968         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
3868969         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
3868970         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
3868971         at java.lang.Thread.run(Thread.java:724)
3868972 2014-01-16 19:31:27.076:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
3868973 2014-01-16 19:31:27.076:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
3868974 2014-01-16 19:31:27.076:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
...<repeat>
4151735 2014-01-16 19:31:33.536:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
4151736 2014-01-16 19:31:33.536:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled 0
4151737 2014-01-16 19:31:33.536:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad filled -1
4151738 2014-01-16 19:31:33.536:DBUG:oejs.HttpInput:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad early EOF
4151739 2014-01-16 19:31:33.536:DBUG:oejs.HttpInput:Scheduler-1456460106: HttpInputOverHTTP@5a1809ad eof EARLY_EOF
4151740 2014-01-16 19:31:33.640:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
4151741 2014-01-16 19:31:33.640:WARN:oejs.HttpConnection:Scheduler-1456460106: req=[POST /api/oauth2/token]@1603375770 org.eclipse.jetty.server.Request@5f91924151741 9a, _parser=HttpParser{s=CONTENT,0 of 126}, _parser.eof=false
4151742 java.lang.Exception: testparserstate
4151743         at org.eclipse.jetty.server.HttpConnection.completed(HttpConnection.java:326)
4151744         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:401)
4151745         at org.eclipse.jetty.server.HttpChannel.run(HttpChannel.java:238)
4151746         at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1159)
4151747         at org.eclipse.jetty.server.HttpChannelState.complete(HttpChannelState.java:440)
4151748         at org.eclipse.jetty.server.AsyncContextState.complete(AsyncContextState.java:92)
4151749         at my.web.async.BasicAsyncListener.onTimeout(BasicAsyncListener.java:36)
4151750         at org.eclipse.jetty.server.HttpChannelState.expired(HttpChannelState.java:396)
4151751         at org.eclipse.jetty.server.HttpChannelState$AsyncTimeout.run(HttpChannelState.java:699)
4151752         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
4151753         at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
4151754         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
4151755         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
4151756         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
4151757         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
4151758         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
4151759         at java.lang.Thread.run(Thread.java:724)
4151760 2014-01-16 19:31:33.641:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
4151761 2014-01-16 19:31:33.641:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
4151762 2014-01-16 19:31:33.641:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
...<repeat>
9999998 2014-01-16 19:35:01.223:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
9999999 2014-01-16 19:35:01.223:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0
10000000 2014-01-16 19:35:01.223:DBUG:oejs.HttpInputOverHTTP:Scheduler-1456460106: HttpInputOverHTTP@e2db5db filled 0

Thanks


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


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/jetty-users


Back to the top