Re: [squid-users] Explaining RELEASEs

On Fri, Apr 15, 2011 at 9:04 PM, Amos Jeffries <squid3_at_treenet.co.nz> wrote:
> On 16/04/11 14:12, Yang Zhang wrote:
>>
>> We're seeing a bunch of the following pairs of RELEASE/SWAPOUT lines
>> for the same URL in our store.log.  Can anyone help me understand
>> what's happening here?
>>
>> 1302893424.155 RELEASE 00 000830A0 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893423        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>> 1302893424.155 SWAPOUT 00 000830A2 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893424        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>
> Cached http://foo.com/alpha is being replaced with a new copy.
>
>> 1302893424.332 RELEASE 00 000830A4 28E57991079BA357DCD9AA6C8D435A57
>> 200 1302893424        -1        -1 application/json 2057/2057 GET
>> http://foo.com/beta
>> 1302893424.333 SWAPOUT 00 000830A6 28E57991079BA357DCD9AA6C8D435A57
>> 200 1302893424        -1        -1 application/json 2057/2057 GET
>> http://foo.com/beta
>
> Cached http://foo.com/beta is being replaced with a new copy.
>
>>
>> Our squid.conf should aggressively cache everything forever, since
>> we're using squid as an application cache against remote web services:
>>
>>   # Increased disk cache size to 5GB; currently consuming 2.8GB
>>   cache_dir ufs /var/spool/squid3 5000 16 256
>>   ...
>>   # Cache everything, forever
>>   refresh_pattern . 525600 100% 525600 override-expire ignore-private
>> ignore-n
>>
>> So I don't understand why there are RELEASEs happening at all - I
>
> Caching "forever" is simply not possible. The cache items get removed when
> there is no space available for new ones, when they are updated, or when
> they expire.

Sure, but we have space and the refresh_pattern is (unless we made an
error - quite possible to misconfigure) forcing squid to forego
update/expiry checks for a long time.

>
>
>> assume that means .  If I also interleave lines from access.log:
>>
>> 1302893423.974 SWAPOUT 00 000830A0 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893423        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>> 1302893423.975    255 10.160.227.224 TCP_MISS/200 2372 GET
>> http://foo.com/alpha - DIRECT/173.223.232.122 application/json
>> ...
>> 1302893424.155 RELEASE 00 000830A0 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893423        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>> 1302893424.155 SWAPOUT 00 000830A2 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893424        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>
>> 1302893424.183    466 10.160.227.224 TCP_MISS/200 2372 GET
>> http://foo.com/alpha - DIRECT/173.223.232.122 application/json
>> 1302894993.280      8 10.160.227.224 TCP_MEM_HIT/200 2381 GET
>> http://foo.com/alpha - NONE/- application/json
>> 1302894993.280      8 10.160.227.224 TCP_MEM_HIT/200 2381 GET
>> http://foo.com/alpha - NONE/- application/json
>
> access.log records the time of finish plus the service duration.
> Interleaving has to be done taking the duration into account to find the
> start time...
>
> (access.log #2 started: 1302893424.183 - 0.466)
> 1302893423.717 10.160.227.224 GET http://foo.com/alpha
>
> (access.log #1 started: 1302893423.975 - 0.255)
> 1302893423.750  10.160.227.224 GET http://foo.com/alpha
>
> (access.log #1 finished.
>> 1302893423.974 SWAPOUT 00 000830A0 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893423        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>> 1302893423.975    255 10.160.227.224 TCP_MISS http://foo.com/alpha
>
> NP: new requests will HIT the #1 object.
>
> (access.log #2 finished.)
>> 1302893424.155 RELEASE 00 000830A0 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893423        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>> 1302893424.155 SWAPOUT 00 000830A2 6E5CACCDB20F6654643A090ACC1B995D
>> 200 1302893424        -1        -1 application/json 2058/2058 GET
>> http://foo.com/alpha
>
> NP: new requests will HIT the #2 object.
>
> The MEM_HITs occured much later and HIT the #2 object.
>
>
> Avoiding this overlap during fetch lag requires the "collapsed forwarding"
> feature. (Which nobody has yet ported to Squid-3. Hint.)
>
> Amos
> --
> Please be using
>  Current Stable Squid 2.7.STABLE9 or 3.1.12
>  Beta testers wanted for 3.2.0.6
>

Collapsed forwarding does indeed sound like a valuable waiting
contribution. Your explanation was very helpful - thanks.

-- 
Yang Zhang
http://yz.mit.edu/