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