Hi,
Can anyone help me understand why apache seems to take seconds for just handing
a request over to mod_jk?
Some (Web-Service) Requests (1-2% overall) take between 2 and 45 (!) seconds
according to apache request-log. Developers (it's a small WebService written in
Java Running on an JBoss-Instance) told me that they can't find any request
that takes longer than 0.5 seconds (based on application-side logging) - so I
updated apache log-configuration to:
LogFormat "%h %l %u %t %{JK_WORKER_NAME}n \"%r\" %>s %b
[%D/jk:%{JK_REQUEST_DURATION}n] %{remote}p %X" common_timed_port
and they seem to be right:
e.g. (request.log):
10.1.1.1 - - [26/Mar/2013:08:18:26 +0100] jboss1 "POST /SomeServiceSOAP
HTTP/1.1" 200 516 [13299477/jk:0.046063] 55005 -
%D .. The time taken to serve the request, in microseconds.
%{JK_REQUEST_DURATION} .. Request duration in seconds and microseconds.
-> so the request takes 13.2 seconds to finish, but only 0.04 are spent in the
mod_jk module. What is apache doing the other time?
First I thought clients are very slow (network-wise) but tcp-ip tracing between
client and webserver shows that clients do send the whole request within
microseconds and then the webserver acks these packages and then "sleeps" for a
couple of seconds before handing over the request to mod_jk where it is handled
rather fast according to the logs.
Second idea was that the httpd as a whole is under stress, but according to our
monitoring (and looking on the server-status page) there are always enough free
slots and enough idle workers to serve any incoming requests (and there are no
"apache might run slow on free workers" warnings in the apache log which I have
seen on other occasions (the actual text of the message might be slightly
different)).
The machine running the webserver is not CPU-bound and other vhosts on the same
apache instance seem to work fine and do not have these strange "long running
requests".
We are using mpm_prefork_module and mod_jk serving these requests with a single
worker and the timeouts between the JBoss-AJP connector and the (mod_jk) worker
on apache side are matching.
Any hints (besides - Apache and mod_jk version are not on the latest level .. I
know ):
Httpd: 2.2.21
Mod_jk: 1.2.32
Worker.conf:
# Template with reasonable settings
worker.template.type=ajp13
worker.template.reply_timeout=60000
worker.template.prepost_timeout=10000
worker.template.connection_pool_timeout=60
worker.template.connect_timeout=10000
worker.template.socket_connect_timeout=10000
worker.template.socket_timeout=10
# jboss ports-01 auf jboss-25
worker.jboss1.reference=worker.template
worker.jboss1.host=jboss-35.mydomain.at
worker.jboss1.port=8109
And AJP-Conf on JBoss:
<Connector port="8009"
address="${jboss.bind.address}"
protocol="AJP/1.3"
emptySessionPath="true"
enableLookups="false"
redirectPort="8443"
maxThreads="800"
connectionTimeout="60000" />
The customer that complained about long response times has an
(application-side) timeout of 2 Seconds defined, which means after 2 seconds
the client doesn't care about the current request any more and sends a FIN/ACK
package to close the connection - which is answered immediately by a "ACK" from
apache - so tcp-connection stays "simplex open" only. In some cases apache yet
has not even handed the connection over to mod_jk. If it does so (another
couple of seconds later) the JBoss application server responds quickly and
apache tries to send the response back to the client but only gets an "RESET"
from the client who wanted to close the connection long ago ..
Anyway: Normally we shouldn't even come close to the 2 Second timeout
considering that network is very fast and application itself only needs 0.2
seconds on average and no longer than 0.5 max ..).
Andreas
