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_78e61427
> context=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_78e61427
> context=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@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_2a0c5bd6
> context=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_2a0c5bd6
> context=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@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_30092b95
> context=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_30092b95
> context=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_at_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_46c2cba
> context=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
> directWrit <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_46c2cba
> context=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_78e61427
> context=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_78e61427
> context=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_2a0c5bd6
> context=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_2a0c5bd6
> context=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_30092b95
> context=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_46c2cba
> context=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@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@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_46c2cba
> context=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_46c2cba
> context=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_30092b95
> context=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_30092b95
> context=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=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_2a0c5bd6
> context=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_2a0c5bd6
> context=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@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_78e61427
> context=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_78e61427
> context=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@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_49354a73
> context=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_49354a73
> context=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@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_46c2cba
> context=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@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@30092b95
> context=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@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.DefaultFilterChain@
> <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_78e61427
> context=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_at_78e61427
> context=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
> <http://org.gl>assfish
> <http://10.45.12.59:8080/>.grizzly.filterchain.InvokeAction@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.IdleTimeoutFilt
> <http://10.154.141.88:53735/>er@2a0c5bd6 context=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_2a0c5bd6
> context=FilterChainContext [connection=TCPNIOConnection{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@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_at_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_30092b95
> context=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@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_at_46c2cba
> context=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_46c2cba
> context=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@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_49354a73
> context=FilterChainContext [connection=TCPNIOConn
> <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@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_at_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_46c2cba
> context=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.TCPNIOTranspor
> <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_46c2cba
> context=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@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_30092b95
> context=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_30092b95
> context=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@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_2a0c5bd6
> context=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_2a0c5bd6
> context=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
> <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@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_78e61427
> context=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@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_78e61427
> context=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@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_49354a73
> context=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.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_4483075e
> initialize 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,
> Setquery <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 <mailto: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
>
>
>