Rainer -- Thanks for your help again.
First of all, we are running Linux 2.6.9 64 bit on Intel Pentium hardware. The apache software is Apache 2.2 running mod_jk 1.2.25. The Tomcat software is JBOSS 4.21GA(Tomcat 6.0.10). I got a trace using some of the settings you have below. I'm not quite sure how to get the whole thing to you, as it is fairly large, and I don't wish to post it to the mailing list. In any event the relevant lines from one example of an interaction I am attaching below. 10.45.3.22 is the apache 2.2 server and 10.45.3.21 and 10.45.3.24 are the tomcat servers. The trace was taken from the apache server. There are numerous other examples of this type of interaction. 02:49:04.329952 IP 10.45.3.22.34977 > 10.45.3.21.8009: F 2991069804:2991069804(0) ack 1909717451 win 8244 <nop,nop,timestamp 865633671 2700468480> 02:49:04.370343 IP 10.45.3.21.8009 > 10.45.3.22.34977: . ack 1 win 1448 <nop,nop,timestamp 2700815038 865633671> 02:49:06.329558 IP 10.45.3.22.34972 > 10.45.3.24.8009: F 2991428814:2991428814(0) ack 330342931 win 4624 <nop,nop,timestamp 865635671 4202573488> 02:49:06.369533 IP 10.45.3.24.8009 > 10.45.3.22.34972: . ack 1 win 2269 <nop,nop,timestamp 4202873970 865635671> 02:49:08.329843 IP 10.45.3.22.35008 > 10.45.3.24.8009: S 3372523679:3372523679(0) win 5840 <mss 1460,sackOK,timestamp 865637671 0,nop,wscale 2> 02:49:08.329961 IP 10.45.3.24.8009 > 10.45.3.22.35008: S 707449532:707449532(0) ack 3372523680 win 5792 <mss 1460,sackOK,timestamp 4202875930 865637671,nop,wscale 2> 02:49:08.329972 IP 10.45.3.22.35008 > 10.45.3.24.8009: . ack 1 win 1460 <nop,nop,timestamp 865637671 4202875930> 02:49:08.330001 IP 10.45.3.22.35008 > 10.45.3.24.8009: P 1:821(820) ack 1 win 1460 <nop,nop,timestamp 865637671 4202875930> 02:49:08.330023 IP 10.45.3.22.35008 > 10.45.3.24.8009: P 821:921(100) ack 1 win 1460 <nop,nop,timestamp 865637671 4202875930> My analysis of this is as follows: 1) A request comes in to the apache server, which has two timed out socket connections to the tomcat servers on ports 34977 and 34972. At 02:49:04.329952 it sends a FIN packet to the tomcat server and receives a response at 02:49:04.370343. It then waits two seconds from the time it sent the FIN packet. 2) At 02:49:06.329558 it sends a FIN packet to the other tomcat server and receives a response at 02:49:06.369533. It then waits two seconds from the time it sent the FIN packet, and then creates a new socket (35008) on which it successfully sends the transaction. Larry -----Original Message----- From: Rainer Jung [mailto:[EMAIL PROTECTED] Sent: Sunday, November 04, 2007 12:38 AM To: Tomcat Developers List Subject: Re: Delays in mod_jk Hi Larry, your analysis is correct, but the results nevertheless a little obscure. Yes, mod_jk has no internal timing of management threads. We will move mod_jk to the APR libraries when starting JK3, but at the moment we rely completely on the web server plugin API. Apache has no timing API, so we need to pack our maintenance on top of request handling. Nevertheless, we don't expect the shutdown process to take that long. In fact, there is a timeout of 2 seconds only used for select in a loop that tries to read pending data from a connection we want to shut down. Usually this draining should not really happen. When I test the code on Solaris, I see no waiting in the select for a connection, that is idle. The select returns betwen 0 and 2 milliseconds after calling it (at least that's what I get from logging). So now the questions are: - what is your OS? - are there any network components between httpd and jboss, which could influence connection shutdown negatively (firewall etc.)? - was jboss very busy during this test? If you can easily reproduce the behaviour, can you sniff a connection? How do I test? I use a simple JSP sleep.jsp: ==== <[EMAIL PROTECTED] session="false"%> Sleeping ... <% Thread.sleep(100); %> Done. ===== For testing I configure connection_pool_timeout very low, e.g. 10 seconds and connection_pool_minsize to 1. Then I send a couple of concurrent requests to the JSP to open a couple of connections. For this I use the Apache httpd tool ab contained in the bin directory bin/ab -c 5 -n 100 http://myhost:myport/sleep.jsp You can check via "netstat -an" if a couple of backend connections are ESTABLISHED. Now wait a minute and call the JSP once, e.g. with a browser. mod_jk should then close all backend connections used by the httpd process that handles this request (apart from 1 remaining connection). If this works for you too, you can sniff the backend traffic after the ab run and before the final request. Regards, Rainer Larry Reisler schrieb: > We are running JBOSS 4.21GA(Tomcat 6.0.10) with mod_jk 1.25 on Apache > 2.2.x, and have run into something of a performance issue. > > We have the system setup so that threads on mod_jk and tomcat timeout > after 10 minutes (an heuristic which has been discussed in some of > the documentation) using the properties on the mod_jk side: > worker.node1.connection_pool_timeout=600,and on the Tomcat side > connectionTimeout="600000". > > We have noticed that some transactions to the apache server were > running slow. After looking at the logs, the mod_jk logs indicated > that the transaction executed relatively quickly (eg. < .03 seconds) > whereas the apache access logs indicated that the transaction took > something more like 2.040 seconds. After enabling trace logs on > mod_jk, it became clear that sometimes before executing a > transaction, mod_jk would call the maintain function, which in turn > would close sockets that had exceeded the time limit of 10 minutes > using jk_shutdown_socket. As per the code message in > jk_shutdown_socket, the socket would take two seconds to shut down, > causing a delay (sometimes it would shut down two or three sockets, > resulting in a delay of 2,4, or 6 seconds). The time spent doing the > maintenance was before the real work of sending the data to Tomcat, > so the mod_jk.log did not reflect that in its timing. Nevertheless, > the transactions are being delayed. > > I found that the number of delays was directly related to the > connection_pool_timeout: a higher timeout meant fewer delays – this > is what I would have expected given my understanding of the problem. > > I tried setting worker.maintain on the mod_jk side to 10 seconds, but > the problem still occurs. > > A couple of questions come out of this: 1. Should the thread > processing the request be running maintain at all? My understanding > is that there is a separate maintenance thread that is running by > default every 60 seconds. Can’t that thread perform the maintenance > exclusively? 2. If the processing thread does have to run the > maintain function, then maybe it could simply place the expired > sockets on a queue for later processing by the maintain thread, or > perhaps send the FIN packet and then place them on a queue. 3. Is > there some reason that Tomcat would not be sending the FIN packet to > mod_jk immediately? > > Thanks Larry Reisler ____________________________________ Come meet Vringo at the following events... Nov 4-6 Rutberg Wireless Influencers, Laguna Niguel, CA Dec 4-5 Nokia World, Amsterdam Dec 11-12 Le Web, Paris Would be delighted to see you... --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
