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
