Date: Thu, 9 Jan 2014 12:51:16 +0100
Hi Jakub,
the big delay is for the minority of the requests.
I performed the test with a proper warm up, as you suggest. The beahaviuor
of my jvm is similar to the attachments.
I observed that the activation of jul produced a delay, and removing it
allowed me to gain something.
Anyway my problem is not solved. I am using 4 thread pools in my project,
with a number of threads set to min / max / queue limit / keep alive / data
structure --> 5 / 25 / 500 / 5000 / ArrayBlockingQueue<Runnable>. I use
them for parallel execution of I/O operations in my resources.
Do you think that this may cause problems to the jvm performances? (I have
xms/xmx 2048/2048 and track stack size at 256KB. And, do you think that
this can produce the delay that I have in Grizzly - Jersey interaction?
Thanks!
On Tue, Jan 7, 2014 at 5:57 PM, Jakub Podlesak <jakub.podlesak_at_oracle.com>wrote:
> Hi Andrea,
>
> Is the big delay more less same for the majority of the requests?
> Or is it just just a rare exception?
>
> After a proper JVM warm-up the hot spot compiler should not spend
> significant amount of cycles with code optimizations.
> Few hundreds of calls is probably not sufficient. For Oracle JVM, you
> should be able to see what happens inside using e.g. VisualVM tool
> that comes bundled with Oracle JDK (jvisualvm command). JConsole shoud do
> the same work for you.
> Look for java.lang.management.CompilationMXBean, that should provide you
> information on compilation total time.
>
> Frankly i think a few hundreds of requests is not sufficient for a proper
> warm up.
>
> I have just made a simple experiment with the ab tool and options you have
> suggested, i have used a simple hello-world app
> running on Grizzly 2. Attached please see what happened after i run ab
> tool with the following options for 10 times:
> ab -n 1000 -c50 http://127.0.0.1:8080/text
> you see that after the first run, the hot spot compiler still have some
> work to do.
> The second screenshot is taken after i have loaded the app more seriously
> with wrk tool (i am not comparing these load generating tools here,
> this is just to differentiate the following output with what follows
> further bellow):
>
> —8<—
> wrk -c 50 -t 12 -d300s http://localhost:8080/text
> Running 5m test @ http://localhost:8080/text
> 12 threads and 50 connections
> Thread Stats Avg Stdev Max +/- Stdev
> Latency 3.54ms 5.61ms 190.01ms 93.70%
> Req/Sec 1.31k 328.46 2.41k 78.49%
> 4679942 requests in 5.00m, 468.96MB read
> Requests/sec: 15599.74
> Transfer/sec: 1.56MB
> —>8—
>
> then i run ab once more again, so that now you can compare the output for
> the very first and the very last ab tool invocation as follows:
>
> 1.st ab invocation:
> —8<—
> Concurrency Level: 50
> Time taken for tests: 1.016 seconds
> Complete requests: 1000
> Failed requests: 0
> Write errors: 0
> Total transferred: 123569 bytes
> HTML transferred: 4004 bytes
> Requests per second: 984.65 [#/sec] (mean)
> Time per request: 50.780 [ms] (mean)
> Time per request: 1.016 [ms] (mean, across all concurrent requests)
> Transfer rate: 118.82 [Kbytes/sec] received
>
> Connection Times (ms)
> min mean[+/-sd] median max
> Connect: 0 0 0.3 0 2
> Processing: 7 50 43.0 35 278
> Waiting: 7 47 41.4 34 265
> Total: 7 50 43.2 36 279
>
> Percentage of the requests served within a certain time (ms)
> 50% 36
> 66% 43
> 75% 51
> 80% 56
> 90% 73
> 95% 213
> 98% 222
> 99% 237
> 100% 279 (longest request)
> —>8—
>
> last ab invocation:
> —8<—
> Concurrency Level: 50
> Time taken for tests: 0.132 seconds
> Complete requests: 1000
> Failed requests: 0
> Write errors: 0
> Total transferred: 126604 bytes
> HTML transferred: 4084 bytes
> Requests per second: 7547.51 [#/sec] (mean)
> Time per request: 6.625 [ms] (mean)
> Time per request: 0.132 [ms] (mean, across all concurrent requests)
> Transfer rate: 933.15 [Kbytes/sec] received
>
> Connection Times (ms)
> min mean[+/-sd] median max
> Connect: 1 2 0.7 2 5
> Processing: 2 4 1.2 4 12
> Waiting: 1 3 0.9 3 12
> Total: 4 6 1.2 6 15
>
> Percentage of the requests served within a certain time (ms)
> 50% 6
> 66% 7
> 75% 7
> 80% 7
> 90% 8
> 95% 9
> 98% 9
> 99% 10
> 100% 15 (longest request)
> —>8—
>
> I hope the above helps to explain how insufficient JVM warm-up time could
> influence your measurement.
>
> I do not know if the problems you seem to have are caused by improper warm
> up or if there is something else,
> but the clarification above would hopefully help us to make some further
> progress.
>
> ~Jakub
>
>
>
> On 07 Jan 2014, at 12:38, Andrea Ulisse <aulisse_at_beintoo.com> wrote:
>
> Hi Jackob,
> thanks for your answer.
>
> I set the number of threads to 32 and 64, but I always have the same delay
> in the same point.
>
> Could you please explain me what do you mean for "after a proper JVM warm
> up"? I perform a warm up launching few hundreds of calls before running the
> test.
> Moreover, could you suggest me some jvm properties to be tuned for
> improving overall jersey performance? I am using the following:
>
> -XX:ThreadStackSize=256 -Xms2048m -Xmx2048m
>
> Thanks
>
>
>
>
> On Mon, Jan 6, 2014 at 11:58 AM, Jakub Podlesak <jakub.podlesak_at_oracle.com
> > wrote:
>
>> Hi Andrea,
>>
>> There should be a big improvement in Jersey 2.4 scalability in terms
>> of processing multiple requests at once in parallel in a multithreaded
>> environment.
>> It is related to https://java.net/jira/browse/JERSEY-2002
>> where we have identified and fixed some bottlenecks in HK2.
>>
>> However, our internal measurement suggest, that increasing number of
>> threads
>> over about 32 does not give you much in return (not sure what happens for
>> more than 64 threads).
>> From your previous communication i understand that you are already on
>> Jersey 2.4, but you allow up to 150 threads.
>> If my understanding is correct, could you please try to limit the number
>> of worker
>> threads to say 32 and re-test?
>>
>> Locally, i was able to get Jersey to serve more than 30k req/s for a
>> simple
>> text/plain hello world scenario, of course after a proper JVM warm up.
>>
>> ~Jakub
>>
>> P.S. There has been a new JIRA record filed recently that could be
>> related to your
>> use case, but from the information i have it is hard to say anything
>> specific.
>>
>>
>> On 04 Jan 2014, at 17:48, Oleksiy Stashok <Oleksiy.Stashok_at_oracle.com>
>> wrote:
>>
>> Hi Andrea,
>>
>> On 03.01.14 02:04, Andrea Ulisse wrote:
>>
>> 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?
>>
>> The 1st step is related to Jersey core, how it passes a request to your
>> resource;
>> on the 2nd step Jersey commits the response and passes it to Grizzly and
>> Grizzly sends the response to a client.
>>
>> 0.4 seconds is a huge delay, so as I mentioned, looks like something is
>> wrong, but difficult to say what exactly.
>>
>> Thanks.
>>
>> WBR,
>> Alexey.
>>
>>
>> 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.AbstractNIOAsync
>>> QueueWr <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_2953cdfedir
>>> 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_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.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
>>>>>
>>>>
>>>>
>>>
>>>
>>
>>
>>
>
>
(image/png attachment: ab-first.png)
(image/png attachment: ab-last.png)