Hi Andrea,
please see inline...
On 09 Jan 2014, at 12:51, Andrea Ulisse <aulisse_at_beintoo.com> wrote:
> Hi Jakub,
> the big delay is for the minority of the requests.
At least something. So now i guess you want to make the size of the minority as small as possible, right?
In my experience, under certain load, and especially, when you CPU load is maxed, it is hard to get rid of cases, where things go wrong.
In these cases you would experience awful latency or even bad/lost responses. Some of these issues might be even coming from outside of JVM itself.
>
> I performed the test with a proper warm up, as you suggest. The beahaviuor of my jvm is similar to the attachments.
Good news, we seem to be at the same page now then.
>
> 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?
I am not really sure. Your settings look safe. Unfortunately, there is not a single magical configuration that would fit all cases.
Then i am afraid you would need to fine tune your settings yourself to fit your particular use case.
You need to have a good test suite (including stable environment where you can test), that would give you reliable results.
Then you may want to experiment with runtime options such as thread pool parameters, JVM GC parameters, heap size, etc.
~Jakub
P.S. Here is a few JVM options that might be relevant, that i used for the simple hello world app test,
just in case it would help (please bear in mind what i wrote above, i.e. it probably would not):
-server -XX:+AggressiveOpts -XX:+UseFastAccessorMethods
>
> 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
>
> <ab-first.png>
> <ab-last.png>
>
>
> 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},
>>>>>
>>>>> 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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=WRITE,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=WRITE,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.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_2a0c5bd6
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=WRITE,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-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.utils.IdleTimeoutFilter_at_2a0c5bd6
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=WRITE,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.grizzly.filterchain.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_30092b95
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=WRITE,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.304Z,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},
>>>>>
>>>>> peerSocketAddress={/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]
>>>>> nextAction=org.glassfish.grizzly.filterchain.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.filterchain.TransportFilter_at_46c2cba
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/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],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.304Z,org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
>>>>>
>>>>> doFineLogwt:minNq,
>>>>> org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
>>>>> doFineLog, AsyncQueueWriter.write
>>>>> connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}
>>>>>
>>>>> record=org.glassfish.grizzly.asyncqueue.AsyncWriteQueueRecord_at_2953cdfe
>>>>>
>>>>> directWrite=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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=WRITE, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.305Z,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},
>>>>>
>>>>> 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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.306Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>>>>>
>>>>>
>>>>> 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.utils.IdleTimeoutFilter_at_2a0c5bd6
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=EVENT,
>>>>>
>>>>> message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.306Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT,
>>>>>
>>>>> message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_at_59ec699a,
>>>>>
>>>>>
>>>>> 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.http.HttpServerFilter_at_30092b95
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}, operation=EVENT,
>>>>>
>>>>> message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.306Z,org.glassfish.grizzly.ProcessorExecutor
>>>>>
>>>>> executewt:minNq,
>>>>> org.glassfish.grizzly.ProcessorExecutor
>>>>> execute, executing connection
>>>>> (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}). IOEvent=NONE
>>>>> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT,
>>>>>
>>>>> message=null,
>>>>>
>>>>> address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.311Z,org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
>>>>>
>>>>> doFineLogwt:minNq,
>>>>> org.glassfish.grizzly.nio.AbstractNIOAsyncQueueWriter
>>>>> doFineLog, AsyncQueueWriter.write
>>>>>
>>>>> connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}
>>>>>
>>>>> record=org.glassfish.grizzly.asyncqueue.AsyncWriteQueueRecord_at_2953cdfe
>>>>>
>>>>> directWrite=true,
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.312Z,org.glassfish.grizzly.ProcessorExecutor
>>>>>
>>>>> executewt:minNq, org.glassfish.grizzly.ProcessorExecutor
>>>>>
>>>>> execute, executing connection
>>>>> (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}).
>>>>> IOEvent=CLOSED processor=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_46c2cba
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null,
>>>>> 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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null,
>>>>>
>>>>> address=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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null,
>>>>> address=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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null]
>>>>>
>>>>> 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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=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.utils.IdleTimeoutFilter_at_2a0c5bd6
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null]
>>>>>
>>>>> 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.http.server.FileCacheFilter_at_78e61427
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null],
>>>>>
>>>>> 2014-01-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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null]
>>>>> nextAction=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, Execute filter.
>>>>> filter=org.glassfish.grizzly.http.server.HttpServerFilter_at_49354a73
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null],
>>>>>
>>>>> 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.http.server.HttpServerFilter_at_49354a73
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=CLOSE, message=null, address=null]
>>>>> nextAction=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.
>>>>> filter=org.glassfish.grizzly.filterchain.TransportFilter_at_46c2cba
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=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.
>>>>>
>>>>> filter=org.glassfish.grizzly.http.HttpServerFilter_at_30092b95
>>>>>
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.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:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}}).
>>>>>
>>>>> IOEvent=NONE
>>>>> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.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
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.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.IdleTimeoutFilter_at_2a0c5bd6
>>>>>
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.417Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.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.http.HttpServerFilter_at_30092b95
>>>>> context=FilterChainContext
>>>>>
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.417Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.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.filterchain.TransportFilter_at_46c2cba
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.418Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>>
>>>>> operation=EVENT, message=null, address=/x.x.x.x:53735]
>>>>> nextAction=org.glassfish.grizzly.filterchain.InvokeAction_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_49354a73
>>>>> context=FilterChainContext [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53735}},
>>>>> operation=READ,
>>>>> message=org.glassfish.grizzly.http.server.Response_at_fb25d38,
>>>>> address=/x.x.x.x:53735]
>>>>> nextAction=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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}}).
>>>>> IOEvent=READ
>>>>> processor=org.glassfish.grizzly.filterchain.DefaultFilterChain_at_74a2b686,
>>>>>
>>>>>
>>>>> 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.filterchain.TransportFilter_at_46c2cba
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x: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.TCPNIOTransport
>>>>> readwt:minNq,
>>>>> org.glassfish.grizzly.nio.transport.TCPNIOTransport
>>>>> read, TCPNIOConnection
>>>>> (TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}})
>>>>> (allocated) read 120 bytes,
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.569Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ, message=HeapBuffer (526498241)
>>>>> [pos=0 lim=120 cap=120], address=/x.x.x.x:53770]
>>>>> nextAction=org.glassfish.grizzly.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_30092b95
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>>
>>>>> operation=READ, message=HeapBuffer (526498241)
>>>>> [pos=0 lim=120 cap=120], address=/x.x.x.x:53770],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.570Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>>
>>>>> address=/x.x.x.x:53770]
>>>>> nextAction=org.glassfish.grizzly.filterchain.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_2a0c5bd6
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>>
>>>>> operation=READ,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53770],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.570Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53770]
>>>>> nextAction=org.glassfish.grizzly.filterchain.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_78e61427
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ,
>>>>>
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>>
>>>>> address=/x.x.x.x:53770],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.570Z,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},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ,
>>>>> message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>> address=/x.x.x.x:53770]
>>>>> nextAction=org.glassfish.grizzly.filterchain.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.HttpServerFilter_at_49354a73
>>>>> context=FilterChainContext
>>>>> [connection=TCPNIOConnection{localSocketAddress={/x.x.x.x:8080},
>>>>>
>>>>> peerSocketAddress={/x.x.x.x:53770}},
>>>>> operation=READ, message=org.glassfish.grizzly.http.HttpContent_at_3517402,
>>>>>
>>>>> address=/x.x.x.x:53770],
>>>>>
>>>>>
>>>>> 2014-01-02
>>>>>
>>>>> 11:26:25.571Z,org.glassfish.grizzly.http.io.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 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
>>>>>
>>>>>
>>>>
>>>>
>>>
>>
>>
>
>