On 15/03/2013 6:59 a.m., Jon Schneider wrote:
I have setup squid 3.2.7 in a test environment in preparation to roll it out to
production, however I have noticed a difference in caching behavior that I have
as of yet been unable to resolve. The squid config files are almost identical
with the exception of two config lines that are now obsolete in 3.2. The
refresh patterns and ACL's are all exactly the same.
After some testing it appears that the 3.2 instance is only caching images,
virtually everything else results in a miss. In the 3.1 instance almost
everything returns as a hit with very few misses. When going through the list
of everything that is a miss in the 3.2 instance that is a hit in the 3.1
instance it all seems to be either dynamic or possibly dynamic content.
Virtually anything that does or could have a '?' at the end does not seem to
get cached in 3.2. This results in page times of about twice as log with the
3.2 instance.
That "or could have a ?" is a big clue #1 that '?' is *not* involved.
Current refresh patterns look like this:
refresh_pattern \.(css|gif|ico|jpg|jpeg|js|swf|xsl|xslt) 5 20% 4320
reload-into-ims
#refresh_pattern .(\?.*)?$ 4320 20% 4320 reload-into-ims
refresh_pattern \.(axd|cssx|svg|swfx|img) 0 100% 4320 reload-into-ims
refresh_pattern . 0 20% 4320 reload-into-ims
Notice the maximum Age time in all these heuristics is 4320 minutes.
I have tried almost everything is it simply refuses to cache the same content
as 3.1 is caching.
I am using siege to do the testing, here is an example output of the header
information, first one is from the 3.2 server, second is from the 3.1 server:
[root@test squid_test]# siege -b -r 1 -c 1 -g
http://testsite.domain.com/Shared/Util/CookieUtils.js?__v=1363031409
GET /Shared/Util/CookieUtils.js?__v=1363031409 HTTP/1.0
Host: testsite.domain.com
Accept: */*
Accept-Encoding: *
User-Agent: JoeDog/1.00 [en] (X11; I; Siege 2.72)
Connection: close
HTTP/1.1 200 OK
Cache-Control: max-age=604800
Last-Modified: Thu, 05 May 2005 20:51:40 GMT
Date: Tue, 12 Mar 2013 22:49:23 GMT
The above is a big clue #2 that 3.2 is operating correctly.
Squid is not permitted to store the object more than 604800 seconds (7
days) past its creation date of 5 May 2005.
This is effectively the same as sending the header: Expires: Thu, 12
May 2005 20:51:40 GMT
Content-Length: 608
X-Cache: MISS from cache1.domain.com
X-Cache-Lookup: MISS from cache1.domain.com:80
Connection: close
[root@test squid_test]# siege -b -r 1 -c 1 -g
http://testsite.domain.com/Shared/Util/CookieUtils.js?__v=1363031409
GET /Shared/Util/CookieUtils.js?__v=1363031409 HTTP/1.0
Host: testsite.domain.com
Accept: */*
Accept-Encoding: *
User-Agent: JoeDog/1.00 [en] (X11; I; Siege 2.72)
Connection: close
Something is a bit screwed up with the HIT that 3.1 was presenting. The
big difference is the Age: header existing in this response.
HTTP/1.0 200 OK
Cache-Control: max-age=604800
Last-Modified: Thu, 05 May 2005 20:51:40 GMT
... same storage expiry calculation as above.
Date: Tue, 12 Mar 2013 19:48:17 GMT
Age: 10897
... but somehow Squid has the object as being only 10897 seconds old in
2013.
Last-Modified plus Age seconds ==> current Date should be "Thu, 05
May 2005, 23:53:17 GMT"
which is definitely *not* the current testing Date in 2013.
X-Cache: HIT from cache2.domain.com
X-Cache-Lookup: HIT from cache2.domain.com:80
Connection: close
Age of 10897 < max-age of 604800 produes a HIT (wrongly).
NOTE: it is not clear how that Age is getting in there. Whether it is
being generated by Squid or IIS, using what server headers? but
apparently some header values which are not being sent out to the client
properly are involved.
I have enabled the debug options in the squid.conf and nothing is cache log
explains why the objects are not being cached.
Squid access log:
Squid 3.2:
2013-03-14 16:10:12 172.18.12.20 GET
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409 origin.portal.domain.com
HTTP/1.0 "JoeDog/1.00 [en] (X11; I; Siege 2.72)" "Domain.SqlXml.LastUpdate=0" -
200 1491 29 - TCP_MISS:ROUNDROBIN_PARENT
Squid 3.1:
2013-03-14 16:42:36 172.18.12.20 GET
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409 - HTTP/1.0 "JoeDog/1.00
[en] (X11; I; Siege 2.72)" "cTestCookie=1" - 200 1332 0 - TCP_HIT:NONE
Cache.log from 3.2 server:
2013/03/14 10:10:12.328 kid1| store_io.cc(33) storeCreate: storeCreate:
Selected dir 0 for -1@-1=0/2/1/1
2013/03/14 10:10:12.328 kid1| client_side.cc(764) swanSong:
local=192.168.5.183:80 remote=172.18.12.20:59204 flags=1
2013/03/14 10:10:12.329 kid1| TcpAcceptor.cc(190) doAccept: New connection on
FD 12
2013/03/14 10:10:12.329 kid1| TcpAcceptor.cc(265) acceptNext: connection on
local=192.168.5.183:80 remote=[::] FD 12 flags=9
2013/03/14 10:10:12.329 kid1| client_side.cc(2298) parseHttpRequest: HTTP
Client local=192.168.5.183:80 remote=172.18.12.20:59205 FD 11 flags=1
2013/03/14 10:10:12.329 kid1| client_side.cc(2299) parseHttpRequest: HTTP
Client REQUEST:
---------
GET /Content/js/SocialShare.js?__v=1363031409 HTTP/1.0^M
Host: testsite.domain.com^M
Cookie: Domain.SqlXml.LastUpdate=0^M
Accept: */*^M
Accept-Encoding: *^M
User-Agent: JoeDog/1.00 [en] (X11; I; Siege 2.72)^M
Connection: close^M
^M
----------
2013/03/14 10:10:12.330 kid1| client_side_request.cc(760)
clientAccessCheckDone: The request GET
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409 is 1,
because it matched 'all'
2013/03/14 10:10:12.330 kid1| client_side_request.cc(734) clientAccessCheck2:
No adapted_http_access configuration. default: ALLOW
2013/03/14 10:10:12.330 kid1| client_side_request.cc(760)
clientAccessCheckDone: The request GET
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409 is 1,
because it matched 'all'
2013/03/14 10:10:12.330 kid1| forward.cc(103) FwdState: Forwarding client
request local=192.168.5.183:80 remote=172.18.12.20:59205 FD 11 flags=1,
url=http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409
2013/03/14 10:10:12.330 kid1| peer_select.cc(271) peerSelectDnsPaths: Find IP
destination for:
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409' via
origin.portal.domain.com
2013/03/14 10:10:12.330 kid1| peer_select.cc(271) peerSelectDnsPaths: Find IP
destination for:
http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409' via
origin.portal.domain.com
2013/03/14 10:10:12.330 kid1| peer_select.cc(298) peerSelectDnsPaths: Found
sources for
'http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409'
2013/03/14 10:10:12.330 kid1| peer_select.cc(299) peerSelectDnsPaths:
always_direct = 0
2013/03/14 10:10:12.330 kid1| peer_select.cc(300) peerSelectDnsPaths:
never_direct = 0
2013/03/14 10:10:12.330 kid1| peer_select.cc(309) peerSelectDnsPaths:
cache_peer = local=0.0.0.0 remote=192.168.5.20:80 flags=1
2013/03/14 10:10:12.330 kid1| peer_select.cc(309) peerSelectDnsPaths:
cache_peer = local=0.0.0.0 remote=192.168.5.20:80 flags=1
2013/03/14 10:10:12.330 kid1| peer_select.cc(311) peerSelectDnsPaths:
timedout = 0
2013/03/14 10:10:12.330 kid1| http.cc(2177) sendRequest: HTTP Server
local=192.168.5.183:51057 remote=192.168.5.20:80 FD 32 flags=1
2013/03/14 10:10:12.330 kid1| http.cc(2178) sendRequest: HTTP Server REQUEST:
---------
GET /Content/js/SocialShare.js?__v=1363031409 HTTP/1.1^M
Host: testsite.domain.com^M
Cookie: Domain.SqlXml.LastUpdate=0^M
Accept: */*^M
Accept-Encoding: *^M
User-Agent: JoeDog/1.00 [en] (X11; I; Siege 2.72)^M
Surrogate-Capability: cache1.domain.com="Surrogate/1.0 ESI/1.0"^M
X-Forwarded-For: 172.18.12.20^M
Cache-Control: max-age=259200^M
Um. 259200 seconds == 4320 minutes. Which is the refresh_pattern maximum
age value.
Asside:
I think there is a minor bug here in that the max-age added by Squid
should really either be absent (nothing cached), or 604800 (from last
server response max-age value).
It is not relevant to your problem though, at worst this would make a
parent cache MISS.
Connection: keep-alive^M
^M
----------
2013/03/14 10:10:12.358 kid1| ctx: enter level 0:
'http://testsite.domain.com/Content/js/SocialShare.js?__v=1363031409'
2013/03/14 10:10:12.358 kid1| http.cc(732) processReplyHeader: HTTP Server
local=192.168.5.183:51057 remote=192.168.5.20:80 FD 32 flags=1
2013/03/14 10:10:12.358 kid1| http.cc(733) processReplyHeader: HTTP Server
REPLY:
---------
HTTP/1.1 200 OK^M
Cache-Control: max-age=604800^M
Again the "don't store more than 7 days from last modification" instruction.
Content-Type: application/x-javascript^M
Content-Encoding: gzip^M
Last-Modified: Fri, 28 Dec 2012 15:00:37 GMT^M
modification + 7 days ==> Expires: 5 Jan 2013 ...
Amos