[Jersey] Re: Fwd: Performance issue with Jersey 2.3.1

From: Andrea Ulisse <aulisse_at_beintoo.com>
Date: Thu, 2 Jan 2014 14:57:12 +0100

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.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_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@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@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_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_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_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.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_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_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, 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
>>
>
>