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_at_-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
Received on Thu Mar 14 2013 - 21:48:43 MDT
This archive was generated by hypermail 2.2.0 : Fri Mar 15 2013 - 12:00:05 MDT