You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Farzad Panahi <fa...@gmail.com> on 2015/10/30 01:03:01 UTC
80ms delay switching between worker threads
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. In my OnMessage implementation I
let the work done for each message by thread from the executor service
thread pool. So onMsg method supposed to return immediately.
Here is the OnMessage implementation and trace log messages. Any ideas
what is causing that delay?
@OnMessage
public void onMsg(Session session, byte[] request) {
LOGGER.trace(COLLECTOR_ENDPOINT_MARKER, "message-trace: in: onMsg:
sessionId: {}, request: {}", () -> session.getId(), () ->
request.hashCode());
executorService.execute(() ->
{
try {
ByteBuffer response = ByteBuffer.wrap(getResponse(session, request));
synchronized (session) {
session.getBasicRemote().sendBinary(response);
}
} catch (Exception e) {
LOGGER.catching(Level.FATAL, e);
}
});
}
23:39:59.723 [http-nio-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 61159560
23:39:59.723 [http-nio-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1603450534
23:39:59.723 [http-nio-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1776164192
23:39:59.723 [http-nio-8080-exec-9] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1289655200
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 2012164707
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1683437101
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1996648771
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1558367554
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1376817303
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 262877862
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1799864953
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 562399886
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 2001150465
23:39:59.804 [http-nio-8080-exec-4] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 565117005
23:39:59.885 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 853722315
23:39:59.885 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 905622955
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 524911688
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 924137147
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 334850062
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1942147126
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 544895426
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1044655000
23:39:59.886 [http-nio-8080-exec-8] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 105480518
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 263098887
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 851943979
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1368132917
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 62533047
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 2021636461
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1999014579
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1181926599
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 343383595
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 298252569
23:39:59.967 [http-nio-8080-exec-6] TRACE {} CollectorEndPoint -
message-trace: in: onMsg: start: sessionId: 0, request: 1391893120
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Farzad Panahi <fa...@gmail.com>.
André - I like your humour :D
On Fri, Oct 30, 2015 at 1:38 AM, André Warnier (tomcat) <aw...@ice-sa.com> wrote:
> On 30.10.2015 01: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. In my OnMessage implementation I
>> let the work done for each message by thread from the executor service
>> thread pool. So onMsg method supposed to return immediately.
>> Here is the OnMessage implementation and trace log messages. Any ideas
>> what is causing that delay?
>>
>
> Come on, let's be a bit humane here.
>
> According to : https://en.wikipedia.org/wiki/Time_%28Orders_of_magnitude%29
> tomcat here thus switches threads in less than the blink of an eye.
> Considering that most tomcats out there already process dozens of requests
> per second, day in, day out, without any holidays ever, with end-user
> clients that they barely know, don't you think that they can be allowed this
> slight pause between conversations ?
>
> Also, for the method supposed to return "immediately" : the (Google)
> definition of "immediately" says "here and now, this very minute". Surely 80
> ms is well within the specs then ?
>
> After all, websocket is an /asynchronous/ protocol.
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by "André Warnier (tomcat)" <aw...@ice-sa.com>.
On 30.10.2015 01: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. In my OnMessage implementation I
> let the work done for each message by thread from the executor service
> thread pool. So onMsg method supposed to return immediately.
> Here is the OnMessage implementation and trace log messages. Any ideas
> what is causing that delay?
>
Come on, let's be a bit humane here.
According to : https://en.wikipedia.org/wiki/Time_%28Orders_of_magnitude%29
tomcat here thus switches threads in less than the blink of an eye.
Considering that most tomcats out there already process dozens of requests per second, day
in, day out, without any holidays ever, with end-user clients that they barely know, don't
you think that they can be allowed this slight pause between conversations ?
Also, for the method supposed to return "immediately" : the (Google) definition of
"immediately" says "here and now, this very minute". Surely 80 ms is well within the specs
then ?
After all, websocket is an /asynchronous/ protocol.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Farzad,
On 10/31/15 2:11 AM, Farzad Panahi wrote:
> Hi Chris - I am using a linux instance on amazon cloud.
You may be seeing either of the following:
1. Loss of real-time clock resolution due to virtualization
(or support from the host OS)
2. Delays imposed on your instance by the hypervisor to maintain QoS
for other users on the same hardware
Try this on real hardware; otherwise there is too much chaos in a
virtualized environment to be able to draw concrete conclusions.
-chris
> On Oct 30, 2015 7:43 PM, "Christopher Schultz" <ch...@christopherschultz.net>
> wrote:
>
>> Farzad,
>>
>> On 10/30/15 6:10 PM, Farzad Panahi wrote:
>>> 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.
>>
>> What OS are you using? IIRC, the Windows timer has horrible resolution.
>> you can call System.currentTimeNanos all you want, but you won't get
>> anything meaningful lower than some threshold regardless of the actual
>> least significant digits coming back from those calls.
>>
>> -chris
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Farzad Panahi <fa...@gmail.com>.
Hi Chris - I am using a linux instance on amazon cloud.
On Oct 30, 2015 7:43 PM, "Christopher Schultz" <ch...@christopherschultz.net>
wrote:
> Farzad,
>
> On 10/30/15 6:10 PM, Farzad Panahi wrote:
> > 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.
>
> What OS are you using? IIRC, the Windows timer has horrible resolution.
> you can call System.currentTimeNanos all you want, but you won't get
> anything meaningful lower than some threshold regardless of the actual
> least significant digits coming back from those calls.
>
> -chris
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: 80ms delay switching between worker threads
Posted by Christopher Schultz <ch...@christopherschultz.net>.
Farzad,
On 10/30/15 6:10 PM, Farzad Panahi wrote:
> 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.
What OS are you using? IIRC, the Windows timer has horrible resolution.
you can call System.currentTimeNanos all you want, but you won't get
anything meaningful lower than some threshold regardless of the actual
least significant digits coming back from those calls.
-chris
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Farzad Panahi <fa...@gmail.com>.
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 <dc...@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-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by David kerber <dc...@verizon.net>.
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-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Farzad Panahi <fa...@gmail.com>.
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?
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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: 80ms delay switching between worker threads
Posted by Mark Thomas <ma...@apache.org>.
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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org