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 |
|