[squid-users] Weird 3 second delay between Squid and F5 LB (reverse proxy)

From: Tory M Blue <tmblue@dont-contact.us>
Date: Fri, 27 Jul 2007 09:33:54 -0700

I'm not sure what is going on and have done so much tracing that I've
just probably confused things more then anything else.

i'm running Squid Cache: Version 2.6.STABLE12, on Fedora Core 6.

It's configured to point to a single parent (which is a Virtual IP on
the LB) with multiple servers sitting behind that virtual (so yes a
pool).

If i run wget's, socket scrpts etc, against squid pointing to a single
host, or have all 4 hosts listed as parents, there is no issue.

If I have squid pointing at the above mentioned VIP I see a 3 second
delay every x connections, can be the 9th, 30th or 100th connection
(again the 3 second delays are very random, but very bothersome).

Another point of interest, running thru a Netapp Cache there are zero delays..

Socket level test:

Fri Jul 27 08:56:53 2007: Iteration #28
Fri Jul 27 08:56:53 2007: Connecting to localhost:80...
Fri Jul 27 08:56:53 2007: Connected.
Fri Jul 27 08:56:53 2007: Sending request...
Fri Jul 27 08:56:53 2007: Sent.
Fri Jul 27 08:56:53 2007: Receiving response... <--- 3 second delay..
Fri Jul 27 08:56:56 2007: Received complete response.
Fri Jul 27 08:56:56 2007: Closing socket.
Fri Jul 27 08:56:56 2007: Socket closed.

Squid http debug: 3 second delay at end
----------------------------------------
2007/07/26 15:36:35| getMaxAge:
'http://host/abc/directorytest/c/i-1.JPG?rand=859749'
2007/07/26 15:36:35| ctx: enter level 0:
'http://host/abc/directorytest/c/i-1.JPG?rand=859749'
2007/07/26 15:36:35| refreshCheck:
'http:/host/abc/directorytest/c/i-1.JPG?rand=859749'
2007/07/26 15:36:35| STALE: expires 1185489395 < check_time 1185489455
2007/07/26 15:36:35| Staleness = 60
2007/07/26 15:36:35| refreshCheck: Matched '<none> 0 20% 259200'
2007/07/26 15:36:35| refreshCheck: age = 60
2007/07/26 15:36:35| check_time: Thu, 26 Jul 2007 22:37:35 GMT
2007/07/26 15:36:35| entry->timestamp: Thu, 26 Jul 2007 22:36:35 GMT
1185489395.994 SWAPOUT 00 00081DFD 741C0A705149FFD54F8CE6B6B4486D77
200 1185489396 1185383126 1185489396 image/jpeg 42492/42492 GET
http://host/abc/directorytest/c/i-1.JPG?
2007/07/26 15:36:38| ctx: exit level 0 <--- shows the 3 second delay

More Squid debug (different times) 3 second delay at end
-------------------------------------------------
2007/07/26 15:06:54| fwdStateFree: 0x85b9388
2007/07/26 15:06:54| fwdStart:
'http://host/abc/directorytest/c/i-1.JPG?rand=279660'
2007/07/26 15:06:54| fwdStartComplete:
http://host/abc/directorytest/c/i-1.JPG?rand=279660
2007/07/26 15:06:54| fwdConnectStart:
http://host/abc/directorytest/c/i-1.JPG?rand=279660
2007/07/26 15:06:54| fwdConnectStart: got addr 0.0.0.0, tos 0
2007/07/26 15:07:03| fwdConnectDone: FD 17:
'http://host/abc/directorytest/c/i-1.JPG?rand=279660'
2007/07/26 15:07:03| fwdDispatch: FD 16: Fetching 'GET
http://host/abc/directorytest/c/i-1.JPG?rand=279660'
2007/07/26 15:07:03| fwdComplete:
http://hostabc/directorytest/c/i-1.JPG?rand=279660
        status 200
2007/07/26 15:07:03| fwdReforward:
http://hostabc/directorytest/c/i-1.JPG?rand=279660?
2007/07/26 15:07:03| fwdReforward: No, ENTRY_FWD_HDR_WAIT isn't set
2007/07/26 15:07:03| fwdComplete: not re-forwarding status 200
1185487623.236 SWAPOUT 00 0008077B 8AB49FB3B897FB721E06A8ED91EE1AF 200
1185487623 1185383126 1185487623 image/jpeg 42492/42492 GET
http://host/abc/directorytest/c/i-1.JPG?
2007/07/26 15:07:03| fwdServerClosed: FD 17
http://host/abc/directorytest/c/i-1.JPG?rand=279660
Received on Fri Jul 27 2007 - 10:33:57 MDT

This archive was generated by hypermail pre-2.1.9 : Wed Aug 01 2007 - 12:00:04 MDT