dev@grizzly.java.net

Re: closed connection under high load

From: Oleksiy Stashok <oleksiy.stashok_at_oracle.com>
Date: Wed, 05 Mar 2014 17:35:00 -0800

Hi Tigran,

>> Hi Tigran,
>>
>> looks like the connection is getting closed because of IOException or -1
>> returned during channel.read(), which is expected.
>> So IMO it's nothing decided by Grizzly, it's either other side or local
>> OS closed the connection.
> Yes, in did, the client closes the connection. But it looks like the reason of it
> that reply from server sent 15sec after request is arrived. The filter itself took
> max 800ms. Any ideas how to trace where rest of the time was spent?
You can register ConnectionProbe for each Connection:
/ connection.getMonitoringConfig().addProbes(new
ConnectionProbe() {
.....
             });/

and monitor different Connection events and time when it happened.
It might be interesting to monitor onWriteEvent() and see if write delay
occurs on Grizzly/Java or OS level. For example Grizzly reports the
socketChannel.write(ByteBuffer) had been accepted the ByteBuffer, but
the peer didn't get this data, which means the delay happens in OS layer.

Thanks.

WBR,
Alexey.

>
> Looking at the requests log I can see that request processing is not equally distributed.
> Some connections processed quite active, while others are not. Is there a way how I can see
> selector threads activity?
>
> Tigran.
>
>> Thanks.
>>
>> WBR,
>> Alexey.
>>
>> On 26.02.14 14:06, Mkrtchyan, Tigran wrote:
>>> Hi,
>>>
>>> we observe that grizzly decides to close connection under high load.
>>> Any idea how to find the reason?
>>>
>>> Thanks,
>>> Tigran.
>>>
>>> java.io.IOException: Connection closed
>>> at org.glassfish.grizzly.asyncqueue.TaskQueue.onClose(TaskQueue.java:302)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter.onClose(AbstractNIOAsyncQueueWriter.java:591)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.transport.TCPNIOTransport.closeConnection(TCPNIOTransport.java:389)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at org.glassfish.grizzly.nio.NIOConnection$2.run(NIOConnection.java:439)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.DefaultSelectorHandler$RunnableTask.run(DefaultSelectorHandler.java:489)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTaskQueue(DefaultSelectorHandler.java:295)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.DefaultSelectorHandler.processPendingTasks(DefaultSelectorHandler.java:286)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.DefaultSelectorHandler.preSelect(DefaultSelectorHandler.java:100)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.SelectorRunner.doSelect(SelectorRunner.java:326)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at org.glassfish.grizzly.nio.SelectorRunner.run(SelectorRunner.java:271)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:565)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:545)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
>>> Caused by: java.lang.Exception: Close stack trace
>>> at org.glassfish.grizzly.nio.NIOConnection.close0(NIOConnection.java:426)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.transport.TCPNIOConnection.close0(TCPNIOConnection.java:292)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:648)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:75)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:173)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:546)
>>> [grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>> at
>>> org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
>>> ~[grizzly-framework-2.3.5.jar:2.3.5]
>>