Hi Oleksiy,
thank you for your answer.
I will try to proceed as you suggest me, anyway I would like to ask you a
question.
I have the problem in two situations:
1) before serving request: my last filter is executed and the code of the
resource should start. Often in this step I lose 0.4 seconds.
2) after serving request: my last filter is executed and the control is
passed again to grizzly
(i can measure that in this step I lose 0.4 seconds, printing a timestamp
as last
instruction of the last filter and printing a timestamp when
onRequestCompleteEvent
of GrizzlyServer is called)
What happens during those two steps? Any advices? What else should I
inspect?
Thanks
On Thu, Jan 2, 2014 at 10:38 PM, Oleksiy Stashok <oleksiy.stashok_at_oracle.com
> wrote:
> Hi Andrea,
>
> I think the only good way to find out the problem is to use some profiler,
> for example jvisualvm (bundled with JDK 6, 7) or hprof. It will help to
> figure out hot spots and address them.
> Otherwise it's difficult to say anything based on logs, we see the
> problem, but don't see where it comes from.
>
> Thanks.
>
> WBR,
> Alexey.
>
> On 02.01.14 05:57, Andrea Ulisse wrote:
>
> Hi Oleksiy,
>
> I am going to give all the profiling informations that I have.
>
> - I am using Jersey 2.5, anyway I had the problem with 2.3.1 and 2.4 also.
>
> - I am using two EC2 instances in the same region: a mi.medium and a
> c3.large. The m1 is used for performing load tests versus the c3.
>
> - I am using ab for performing tests, using n1000 and c50
>
> - the resource is really simple: it only produce a String to be returned,
> containing the current time
>
> - I am using the AuthorizationFilter, set following the official Jersey
> documentation
>
> - my resource only creates Nand returns a String
>
> - I configured the ThreadPool with default number of selector threads,
> core pool size 15, max pool size 150, keepalive 5000, queue limit 200,
> ArrayBlockingQueue. In the test I have no requests rejected.
>
> - I enabled the jul, and I can see:
>
> 2014-01-02T10:53:02.663Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:G02xI, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] GrizzlyHttpContainer.service(...) started on thread
> wt:G02xI
>
> 2014-01-02T10:53:03.136Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:G02xI, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] GrizzlyHttpContainer.service(...) finished on thread
> wt:G02xI
>
> Here you can find the full logging of a slow call, mixing my application
> logging with jul. I really don't understand what happens in the lines
> highlighted in yellow. (wt:minNq is a token assigned to the thread name)
>
> Why does it need so much time for passing from a filter to the code of the
> resource?
>
> 2014-01-02 11:26:24,555 TRACE wt:minNq [GrizzlyServer:168]
> 4;4;-1;4;5;50;1000;1;5000;
>
> 2014-01-02 11:26:24.587Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] ResponseWriter {id=1db04626-1809-4f46-b935-7c7dbeae3ede,
> grizzlyResponse=263347512} - init on thread wt:minNq,
>
> 2014-01-02 11:26:24.587Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] GrizzlyHttpContainer.service(...) started on thread
> wt:minNq,
>
> 2014-01-02 11:26:24,632 INFO wt:minNq [LoggingFilter:51] IN: -
> /status H:{host=[xxxx:8080], user-agent=[ApacheBench/2.3],
> accept=[*/*]}
>
> 2014-01-02 11:26:24,687 DEBUG wt:minNq [AuthorizationFilter:57] Header key
> is empty
>
> 2014-01-02 11:26:24,694 DEBUG wt:minNq [AuthorizationFilter:99] the appkey
> is not verified. PUBLIC role assigned.
>
> 2014-01-02 11:26:24,788 TRACE wt:minNq [ParamsInThreadLocalFilter:27] in
>
> 2014-01-02 11:26:24,788 DEBUG wt:minNq [ParamsInThreadLocalFilter:33] No
> fields required specified
>
> 2014-01-02 11:26:24,788 TRACE wt:minNq [ParamsInThreadLocalFilter:35] out
> --> why, after this filter (the last), does it need about half a second for
> beginning serving the request? Sometimes it takes 1 second!
>
> 2014-01-02 11:26:25,162 TRACE wt:minNq [StatusResource:37] in --> the
> request is served
>
> 2014-01-02 11:26:25,163 TRACE wt:minNq [StatusResource:42] out --> the
> resource ends its job, after creating a string
>
> 2014-01-02 11:26:25,186 TRACE wt:minNq [CORSFilter:32] Starting...
>
> 2014-01-02 11:26:25,258 TRACE wt:minNq [CORSFilter:56] Finished, header
> was NOT modified
>
> 2014-01-02 11:26:25,258 INFO wt:minNq [LoggingFilter:64] OUT: 200 -
> Everything's fine, Thu Jan 02 11:26:25 UTC 2014
>
> 2014-01-02 11:26:25.303Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] ResponseWriter {id=1db04626-1809-4f46-b935-7c7dbeae3ede,
> grizzlyResponse=263347512} - writeResponseStatusAndHeaders() called on
> thread wt:minNq,
>
> 2014-01-02 11:26:25.303Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor execute, executing
> connection (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}). IOEvent=NONE
> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_74a2b686,
>
> 2014-01-02
> 11:26:25.303Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=WRITE,
> message=org.glassfish.grizzly.http.HttpContent_at_3517402, address=/
> x.x.x.x:53735], <http://10.154.141.88:53735/>
>
> 20 <http://10.154.141.88:53735/>14-01-02
> 11:26:25.303Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
> <http://10.45.12.59:8080/>peerSocketAddress={/x.x.x.x:53735}},
> operation=WRITE, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>] nextAction=org.g<http://10.154.141.88:53735/>
> lassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.303Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080}, peer<http://10.45.12.59:8080/>SocketAddress={/x.x.x.x:53735}},
> operation=WRITE, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.303Z,o <http://10.154.141.88:53735/>rg.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSock <http://10.45.12.59:8080/>etAddress={/x.x.x.x:53735}},
> operation=WRITE, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterc <http://10.154.141.88:53735/>
> hain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.304Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAd <http://10.45.12.59:8080/>dress={/x.x.x.x:53735}},
> operation=WRITE, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.304Z,org.glassfish.grizzly.fil<http://10.154.141.88:53735/>terchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddres <http://10.45.12.59:8080/>s={/x.x.x.x:53735}},
> operation=WRITE, message=BuffersBuffer (2106724763) [pos=0 lim=237
> cap=237 bufferSize=2 buffers=[HeapBuffer (12720005) [pos=0 lim=156
> cap=156], HeapBuffer (1184242982) [pos=0 lim=81 cap=81], null, null]],
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction@59ec69<http://10.154.141.88:53735/>9a,
>
>
> 2014-01-02
> 11:26:25.304Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/ <http://10.45.12.59:8080/>x.x.x.x:53735}},
> operation=WRITE, message=BuffersBuffer (2106724763) [pos=0 lim=237
> cap=237 bufferSize=2 buffers=[HeapBuffer (12720005) [pos=0 lim=156
> cap=156], HeapBuffer (1184242982) [pos=0 lim=81 cap=81], null, null]],
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.304Z,org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWr<http://10.154.141.88:53735/>iter
> doFineLogwt:minNq, org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
> doFineLog, AsyncQueueWriter.write
> connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x <http://10.45.12.59:8080/>:53735<http://10.154.141.88:53735/>}}
> record=org.glassfish.grizzly.asyncqueue.AsyncWriteQueueRecord_at_2953cdfe dir
> ectWrit <http://10.45.12.59:8080/>e=true,
>
> 2014-01-02
> 11:26:25.305Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=WRITE, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02 11:26:25.305Z, <http://10.154.141.88:53735/>org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] ResponseWriter {id=1db04626-1809-4f46-b935-7c7dbeae3ede,
> grizzlyResponse=263347512} - commit() called on thread wt:minNq,
>
> 2014-01-02 11:26:25.305Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] Released scope instance
> Instance{id=5e84ac7d-4d49-4966-af4d-ded939717f57, referenceCounter=0, store
> size=0} on thread wt:minNq,
>
> 2014-01-02 11:26:25.305Z,org.glassfish.jersey.internal.util.ExtendedLogger
> debugLogwt:minNq, org.glassfish.jersey.internal.util.ExtendedLogger
> debugLog, [DEBUG] GrizzlyHttpContainer.service(...) finished on thread
> wt:minNq,
>
> 2014-01-02 11:26:25.305Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor execute, executing
> connection (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}). IOEvent=NONE
> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_74a2b686,
>
> 2014-01-02
> 11:26:25.305Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53 <http://10.45.12.59:8080/>735}},
> operation=EVENT, message=null, address=/x.x.x.x:53735<http://10.154.141.88:53735/>],
>
>
> 2014-01-02
> 11:26:25.306Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glass <http://10.154.141.88:53735/>fish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735} <http://10.45.12.59:8080/>},
> operation=EVENT, message=null, address=/x.x.x.x:53735<http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02 11:26:25.306Z,org.glassfish.grizzly.filterch<http://10.154.141.88:53735/>ain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, o <http://10.45.12.59:8080/>peration=EVENT,
> message=null, address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02
> 11:26:25.306Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain<http://10.154.141.88:53735/>.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, opera <http://10.45.12.59:8080/>tion=EVENT,
> message=null, address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02 11:26:25.306Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> e <http://10.154.141.88:53735/>xecuteFilterwt:minNq,
> org.glassfish.grizzly.filterchain.DefaultFilterChain executeFilter, Execute
> filter. filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation <http://10.45.12.59:8080/>=EVENT,
> message=null, address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.306Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor execute, executing
> connection (TCPNI <http://10.154.141.88:53735/>
> OConnection{localSocketAddress={/x.x.x.x:8080 <http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}). IOEvent=NONE<http://10.45.12.59:8080/>processor=org.glassfish.grizzly.filterchain.DefaultFilterChain@74a2b686,
>
>
> 2014-01-02
> 11:26:25.306Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT,
> <http://10.45.12.59:8080/>message=null, address=/x.x.x.x:53735<http://10.154.141.88:53735/>],
>
>
> 2014-01-02
> 11:26:25.311Z,org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
> doFineLogwt:minNq, org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
> doFineLog, AsyncQueueWri <http://10.154.141.88:53735/>ter.write
> connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735 <http://10.154.141.88:53735/>}}
> record=org.glassfish.g <http://10.45.12.59:8080/>
> rizzly.asyncqueue.AsyncWriteQueueRecord_at_2953cdfe directWrite=true,
>
> 2014-01-02 11:26:25.312Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfi <http://10.154.141.88:53735/>sh.grizzly.ProcessorExecutor
> execute, executing connection (TCPNIOConnection{localSocketAddress={/
> x.x.x.x:8080 <http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}). IOEvent=CLOSED processor<http://10.45.12.59:8080/>
> =org.glassfish.grizzly.filterchain.DefaultFilterChain_at_74a2b686,
>
> 2014-01-02
> 11:26:25.312Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null<http://10.45.12.59:8080/>,
> address=null],
>
> 2014-01-02
> 11:26:25.312Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null, ad<http://10.45.12.59:8080/>dress=null]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.312Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null, addres<http://10.45.12.59:8080/>s=null],
>
>
> 2014-01-02
> 11:26:25.313Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null, add
> ress=nu <http://10.45.12.59:8080/>ll]
> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.313Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null, address
> =null], <http://10.45.12.59:8080/>
>
> 2014-01-02
> 11:26:25.313Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null,
> address=null] next <http://10.45.12.59:8080/>
> Action=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.313Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null,
> address=null], <http://10.45.12.59:8080/>
>
> 2014-0 <http://10.45.12.59:8080/>1-02
> 11:26:25.415Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null,
> address=null] nextAction=o <http://10.45.12.59:8080/>
> rg.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.416Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.HttpServerFilter_at_49354a73context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null,
> address=null],
>
> 2014-01-02 11: <http://10.45.12.59:8080/>26:25.416Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.HttpServerFilter_at_49354a73context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=CLOSE, message=null,
> address=null] nextAction=org.glass <http://10.45.12.59:8080/>
> fish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.416Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>] nextActi<http://10.45.12.59:8080/>
> on=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.416Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter. fi <http://10.154.141.88:53735/>
> lter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>] nextAction=o<http://10.45.12.59:8080/>
> rg.glassfish.grizzly.filterchain.StopAction_at_1c909fae,
>
> 2014-01-02 11:26:25.416Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor execute, executing
> connection (TCPNIOConnection{localSocketAddress={/x.x.x.x:8<http://10.45.12.59:8080/>
> 080}, p <http://10.154.141.88:53735/>eerSocketAddress={/x.x.x.x:53735}}).
> IOEvent=NONE processor=org.glassfish.grizzly.filterchain.DefaultFilte
> rChain@ <http://10.45.12.59:8080/>74a2b686,
>
> 2014-01-02
> 11:26:25.416Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:2 <http://10.45.12.59:8080/>5.417Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter@78e61427context=FilterChainContext[conne<http://10.154.141.88:53735/>
> ction=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>] nextAction=org.gl
> assfish <http://10.45.12.59:8080/>
> .grizzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.417Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter. filter=org.glassfish.grizzly.utils.IdleTime
> outFilt <http://10.154.141.88:53735/>er@2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.417Z,o <http://10.45.12.59:8080/>rg.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext [connection=TCPNIOConnectio
> n{local <http://10.154.141.88:53735/>SocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly <http://10.45.12.59:8080/>
> .filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.417Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter@30092b95 context=Filter<http://10.154.141.88:53735/>ChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.417Z,org.glass <http://10.45.12.59:8080/>fish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x<http://10.45.12.59:8080/>
> .x.x:80 <http://10.154.141.88:53735/>80 <http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterc <http://10.45.12.59:8080/>
> hain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.417Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter@46c2cbacontext=FilterChainContext[conne<http://10.154.141.88:53735/>
> ction=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT, message=null,
> address=/x.x.x.x:53735 <http://10.154.141.88:53735/>],
>
> 2014-01-02 11:26:25.418Z,org.glassfish.gri <http://10.45.12.59:8080/>zzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddr <http://10.154.141.88:53735/>ess={/x.x.x.x:53735}},
> operation=EVENT, message=null, address=/x.x.x.x:53735<http://10.154.141.88:53735/>]
> nextAction=org.glassfish.grizzly.filterchain.Inv<http://10.45.12.59:8080/>
> okeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.460Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.HttpServerFilter_at_49354a73context=FilterChainContext [connection=TCP
> NIOConn <http://10.154.141.88:53735/>ection{localSocketAddress={/
> x.x.x.x:8080 <http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53735}}, operation=READ,
> message=org.glassfish.grizzly.http.server.Response_at_fb25d38, address=/
> x.x.x.x:53735 <http://10.154.141.88:53735/>] nextAct<http://10.45.12.59:8080/>
> ion=org.glassfish.grizzly.filterchain.StopAction_at_1c909fae,
>
> 2014-01-02 11:26:25.569Z,org.glassfish.grizzly.ProcessorExecutor
> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor execute, executing
> connection (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}). IOEvent=READ
> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain@7<http://10.154.141.88:53735/>4a2b686,
>
>
> 2014-01-02 11:26:25.569Z,org. <http://10.45.12.59:8080/>glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ, message=null,
> address=null],
>
> 2014-01-02 11:26:25.569Z,org.glassfish.grizzly.nio.transport.TCPNIOT
> ranspor <http://10.45.12.59:8080/>t readwt:minNq,
> org.glassfish.grizzly.nio.transport.TCPNIOTransport read, TCPNIOConnection
> (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}) (allocated) read 120 bytes,
>
> 2014-01-02
> 11:26:25.569Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:mi <http://10.45.12.59:8080/>nNq,
> org.glassfish.grizzly.filterchain.DefaultFilterChain executeFilter, after
> execute filter.
> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cbacontext=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ, message=HeapBuffer
> (526498241) [pos=0 lim=120 cap=120], address=/x.x.x.x:53770<http://10.154.141.88:53770/>]
> nextAction=org.glassfish.gr <http://10.45.12.59:8080/>
> izzly.filterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.569Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAd <http://10.154.141.88:53770/>dress={/x.x.x.x:53770}},
> operation=READ, message=HeapBuffer (526498241) [pos=0 lim=120 cap=120],
> address=/x.x.x.x:53770 <http://10.154.141.88:53770/>],
>
> 2014-01-02 11:26:25.570Z,org. <http://10.45.12.59:8080/>glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ,
> message=org.glassfish.grizzly.ht <http://10.154.141.88:53770/>
> tp.HttpContent@3517402, address=/x.x.x.x:53770<http://10.154.141.88:53770/>]
> nextAction=org.glassfish.grizzly.fi <http://10.45.12.59:8080/>
> lterchain.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.570Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770} <http://10.154.141.88:53770/>},
> operation=READ, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
> address=/x.x.x.x:53770 <http://10.154.141.88:53770/>],
>
> 2014-01-02 11:26:25.570Z,org.glassfis <http://10.45.12.59:8080/>h.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.utils.IdleTimeoutFilter_at_2a0c5bd6context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ,
> message=org.glassfish.grizzly.http.HttpContent@3517402<http://10.154.141.88:53770/>,
> address=/x.x.x.x:53770 <http://10.154.141.88:53770/>]
> nextAction=org.glassfish.grizzly.filterchai <http://10.45.12.59:8080/>
> n.InvokeAction_at_59ec699a,
>
> 2014-01-02
> 11:26:25.570Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ, m<http://10.154.141.88:53770/>
> essage=org.glassfish.grizzly.http.HttpContent_at_3517402, address=/
> x.x.x.x:53770 <http://10.154.141.88:53770/>],
>
> 2014-01-02 11:26:25.570Z,org.glassfish.grizzl <http://10.45.12.59:8080/>y.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, after execute filter.
> filter=org.glassfish.grizzly.http.server.FileCacheFilter_at_78e61427context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ,
> message=org.glassfish.grizzly.http.HttpContent_at_3517402, address=/
> x.x.x.x:53770 <http://10.154.141.88:53770/>]
> nextAction=org.glassfish.grizzly.filterchain.Invoke<http://10.45.12.59:8080/>
> Action_at_59ec699a,
>
> 2014-01-02
> 11:26:25.570Z,org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilterwt:minNq, org.glassfish.grizzly.filterchain.DefaultFilterChain
> executeFilter, Execute filter.
> filter=org.glassfish.grizzly.http.server.HttpServerFilter_at_49354a73context=FilterChainContext
> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080<http://10.45.12.59:8080/>},
> peerSocketAddress={/x.x.x.x:53770}}, operation=READ, message=org.glass
> fish.gr <http://10.154.141.88:53770/>izzly.http.HttpContent@3517402,
> address=/x.x.x.x:53770 <http://10.154.141.88:53770/>],
>
> 2014-01-02 11:26:25.571Z,org.glassfish.grizzly.http.i<http://10.45.12.59:8080/>o.InputBuffer
> logwt:minNq, org.glassfish.grizzly.http.io.InputBuffer log, InputBuffer
> org.glassfish.grizzly.http.server.io.ServerInputBuffer_at_4483075einitialize with ready content: ByteBufferWrapper (1837101520)
> [visible=[java.nio.HeapByteBufferR[pos=0 lim=0 cap=0]]],
> 2014-01-02 11:26:25.571Z,org.glassfish.grizzly.http.util.Parameters
> setQueryStringEncodingwt:minNq, org.glassfish.grizzly.http.util.Parameters
> setQueryStringEncoding, Set query <http://10.154.141.88:53770/>string
> encoding to null,
>
>
>
> On Sun, Dec 22, 2013 at 6:07 AM, Oleksiy Stashok <
> oleksiy.stashok_at_oracle.com> wrote:
>
>> Hi Andrea,
>>
>> it would be interesting to see some profiling data, because service() is
>> actually the place where requests are getting processed, it's a place where
>> Grizzly passes control to Jersey to handle the request. So to understand
>> the problem (if there is a problem) we need more details.
>>
>> Thanks.
>>
>> WBR,
>> Alexey.
>>
>>
>> On 21.12.13 09:12, Andrea Ulisse wrote:
>>
>>> Hello,
>>> I am using Grizzly and Jersey 2.3.1
>>>
>>> I really need to have optimal performance, and I have millions of daily
>>> active users in my cluster.
>>>
>>> I noticed that sometimes Jersey spends about 200ms on this method:
>>> GrizzlyHttpContainer.service().
>>>
>>> I got the time looking at logging time between
>>> logger.debugLog("GrizzlyHttpContainer.service(...) started");
>>> and
>>> logger.debugLog("GrizzlyHttpContainer.service(...) finished");
>>>
>>> Could someone help me please?
>>>
>>> Thanks,
>>> Andrea
>>>
>>
>>
>
>