Unexplained Cache MISSes
Nigel Peck
np.lists at sharphosting.uk
Thu Jun 1 23:22:02 CEST 2017
On 31/05/2017 18:33, Dridi Boukelmoune wrote:
> There's no ordering guarantee in the varnishlog output, although they
> should likely be ordered since they share the same hash. You'd need to
> check the Timestamp records to get a grasp of chronology.
Thanks, I'll keep that in mind. I looked at a typical set of entries
that I saved. This is not a busy site. All the timestamps are in order.
I've included the full log below, based on a search for the ReqURL.
There is the PURGE and then the restart that gets a HIT. The restart
shows itself as being the 7th hit on that object - X-Cache: HIT (7) - I
can't check the VXID because the PURGE entry doesn't include it[1].
And then the next request, 40 minutes later, gets a MISS. All caching on
this server is for one week. The next request an hour after that gets
HIT(1). So all working properly apart from the restart getting a HIT,
resulting in the next request getting a MISS instead[2].
It seems clear to me that there is some bug causing a delay on the PURGE
going through in some cases (around 10% of purges in my case), so the
restart comes back round before the PURGE has completed. The purge
completes after the restart.
[1] - I'm not sure how I can get the VXID for a purge, since it seems
vcl_purge does not have access to the obj it is going to purge.
Hopefully the obj.hits being more than 1 or 2 in the restarted hit is
evidence enough, and the lack of intervening entries on this non-busy site.
[2] - Very noticeable in my case, because I am using Varnish to ensure
every request is a cache HIT, even for pages that only get viewed once
or twice a week, to improve performance. So I'm monitoring MISSes and
seeing this happening.
> If it's a bug, it might be one of those hard to reproduce...
>
> Amazingly enough I never looked at the logs of a purge, maybe ExpKill
> could give us a VXID to then check against the hit. If only SomeoneElse(tm)
> could spare me the time and look at it themselves and tell us (wink wink=).
I'm very happy to help in any way I can. Please let me know anything I
can do or information I can provide. I'm no C programmer (web
developer/server admin), so can't help out with
coding/patching/debugging[3], but anything else I can do, please let me
know what you need.
Would a cleanly installed server and absolute minimum VCL to reproduce
this be useful? You would be welcome to have access to that server, if
useful, once I've got it set up and producing the same problem.
Nigel
[3] - Assuming it's a bug, which for my part I'm convinced it is at this
point.
* << 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
More information about the varnish-misc
mailing list