Thanks for the explanation David.
I added System.nanoTime() to get high resolution numbers. Nano second
numbers are telling me the same thing. When thread changes we see a
difference of about 82ms (3082462134714 - 3082379268473 = 82866241).
Within the same thread the time difference is something between 84 to
22 micros seconds (3082462218770 - 3082462134714 = 84056) ,
(3082462241008 - 3082462218770 = 22238).
I think if it is a time resolution issue it should apply to all log
lines. Why is it the case that only when thread is switching we see
this huge hiccup? Thread context switch affects this but it cannot be
in order of milli seconds.
Any thoughts?
Thanks.
---
LOGGER.trace(COLLECTOR_ENDPOINT_MARKER, "message-trace: in: milli: {},
nano: {}, sessionId: {}, request: {}", () ->
System.currentTimeMillis(), () -> System.nanoTime(), () ->
session.getId(), () -> request.hashCode());
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082378990611,
sessionId: 0, request: 234588747
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379045895,
sessionId: 0, request: 1273692279
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379067928,
sessionId: 0, request: 1206749007
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379087676,
sessionId: 0, request: 1991241008
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379106147,
sessionId: 0, request: 668436604
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379153184,
sessionId: 0, request: 883743817
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379175153,
sessionId: 0, request: 533783148
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379196640,
sessionId: 0, request: 379538123
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379233562,
sessionId: 0, request: 227582988
21:39:35.035 [http-apr-8080-exec-5] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175035, nano: 3082379268473,
sessionId: 0, request: 1594654563
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462134714,
sessionId: 0, request: 1869543380
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462218770,
sessionId: 0, request: 28517044
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462241008,
sessionId: 0, request: 1405292860
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462263993,
sessionId: 0, request: 1931451722
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462310144,
sessionId: 0, request: 1809257642
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462334320,
sessionId: 0, request: 1936276966
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462356133,
sessionId: 0, request: 946374726
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462379203,
sessionId: 0, request: 923973580
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462401693,
sessionId: 0, request: 1689491392
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462423954,
sessionId: 0, request: 1578045629
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462446255,
sessionId: 0, request: 576293250
21:39:35.118 [http-apr-8080-exec-7] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175118, nano: 3082462469691,
sessionId: 0, request: 14153426
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544810118,
sessionId: 0, request: 1215254206
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544894555,
sessionId: 0, request: 1707677495
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544916363,
sessionId: 0, request: 1638262766
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544935837,
sessionId: 0, request: 51725213
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544954314,
sessionId: 0, request: 826140671
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544973258,
sessionId: 0, request: 476069440
21:39:35.201 [http-apr-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175201, nano: 3082544992647,
sessionId: 0, request: 1387540661
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627046012,
sessionId: 0, request: 396131997
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627129421,
sessionId: 0, request: 510974985
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627150868,
sessionId: 0, request: 1928984475
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627170432,
sessionId: 0, request: 1110175564
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627188653,
sessionId: 0, request: 917969154
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627207900,
sessionId: 0, request: 245043017
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627227334,
sessionId: 0, request: 862151726
21:39:35.283 [http-apr-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175283, nano: 3082627249002,
sessionId: 0, request: 774876289
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709170172,
sessionId: 0, request: 1235493857
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709237417,
sessionId: 0, request: 1039787453
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709275348,
sessionId: 0, request: 1930253181
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709294751,
sessionId: 0, request: 108050384
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709314195,
sessionId: 0, request: 1856190420
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709333395,
sessionId: 0, request: 470152112
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709355183,
sessionId: 0, request: 84594166
21:39:35.365 [http-apr-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: milli: 1446241175365, nano: 3082709376459,
sessionId: 0, request: 113718448
On Fri, Oct 30, 2015 at 12:36 PM, David kerber <dcker...@verizon.net> wrote:
> On 10/30/2015 3:23 PM, Farzad Panahi wrote:
>>
>> Mark - Could you elaborate a bit more on what you mean by "resolution
>> of the timestamps for the log messages"? If you are referring to the
>> log4j latency
>> (https://logging.apache.org/log4j/2.x/manual/async.html#Latency),
>> it is in microseconds.
>>
>> If it has anything to do with the logger why is it happening on thread
>> switch only and is so consistent? In your opinion what is a good way
>> to monitor or measure the performance of tomcat websocket message
>> processing?
>
>
> It has to do with the resolution of the timer function being called by the
> logger to generate the time stamp, which in turn depends on the OS. I see
> conflicting values when I search around, but 10ms and 50ms are common values
> I've seen, and also 1/16 of a second, which is ~66ms. Different gettime
> methods have different resolutions too.
>
>
>
>
>>
>> Cheers
>>
>> Farzad
>>
>> On Fri, Oct 30, 2015 at 3:16 AM, Mark Thomas <ma...@apache.org> wrote:
>>>
>>> On 30/10/2015 00:03, Farzad Panahi wrote:
>>>>
>>>> Hi,
>>>>
>>>> I am using tomcat 8.0.23 to terminate my websocket connections. I was
>>>> looking at my trace logs and noticed that when tomcat worker thread
>>>> responsible for processing websocket messages switches to a different
>>>> thread, there is about 80ms delay.
>>>
>>>
>>> No there isn't. There is about an 80ms resolution of the timestamps for
>>> the log messages.
>>>
>>> Mark
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
>>> For additional commands, e-mail: users-h...@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
>> For additional commands, e-mail: users-h...@tomcat.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
