Re: [squid-users] Re: Re: why RELEASE?

> On Thu, 2009-04-02 at 11:35 +1200, Amos Jeffries wrote:
>>
>> IIRC, non-cachable objects larger than max_object_size_in_memory get a
>> disk object saved for the transition buffer then released when completed
>> whether they need it or not. One of the inefficiencies we are working
>> towards killing.
>
> OK. But that doesn't explain these ones does it?
>
> 1239123733.599 RELEASE 00 00002503 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239123131 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239123733.600 SWAPOUT 00 00002548 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239123736 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239124338.647 RELEASE 00 00002548 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239123736 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239124338.649 SWAPOUT 00 000025D5 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239124341 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239124944.128 RELEASE 00 000025D5 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239124341 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239124944.130 SWAPOUT 00 0000261E C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239124946 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239125550.777 RELEASE 00 0000261E C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239124946 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239125550.777 SWAPOUT 00 00002660 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239125553 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239126156.245 RELEASE 00 00002660 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239125553 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239126156.247 SWAPOUT 00 000026D1 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239126158 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239126762.193 RELEASE 00 000026D1 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239126158 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239126762.193 SWAPOUT 00 0000273B C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239126764 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239127368.419 RELEASE 00 0000273B C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239126764 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239127368.419 SWAPOUT 00 000027BF C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239127370 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239127976.513 RELEASE 00 000027BF C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239127370 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239127976.515 SWAPOUT 00 00002827 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239127978 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239128584.002 RELEASE 00 00002827 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239127978 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239128584.002 SWAPOUT 00 00002A59 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239128586 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239129189.138 RELEASE 00 00002A59 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239128586 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239129189.138 SWAPOUT 00 00002A97 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239129191 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239129793.280 RELEASE 00 00002A97 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239129191 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239129793.282 SWAPOUT 00 00002AD4 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239129795 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239130397.185 RELEASE 00 00002AD4 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239129795 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> 1239130397.370 SWAPOUT 00 00003011 C11C22024C6BFA7AB028CE37E26CADBD 200
> 1239130399 1234617780 -1 image/gif 1366/1366 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
>
> Really, why should that object ever get RELEASEd?
>
> Here's the header from a fetch of it:
>
> HTTP/1.0 200 OK
> Date: Tue, 07 Apr 2009 18:53:19 GMT
> Server: Apache/2
> Last-Modified: Sat, 14 Feb 2009 13:23:00 GMT
> ETag: "1b88337-556-462e0da35d500"
> Accept-Ranges: bytes
> Content-Length: 1366
> Content-Type: image/gif
> Age: 197
> X-Cache: HIT from linux
> X-Cache-Lookup: HIT from linux:3128
> Via: 1.0 linux (squid/3.0.STABLE10)
> Proxy-Connection: keep-alive
>
> Certainly in this case, it was a cache hit, a memory hit in fact:
>
> 1239130594.149 2 10.75.22.1 TCP_MEM_HIT/200 1729 GET
> http://www.example.org/forum/images/styles/soness/style/footer_top.gif
> brian NONE/- image/gif
>
> Any ideas?

1239130594.149 is a time outside the above trace of SWAPOUT->RELEASE
patterns so i can't tell if that request had a matching RELEASE. Could be
that earlier copies were requested with must-revalidate or no-cache
requests or were testing for If-matches on different ETags.

Certainly Age: 197 says the object was generated new at 1239130397.*
which matches the time of last RELEASE/SWAPOUT in the trace.

I would hazard a guess that those images are in fact being passed through
a dynamic script that outputs their binary data and mangles the headers
somehow between requests. Check the request + reply set of headers on two
or three sequential RELEASE timestamps.

Amos
Received on Wed Apr 08 2009 - 01:56:32 MDT