Hi Jakub,
I am going to write you an update.
Yes, I want to make the size of the minority as small as possible During my
last day of tuning I got some good results (my jvm warm up is always ok).
1) I tried to tune the jvm with the options you suggested, but I did not
observe improvements
2) I got an improvement using a grizzly thread pool min/max 32/32 (as you
suggested), and I am glad about this.
3) I got the best performance improvement by setting the keep alive of
grizzly's threads from 5000 ms to 1 hour. After doing this, the time spent
for passing control from Grizzly to jersey's resource being served really
decresead, and this is a good result for me. From 400 ms (in the bad cases)
now I can always stay under 200ms when making 25 concurrent requests. So, I
think that my latency was due to some threads that get involved when
Grizzly passes control to Jersey. Isn't it?
Anyway, I am happy for the improvement but I really can't figure out what
happens in this two situations:
- Grizzly passes control to Jersey
- Last filter is executed and jersey resource starts to be served
4) A question.
Given that
- I have a server with 2 processor
- I am using the worker-thread strategy
- threads performs slow I/O operations,
Is it always true that the best number of selector thread is 2? I tried
with 4 and 12 and I got similar results. So I am going to set this value to
2, would you agree with me?
Thanks!
On Thu, Jan 9, 2014 at 6:16 PM, Jakub Podlesak <jakub.podlesak_at_oracle.com>wrote:
> 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<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@2a0c5bd6context=FilterChainContext [connection=TCPNIOConnectio<http://10.154.141.88:53735/>
>>>>
>>>> ...
>
> [Message clipped]