tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rainer Jung <rainer.j...@kippdata.de>
Subject Re: 2 second delays in mod_jk while "maintaining workers"
Date Tue, 07 Sep 2010 08:02:31 GMT
On 07.09.2010 09:05, John Baker wrote:
> On Tuesday 07 September 2010 06:28:33 you wrote:
>> On 09/06/2010 11:59 PM, John Baker wrote:
>>> What's jk_maintain?
>>>
>>
>> Function that maintains the workers
>> (closes excess connections inactive for a long time)
>>
>> Anyhow, like Rainer said, if that's the case
>> you should have something like this in the log (DEBUG)
>>
>> ... Shutdown socket 123 and read 123 lingering bytes in 2 sec.
>
> Is this what we're looking for?  There's a lot of it in the logs during the period in
which I switched on 'trace'.
>
> [Mon Sep 06 15:05:18.128 2010] [24061:1404667232] [debug] jk_shutdown_socket::jk_connect.c
(732): Shutdown socket 158 and rea  0 lingering bytes
>
> If so, what does this mean and how do I solve the problem?

You gave us the following log lines:

[Mon Sep 06 15:05:14.128 2010] [24061:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration
[Mon Sep 06 15:05:14.241 2010] [23945:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration
[Mon Sep 06 15:05:16.644 2010] [23944:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration
[Mon Sep 06 15:05:18.131 2010] [24061:1404667232] [debug]
init_ws_service::mod_jk.c (977): Service protocol=HTTP/1.1 method=GET
ssl=false host=(null) addr=10.117.112.1 name=xxx port=80 auth=(null)
user=(null) laddr=10.117.112.1 raddr=10.117.112.1 uri=/index.jsp
[Mon Sep 06 15:05:18.131 2010] [24061:1404667232] [debug]
get_most_suitable_worker::jk_lb_worker.c (997): found best worker
jboss51-integration2 (jboss51-integration2) using method 'Request'

Those are written by three different processes and threads (see the IDS 
[PID:TID] behind the timestamp) and thus three different requests. 
Sorting by request:

[Mon Sep 06 15:05:14.128 2010] [24061:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration
[Mon Sep 06 15:05:18.131 2010] [24061:1404667232] [debug]
init_ws_service::mod_jk.c (977): Service protocol=HTTP/1.1 method=GET
ssl=false host=(null) addr=10.117.112.1 name=xxx port=80 auth=(null)
user=(null) laddr=10.117.112.1 raddr=10.117.112.1 uri=/index.jsp
[Mon Sep 06 15:05:18.131 2010] [24061:1404667232] [debug]
get_most_suitable_worker::jk_lb_worker.c (997): found best worker
jboss51-integration2 (jboss51-integration2) using method 'Request'

[Mon Sep 06 15:05:14.241 2010] [23945:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration

[Mon Sep 06 15:05:16.644 2010] [23944:1404667232] [debug]
wc_maintain::jk_worker.c (339): Maintaining worker lb-jboss51-integration

So the first block shows something, the other two blocks only consist of 
one line, so we can not make any statements about durations.

In the first block, there is a 4 seconds gap between the start of the 
worker maintenance and the start of the service. This is the gap you are 
referring to?

The log message Mladen cited is written in line 813 (mod_jk version 
1.2.30) of jk_connect.c with level DEBUG: "Shutdown socket ... and read 
... lingering bytes in ... sec." Before the socket closing, there should 
also be messages like "About to shutdown socket ...". If those are not 
present, then the reason for the time gap is something else. Note that 
version 1.2.30 also ncludes the duration of the socket shutdown 
procedure, so it's better to use that version.

If you can reproduce with trace log level (very high log volume!), then 
one log block from "Maintaining" until "Service protocol=" would be helpful.

Regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message