tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Marcin ZajÄ…czkowski <>
Subject mod_jk -> tomcat sending delay
Date Fri, 26 Jan 2007 11:24:24 GMT

I observe in mod_jk's log errors:
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down 
or refused connection. No response has been sent to the client (yet)

In the rush hours (20-30 requests/second) up to several entries per hour.
Sometimes it's followed by:
[error] ajp_service::jk_ajp_common.c (1928): (ajp13w) Connecting to 
tomcat failed. Tomcat is probably not started or is listening on the 
wrong port
[error] ajp_connection_tcp_get_message::jk_ajp_common.c (948): (ajp13w) 
can't receive the response message from tomcat, network problems or 
tomcat is down (, err=-104

but usually it is covered by another retries. It's corresponding to 
exception in tomcat:
ERROR [org.apache.jk.common.HandlerRequest] Error decoding request Read timed out

*Note* Post is quite long because of info from logs. To get know what it 
is about it is enough to read descriptions next to numbers.

I increased logs granularity (mod_jk and tomcat + tcpdump) and in a few 
checked issues it looks like:

*1*. mod_jk talks with tomcat and some request is serviced.

[11:10:30] [debug] ajp_process_callback::jk_ajp_common.c (1491): AJP13 
protocol: Reuse is OK
[debug] ajp_done::jk_ajp_common.c (2258): recycling connection pool 
slot=0 for worker ajp13w
[debug] jk_handler::mod_jk.c (2126): Service finished with status=200 
for worker=wlb

*2*. A few seconds later thread is used again by an another request.

[11:10:32] [debug] wc_get_worker_for_name::jk_worker.c (114): found a 
worker wlb
[debug] wc_get_name_for_type::jk_worker.c (290): Found worker type 'lb'
[debug] init_ws_service::mod_jk.c (584): Service protocol=HTTP/1.1 
method=POST (...)
[debug] service::jk_lb_worker.c (840): service sticky_session=1 
[debug] service::jk_lb_worker.c (860): service worker=ajp13w route=ajp13w
[debug] ajp_get_endpoint::jk_ajp_common.c (2315): acquired connection 
pool slot=0
[debug] ajp_marshal_into_msgb::jk_ajp_common.c (548): ajp marshaling done
[debug] ajp_service::jk_ajp_common.c (1771): processing ajp13w with 2 
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending 
to ajp13 pos=4 len=307 max=8192
(...) [header is sent and it is received by tomcat]

a) mod_jk tries to send body:

[11:10:32] [debug] ajp_send_request::jk_ajp_common.c (1273): request 
body to send 646 - request body to resend 0

b) tomcat is waiting for it:
DEBUG [org.apache.jk.common.ChannelSocket] Call next 0 
DEBUG [org.apache.jk.common.HandlerRequest] Handling 2
DEBUG [org.apache.jk.common.ChannelSocket] receive()

*4*. 5 seconds later (connector timeout is 5000ms) tomcat throws exception:
[11:10:37] ERROR [org.apache.jk.common.HandlerRequest] Error decoding 
request Read timed out
and resets connection (regarding to tcpdump log)

*5*. A few more seconds later (e.g. 8 from point 3) mod_jk starts 
sending a body:
[11:10:40] [debug] ajp_connection_tcp_send_message::jk_ajp_common.c 
(893): sending to ajp13 pos=4 len=652 max=8192
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): 0000 
12 34 02 88 02 86 3C 3F (...) [body's dump]

*6*. Unfortunately connection was already reseted by tomcat and mod_jk 
got info about that:
[11:10:40] [info]  ajp_connection_tcp_get_message::jk_ajp_common.c 
(942): (ajp13w) Tomcat has forced a connection close for socket 28
[error] ajp_get_reply::jk_ajp_common.c (1566): (ajp13w) Tomcat is down 
or refused connection. No response has been sent to the client (yet)
[info]  ajp_service::jk_ajp_common.c (1877): (ajp13w) receiving from 
tomcat failed, recoverable operation attempt=0

*7*. mod_jk tries to do send request again to tomcat:
[11:10:40] [info]  ajp_service::jk_ajp_common.c (1916): (ajp13w) sending 
request to tomcat failed,  recoverable operation attempt=1
[debug] jk_open_socket::jk_connect.c (335): socket TCP_NODELAY set to On
[debug] jk_open_socket::jk_connect.c (433): trying to connect socket 28 
[debug] jk_open_socket::jk_connect.c (459): socket 28 connected to
[debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket 
28 to (
[debug] ajp_connection_tcp_send_message::jk_ajp_common.c (893): sending 
to ajp13 pos=4 len=307 max=8192

Usually (but not always) it is able to do that without errors.

I sniffed into mod_jk source code, but I haven't found a place where it 
can stuck.

What can be delay (about 8 seconds) in mod_jk between sending HTTP 
header and HTTP content caused by?

I use Apache 2.0.52 (with MPM prefork), mod_jk 1.2.20, JBoss 3.2.5 with 
Tomcat 5.0 (probably 5.0.27) and Red Hat Enterprise Linux ES 4.

mod_jk configuration is quite simple, without load balancing (and wasn't 
changed for years).





The only change in mod_jk config was:
JkShmSize 1024k

       <Connector port="8009" address=""
        minProcessors="5" maxProcessors="100"
        enableLookups="false" acceptCount="100" debug="0"
        connectionTimeout="5000" useURIValidationHack="false"

Thanks for your advice

To start a new topic, e-mail:
To unsubscribe, e-mail:
For additional commands, e-mail:

View raw message