Re: [squid-users] Explaining RELEASEs

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.

> 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