Unexplained Cache MISSes
Nigel Peck
np.lists at sharphosting.uk
Wed May 24 00:58:31 CEST 2017
Hi,
I have an issue where some requests are not getting served from the
cache when they should be. "should be" as in it's my intention they
should be, and not sure what's going wrong to cause them not to be. I
had some discussion about this issue before, when I was on 4.0.4, and
the suggestion was to upgrade, which I've now done and am on 4.1.6.
Below is a full varnishlog report for an image URL. My VCL sets a week
TTL on every backend response that is going to be stored, and is then
kept up to date with PURGEs from a script when needed or every four days
otherwise, so everything that can be cached should be coming out of the
cache at all times. The first two entries below are the PURGE/restart
and then the subsequent entry a MISS. There are no other entries, this
is a complete report from:
sudo varnishlog -d -q 'ReqURL eq "/example/image/URI/image.jpg"'
Names have been changed to protect the guilty. Nothing has been
lru_nuked at all, there is no entry for it in varnishstat.
There is an "Age" header on the restarted response after the purge,
which seems strange. I can't see a "TTL" record on the restarted
response either.
All insights greatly appreciated. Please let me know if any further info
needed.
Nigel
--
* << Request >> 230779
- Begin req 230778 rxreq
- Timestamp Start: 1495505749.920337 0.000000 0.000000
- Timestamp Req: 1495505749.920337 0.000000 0.000000
- ReqStart 192.168.0.1 33530
- ReqMethod PURGE
- ReqURL /example/image/URI/image.jpg
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: 192.168.0.1
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_acl MATCH purgers "192.168.0.1"
- VCL_return purge
- VCL_call HASH
- VCL_return lookup
- VCL_call PURGE
- ReqMethod GET
- VCL_return restart
- Timestamp Restart: 1495505749.920445 0.000108 0.000108
- Link req 230780 restart
- End
* << Request >> 230780
- Begin req 230779 restart
- Timestamp Start: 1495505749.920445 0.000108 0.000000
- ReqStart 192.168.0.1 33530
- ReqMethod GET
- ReqURL /example/image/URI/image.jpg
- ReqProtocol HTTP/1.1
- ReqHeader TE: deflate,gzip;q=0.3
- ReqHeader Connection: TE, close
- ReqHeader Accept-Encoding: gzip
- ReqHeader Host: www.example.com
- ReqHeader User-Agent: SuperDuperApps-Cache-Purger/0.1
- ReqHeader X-Forwarded-For: 192.168.0.1
- ReqHeader X-Processed-By: Melian
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 168785
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Mon, 22 May 2017 18:41:37 GMT
- RespHeader Server: Apache/2
- RespHeader Last-Modified: Thu, 02 Mar 2017 02:22:25 GMT
- RespHeader ETag: "1e40-549b6198b7a40"
- RespHeader Content-Length: 7744
- RespHeader Content-Type: image/jpeg
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/image/URI/image.jpg
- RespHeader Cache-Control: max-age=3600
- RespHeader X-Varnish: 230780 168785
- RespHeader Age: 27252
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 27252
- RespHeader Age: 0
- RespHeader X-Cache: HIT (1)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/image/URI/image.jpg
- RespUnset X-Varnish: 230780 168785
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495505749.920481 0.000144 0.000036
- RespHeader Accept-Ranges: bytes
- Debug "RES_MODE 2"
- RespHeader Connection: close
- Timestamp Resp: 1495505749.920542 0.000204 0.000060
- ReqAcct 227 0 227 306 7744 8050
- End
* << Request >> 2031637
- Begin req 131739 rxreq
- Timestamp Start: 1495573815.866983 0.000000 0.000000
- Timestamp Req: 1495573815.866983 0.000000 0.000000
- ReqStart 86.153.27.10 48595
- ReqMethod GET
- ReqURL /example/image/URI/image.jpg
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: keep-alive
- ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 6.0.1;
SAMSUNG SM-G900F Build/MMB29M) AppleWebKit/537.36 (KHTML, like Gecko)
SamsungBrowser/5.4 Chrome/51.0.2704.106 Mobile Safari/537.36
- ReqHeader Accept: image/webp,image/*,*/*;q=0.8
- ReqHeader Referer: http://www.example.com/jcb-parts-catalogue
- ReqHeader Accept-Encoding: gzip, deflate
- ReqHeader Accept-Language: en-GB,en-US,en
- ReqHeader Cookie: _gat=1;
hgkjb432k5vb4k35vb4k35n32vbmn423=bjjb423jbr2bkj234bjk324bkj;
PRODUCT_BROWSING_FEATURES_USED=1; _ga=GA1.2.1234567890.1234567890;
_gid=GA1.2.1234567890.1234567890
- ReqHeader X-Forwarded-For: 86.153.27.10
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- ReqUnset Cookie: _gat=1;
hgkjb432k5vb4k35vb4k35n32vbmn423=bjjb423jbr2bkj234bjk324bkj;
PRODUCT_BROWSING_FEATURES_USED=1; _ga=GA1.2.1234567890.1234567890;
_gid=GA1.2.1234567890.1234567890
- VCL_return hash
- ReqUnset Accept-Encoding: gzip, deflate
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 2031638 fetch
- Timestamp Fetch: 1495573815.869083 0.002100 0.002100
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Tue, 23 May 2017 21:10:15 GMT
- RespHeader Server: Apache/2
- RespHeader Last-Modified: Thu, 02 Mar 2017 02:22:25 GMT
- RespHeader ETag: "1e40-549b6198b7a40"
- RespHeader Content-Length: 7744
- RespHeader Content-Type: image/jpeg
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/image/URI/image.jpg
- RespHeader Cache-Control: max-age=3600
- RespHeader X-Varnish: 2031637
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 0
- RespHeader Age: 0
- RespHeader X-Cache: MISS
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/image/URI/image.jpg
- RespUnset X-Varnish: 2031637
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495573815.869164 0.002180 0.000080
- RespHeader Accept-Ranges: bytes
- Debug "RES_MODE 2"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495573815.869250 0.002266 0.000086
- ReqAcct 655 0 655 308 7744 8052
- End
--
More information about the varnish-misc
mailing list