[squid-users] Dynamic content caching in Squid 3.2 vs 3.1

From: Jon Schneider <Jon.Schneider_at_Yardi.Com>
Date: Thu, 14 Mar 2013 17:59:02 +0000

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.

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

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
Content-Type: application/x-javascript
Content-Encoding: gzip
Last-Modified: Thu, 05 May 2005 20:51:40 GMT
Accept-Ranges: bytes
ETag: "80d6863cb451c51:0"
Vary: Accept-Encoding
Server: Microsoft-IIS/7.5
X-Server: IISSVR2
X-Powered-By: ASP.NET
Date: Tue, 12 Mar 2013 22:49:23 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

HTTP/1.0 200 OK
Cache-Control: max-age=604800
Content-Type: application/x-javascript
Content-Encoding: gzip
Last-Modified: Thu, 05 May 2005 20:51:40 GMT
Accept-Ranges: bytes
ETag: "80d6863cb451c51:0"
Vary: Accept-Encoding
Server: Microsoft-IIS/7.5
X-Server: IISSVR2
X-Powered-By: ASP.NET
Date: Tue, 12 Mar 2013 19:48:17 GMT
Content-Length: 608
Age: 10897
X-Cache: HIT from cache2.domain.com
X-Cache-Lookup: HIT from cache2.domain.com:80
Connection: close

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
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
Content-Type: application/x-javascript^M
Content-Encoding: gzip^M
Last-Modified: Fri, 28 Dec 2012 15:00:37 GMT^M
Accept-Ranges: bytes^M
ETag: "709ea918ce5cd1:0"^M
Vary: Accept-Encoding^M
Server: Microsoft-IIS/7.5^M
X-Server: IISSVR2^M
X-Powered-By: ASP.NET^M
Date: Thu, 14 Mar 2013 16:10:12 GMT^M
Content-Length: 1020^M

Any help is greatly appreciated

Thanks,
Jon
Received on Thu Mar 14 2013 - 17:59:09 MDT

This archive was generated by hypermail 2.2.0 : Fri Mar 15 2013 - 12:00:05 MDT