Why server taking so much time? Or is it a network delay?
 

Hi,
I am running apache on a Red Hat ES3 server which is connected to a LAN. Though there is no network congestion on the LAN it takes about half a minute for each request from a client. A tethereal snapshot is as follows..

0.000000 192.168.0.2 -> 192.168.0.17 TCP 59432 > http [SYN] Seq=2894610117 Ack=0 Win=5840 Len=0
0.000037 192.168.0.17 -> 192.168.0.2 TCP http > 59432 [SYN, ACK] Seq=1168270768 Ack=2894610118 Win=5792 Len=0
0.000124 192.168.0.2 -> 192.168.0.17 TCP 59432 > http [ACK] Seq=2894610118 Ack=1168270769 Win=1460 Len=0
0.000374 192.168.0.2 -> 192.168.0.17 HTTP GET /ii.htm HTTP/1.0
0.000391 192.168.0.17 -> 192.168.0.2 TCP http > 59432 [ACK] Seq=1168270769 Ack=2894610736 Win=6798 Len=0
28.056178 192.168.0.17 -> 192.168.0.2 HTTP HTTP/1.1 200 OK
28.056322 192.168.0.2 -> 192.168.0.17 TCP 59432 > http [ACK] Seq=2894610736 Ack=1168270954 Win=1728 Len=0

My question is where from this 28 second delay is coming and how to resolve the problem.

thanx

nice to see someone come armed with a tcp capture for once...

where is this capture actually from? the client? have you tried comparing it to the capture on the server? often you could get network level issues with arp requests failing or dns issues, but as this is a pause in a single established connection i can't think of any good reason to really think the network itself is at fault. what about the cpu load on the server maybe? swapping to disk obscenely high volumes of data? unlikely to be relevant really, but obviosuly you'd never expect such a delay. i'd explore this at apache level myself (after checking a tcpdump on the server side. what if you try to connect to the server from the server itself with wget or something...? also have you tried all levels of http client, from firefox to curl / wget? checked your apache logs?

That one was taken on the server.
Here are two more captures. One on the server and the other on the client side.

Server side --->>

0.000000 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [SYN] Seq=3777072020 Ack=0 Win=5840 Len=0
0.000032 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [SYN, ACK] Seq=1917876268 Ack=3777072021 Win=5792 Len=0
0.000125 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=3777072021 Ack=1917876269 Win=1460 Len=0
0.000374 192.168.0.250 -> 192.168.0.17 HTTP GET / HTTP/1.0
0.000389 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [ACK] Seq=1917876269 Ack=3777072148 Win=5792 Len=0
28.059166 192.168.0.17 -> 192.168.0.250 HTTP HTTP/1.1 200 OK
28.059337 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=3777072148 Ack=1917876883 Win=1767 Len=0
28.060079 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [FIN, ACK] Seq=3777072148 Ack=1917876883 Win=1767 Len=0
28.060127 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [FIN, ACK] Seq=1917876883 Ack=3777072149 Win=5792 Len=0
28.060329 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=3777072149 Ack=1917876884 Win=1767 Len=0


Client side --->>


0.000000 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [SYN] Seq=0 Ack=0 Win=5840 Len=0 MSS=1460 TSV=1543747012 TSER=0 WS=2
0.000185 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=155644061 TSER=1543747012 WS=0
0.000202 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=1543747013 TSER=155644061
0.000360 192.168.0.250 -> 192.168.0.17 HTTP GET / HTTP/1.0
0.000542 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [ACK] Seq=1 Ack=128 Win=5792 Len=0 TSV=155644061 TSER=1543747013
28.062836 192.168.0.17 -> 192.168.0.250 HTTP HTTP/1.1 200 OK (text/html)
28.062861 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=128 Ack=615 Win=7068 Len=0 TSV=1543775080 TSER=155646867
28.063583 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [FIN, ACK] Seq=128 Ack=615 Win=7068 Len=0 TSV=1543775080 TSER=155646867
28.063728 192.168.0.17 -> 192.168.0.250 TCP http > 39157 [FIN, ACK] Seq=615 Ack=129 Win=5792 Len=0 TSV=155646867 TSER=1543775080
28.063751 192.168.0.250 -> 192.168.0.17 TCP 39157 > http [ACK] Seq=129 Ack=616 Win=7068 Len=0 TSV=1543775080 TSER=155646867



And the following is when I tried to connect from the server itself --->>

0.000000 192.168.0.17 -> 192.168.0.17 TCP 36435 > http [SYN] Seq=2154306499 Ack=0 Win=32767 Len=0
0.000037 192.168.0.17 -> 192.168.0.17 TCP http > 36435 [SYN, ACK] Seq=2161593914 Ack=2154306500 Win=32767 Len=0
0.000061 192.168.0.17 -> 192.168.0.17 TCP 36435 > http [ACK] Seq=2154306500 Ack=2161593915 Win=32767 Len=0
0.000153 192.168.0.17 -> 192.168.0.17 HTTP GET / HTTP/1.0
0.000165 192.168.0.17 -> 192.168.0.17 TCP http > 36435 [ACK] Seq=2161593915 Ack=2154306599 Win=32767 Len=0
0.001143 192.168.0.17 -> 192.168.0.17 HTTP HTTP/1.1 200 OK
0.001165 192.168.0.17 -> 192.168.0.17 TCP 36435 > http [ACK] Seq=2154306599 Ack=2161594529 Win=32767 Len=0
0.002246 192.168.0.17 -> 192.168.0.17 TCP 36435 > http [FIN, ACK] Seq=2154306599 Ack=2161594529 Win=32767 Len=0
0.002306 192.168.0.17 -> 192.168.0.17 TCP http > 36435 [FIN, ACK] Seq=2161594529 Ack=2154306600 Win=32767 Len=0
0.002321 192.168.0.17 -> 192.168.0.17 TCP 36435 > http [ACK] Seq=2154306600 Ack=2161594530 Win=32767 Len=0



And this time I connect the server and the client via a cross cable. No switch is involved.

I check the apache logs. No unusual entry in the access_log and the error_log is empty.

No unusual disk activity and CPU load is around 1 to 3%.

Hope to find a solution.
thnx

what are you capturing with the command? just port 80? try expanding it to absolutely all ip packets, *could* be wanting a reverse lookup, but i didn't think apache did that....

Yes you are correct. The server was trying to do reverse lookup. The problem is solved now. No more 28 sec. delay.

Thanx a lot.

cool. again another case of teh poor poor network being blamed for a server misconfiguration. i seem to spend half my working life defending my network and doing other peoples jobs to prove it's the servers fault...