Re: [squid-users] squid 3.2 cache mechanism - not working properly compare to 3.1 series

From: Amos Jeffries <squid3_at_treenet.co.nz>
Date: Fri, 26 Oct 2012 00:21:03 +1300

On 25/10/2012 11:21 p.m., Ben wrote:
> On 25-10-2012 14:49, Amos Jeffries wrote:
>> On 25/10/2012 7:24 p.m., Ben wrote:
>>>
>>> Hi,
>>>
>>> I upgraded my squid boxes from 3.1 series to 3.2 series. I noticed
>>> that 3.2 is not better then 3.1 while concerning with caching
>>> capabilities.
>>>
>>> I checked for simple web site , which has jpg images and all. as web
>>> site is standard and normal site. So squid must cache it contents. I
>>> tried many times, but each time i saw TCP_MISS in access.log
>>>
>>> I checked for a site which is elitecore.com ( as example )
>>>
>>> redbot url: http://redbot.org/?descend=True&uri=http://elitecore.com -
>>> it suggests that this site is cacheable.
>>>
>>> squid version : 3.2.3
>>>
>>> currently, there is no change in squid.conf. I am using default one
>>> for testing purposes.
>>>
>>>
>>> what could be problem with squid-3.2.3? Is there any changes required
>>> for 3.2.3 configuration or any changes in caching mechanism for 3.2
>>> series?
>>
>> Firstly, TCP_MISS does *not* mean anything about whether the response to
>> a previous request or to the curent request was cached. All it means is
>> the current request was not serviced by anything already existing in
>> cache.
>>
>> Both the client request headers AND the cached response headers are
>> taken into account when deciding whether a response can be served from
>> cache. It is perfectly reasonable to get a log trace like this from a
>> client requesting brand new object and rejecting anything that might be
>> stale (max-age=0).
>>
>> Since the site uses User-Agent in its Vary: header it is perfectly
>> possible that each client request has a different agent string and
>> MISS'es the previously cached entry. Even one byte of change in the
>> agent string will cause those objects to MISS.
>> But since you said 3.1 was working okay it is probably not this issue
>> which affects all caches.
>
> For testing purpose, I open same site from same browser and again run
> same process to check caching is happening or not.
>
>>
>>
>> For more info on what 3.2.3 is caching you can log at debug level 11,3
>> and get log about each response and whether it was determined cacheable.
>> Look for "cacheableReply" and a YES/NO with explained reason.
>
>
> I enabled debug_options 11,3. It shows request/response header with
> meaningfull information but I could not find "cacheableReply",
> mentioning one block of request/response from log as per 11,3 debug
> level.
>
>
> ---------
> GET http://elitecore.com/images/body_bkgd.jpg HTTP/1.1^M
> Host: elitecore.com^M
> User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0)
> Gecko/20100101 Firefox/15.0.1^M
> Accept: image/png,image/*;q=0.8,*/*;q=0.5^M
> Accept-Language: en-us,en;q=0.5^M
> Accept-Encoding: gzip, deflate^M
> Proxy-Connection: keep-alive^M
> Referer: http://elitecore.com/css/stylesheet.css^M
> Cookie: __utma=25544809.1437989579.1351159439.1351159439.1351159439.1;
> __utmb=25544809.4.10.1351159439; __utmc=25544809;
> __utmz=25544809.1351159439.1
> .1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)^M
> If-Modified-Since: Thu, 24 Sep 2009 06:16:20 GMT^M
> If-None-Match: "4005f-56a5-4744cc51a1500"^M
> Cache-Control: max-age=0^M
> ^M
>
> ----------
> 2012/10/25 15:45:32.794 kid1| httpStart: "GET
> http://elitecore.com/images/body_bkgd.jpg"
> 2012/10/25 15:45:32.794 kid1| HTTP Server local=10.115.1.230:30562
> remote=180.179.100.102:80 FD 35 flags=1
> 2012/10/25 15:45:32.794 kid1| HTTP Server REQUEST:
> ---------
> GET /images/body_bkgd.jpg HTTP/1.1^M
> Host: elitecore.com^M
> User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0)
> Gecko/20100101 Firefox/15.0.1^M
> Accept: image/png,image/*;q=0.8,*/*;q=0.5^M
> Accept-Language: en-us,en;q=0.5^M
> Accept-Encoding: gzip, deflate^M
> Referer: http://elitecore.com/css/stylesheet.css^M
> Cookie: __utma=25544809.1437989579.1351159439.1351159439.1351159439.1;
> __utmb=25544809.4.10.1351159439; __utmc=25544809;
> __utmz=25544809.1351159439.1
> .1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)^M
> If-Modified-Since: Thu, 24 Sep 2009 06:16:20 GMT^M
> If-None-Match: "4005f-56a5-4744cc51a1500"^M
> Via: 1.1 ns1.example.com (squid/3.2.3)^M
> X-Forwarded-For: 10.115.1.16^M
> Cache-Control: max-age=0^M
> Connection: keep-alive^M
>
> As per my understanding, In request header,I can see Cache-Control:
> max-age=0 , so i add override-expire options with refresh_pattern to
> cross this header parameters but still same.

No. override-expire just overrides Expires: header. ignore-reload
overrides max-age=0.

However; max-age=0 is a quirk you are more likely to hit in testing
than in real traffic. If you force-refresh the browser adds it in order
to ensure up to date content. During regular browsing the modern
browsers mostly do NOT add it by default.
  If you will notice the request has If-None-Match and If-Modified-Since
headers. So even with the force-refresh the client may get cached
content provided the server replies 304 unmodified.

What I noticed while checking with redbot was that the Server: and ETag:
headers that site was emitting were bouncing all over the place.
Multiple Server: strings and each one emittinng different set of ETag
for the same objects. The response ETag was flapping backwards and
forwards on a series of repeated identical requests.

I expect the If-None-Match conditional was being recieved by the server
with *other* Etag set. Causing it to send out new ETag response for the
client (and cache replacement) instead of permitting a HIT to happen. I
will need to see the response headers from server and to client to say
more about what is happening about its caching.

The cacheableReply check should be shortly after the server response
headers. Might just have a verdict "YES because ..." "NO because ...".

>
> refresh_pattern is for response header ? or for both request/response?
> I added refresh_pattern,
>
> refresh_pattern -i \.(jpg|jpeg)$ 1440 40% 14400 override-expire
> for testing purpose .
>
> How to cache such site's contents?

It *is* being cached. The If-* headers would not be added by Squids
outbound request if there were no cached copy to be revalidated.

There seems to have been a change in how TCP_MISS and TCP_REFRESH_MISS
are determined for logging. I think the latter is what should have been
logged for at least the request headers above.

Amos
Received on Thu Oct 25 2012 - 11:21:15 MDT

This archive was generated by hypermail 2.2.0 : Thu Oct 25 2012 - 12:00:04 MDT