tomcat-users mailing list archives

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


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
or
[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 (127.0.0.1:8009), 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
java.net.SocketTimeoutException: 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 
id='8A49C0D934C8A115342BA5CBFC79C434'
[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 
retries
[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]

*3*.
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 
org.apache.jk.common.HandlerRequest@1ca8b3d
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
java.net.SocketTimeoutException: 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 
to 127.0.0.1:8009
[debug] jk_open_socket::jk_connect.c (459): socket 28 connected to 
127.0.0.1:8009
[debug] ajp_connect_to_endpoint::jk_ajp_common.c (847): Connected socket 
28 to (127.0.0.1:8009)
[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.


*Question*
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).

<workers.properties>
workers.tomcat_home=/jboss/deploy/jbossweb-tomcat50.sar
workers.java_home=/jboss/java
ps=/

worker.list=wlb,jkstatus

worker.ajp13w.type=ajp13
worker.ajp13w.host=localhost
worker.ajp13w.port=8009

worker.wlb.type=lb
worker.wlb.balance_workers=ajp13w
</workers.properties>

The only change in mod_jk config was:
JkShmSize 1024k

<servel.xml>
       <Connector port="8009" address="127.0.0.1"
        minProcessors="5" maxProcessors="100"
        enableLookups="false" acceptCount="100" debug="0"
        connectionTimeout="5000" useURIValidationHack="false"
        protocol="AJP/1.3"/>
</servel.xml>


Thanks for your advice
Marcin


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


Mime
View raw message