Unexplained Cache MISSes
Nigel Peck
np.lists at sharphosting.uk
Thu May 25 01:59:39 CEST 2017
I've been looking at this some more, and it seems the problem is the
same as it was before. The PURGE does not seem to work immediately. The
restarted request gets a HIT, then the next request gets a MISS and
after that the HITs start again. Here's a sequence from varnishlog showing:
- the PURGE,
- the restart,
- the MISS,
- the HIT
Again this is a full output for everything in the log on that URL. Names
and IP addresses have been changed.
Thanks
Nigel
* << Request >> 266604
- Begin req 266603 rxreq
- Timestamp Start: 1495662133.465511 0.000000 0.000000
- Timestamp Req: 1495662133.465511 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod PURGE
- ReqURL /example/url
- 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: xxx.xxx.xxx.xx2
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_acl MATCH purgers "xxx.xxx.xxx.xx2"
- VCL_return purge
- VCL_call HASH
- VCL_return lookup
- VCL_call PURGE
- ReqMethod GET
- VCL_return restart
- Timestamp Restart: 1495662133.465563 0.000052 0.000052
- Link req 266605 restart
- End
* << Request >> 266605
- Begin req 266604 restart
- Timestamp Start: 1495662133.465563 0.000052 0.000000
- ReqStart xxx.xxx.xxx.xx2 57250
- ReqMethod GET
- ReqURL /example/url
- 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: xxx.xxx.xxx.xx2
- ReqHeader X-Processed-By: Melian
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 132102
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 02:37:14 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 02:37:15 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 266605 132102
- RespHeader Age: 68698
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 68698
- RespHeader Age: 0
- RespHeader X-Cache: HIT (7)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 266605 132102
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495662133.465618 0.000107 0.000055
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 7493
- Debug "RES_MODE 2"
- RespHeader Connection: close
- Timestamp Resp: 1495662133.465660 0.000149 0.000042
- ReqAcct 225 0 225 396 7493 7889
- End
* << Request >> 3017
- Begin req 3016 rxreq
- Timestamp Start: 1495664394.000921 0.000000 0.000000
- Timestamp Req: 1495664394.000921 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx3 45771
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 15:16:04 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx3
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 3018 fetch
- Timestamp Fetch: 1495664394.381188 0.380267 0.380267
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 3017
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Cache: MISS
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 3017
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495664394.381214 0.380294 0.000026
- RespHeader Accept-Ranges: bytes
- RespHeader Transfer-Encoding: chunked
- Debug "RES_MODE 8"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495664394.396562 0.395641 0.015347
- ReqAcct 409 0 409 404 7493 7897
- End
* << Request >> 35821
- Begin req 35820 rxreq
- Timestamp Start: 1495668065.207785 0.000000 0.000000
- Timestamp Req: 1495668065.207785 0.000000 0.000000
- ReqStart xxx.xxx.xxx.xx1 33904
- ReqMethod GET
- ReqURL /example/url
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.example.com
- ReqHeader Connection: Keep-alive
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader From: googlebot(at)googlebot.com
- ReqHeader User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1;
+http://www.google.com/bot.html)
- ReqHeader Accept-Encoding: gzip,deflate,br
- ReqHeader If-Modified-Since: Wed, 24 May 2017 22:19:54 GMT
- ReqHeader X-Forwarded-For: xxx.xxx.xxx.xx1
- VCL_call RECV
- ReqHeader X-Processed-By: Melian
- VCL_return hash
- ReqUnset Accept-Encoding: gzip,deflate,br
- ReqHeader Accept-Encoding: gzip
- VCL_call HASH
- VCL_return lookup
- Hit 3018
- VCL_call HIT
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Server: Apache/2
- RespHeader P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM"
- RespHeader Last-Modified: Wed, 24 May 2017 22:19:54 GMT
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader X-Host: www.example.com
- RespHeader X-URL: /example/url
- RespHeader Cache-Control: max-age=3600
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 35821 3018
- RespHeader Age: 3670
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespUnset Age: 3670
- RespHeader Age: 0
- RespHeader X-Cache: HIT (1)
- RespUnset X-Host: www.example.com
- RespUnset X-URL: /example/url
- RespUnset X-Varnish: 35821 3018
- RespUnset Via: 1.1 varnish-v4
- RespHeader Via: Varnish
- VCL_return deliver
- Timestamp Process: 1495668065.207927 0.000142 0.000142
- RespProtocol HTTP/1.1
- RespStatus 304
- RespReason Not Modified
- RespReason Not Modified
- Debug "RES_MODE 0"
- RespHeader Connection: keep-alive
- Timestamp Resp: 1495668065.208002 0.000217 0.000075
- ReqAcct 409 0 409 367 0 367
- End
On 23/05/2017 17:58, Nigel Peck wrote:
>
> 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
>
> --
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
More information about the varnish-misc
mailing list