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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Reply via email to