Object no cached when TTL expires
Roberto O. Fernández Crisial
roberto.fernandezcrisial at gmail.com
Wed Jan 12 15:34:54 CET 2011
Kristian,
Here is the VCL and varnishstats requested. Unfortunatelly the varnishlog
runs so fast so I can't catch the HIT/MISS logs just for one request.
# VCL
backend be1 {
.host = "X.X.X.X";
}
acl purge {
"localhost";
}
sub vcl_recv {
set req.grace = 60s;
if (req.http.host == "domain.com") {
set req.backend = be1;
}
if (req.request == "PURGE") {
if (!client.ip ~ purge) {
error 405 "Not allowed.";
}
return (lookup);
}
if (req.http.x-forwarded-for) {
set req.http.X-Forwarded-For = req.http.X-Forwarded-For ", "
client.ip;
}
else {
set req.http.X-Forwarded-For = client.ip;
}
if (req.request != "GET" && req.request != "HEAD" && req.request !=
"PUT" && req.request != "POST" && req.request != "TRACE" && req.request !=
"OPTIONS" && req.request != "DELETE") {
return (pipe);
}
if (req.http.Cookie ~ "^\s*$") {
unset req.http.Cookie;
}
if (!req.url~ "\.php\?.*$" && !req.url~ "search" ) {
set req.url = regsub(req.url, "\?.*$", "");
}
if (req.request != "GET" && req.request != "HEAD") {
return (pass);
}
if (req.url ~ "^(files|misc|sites|themes|modules|sfx)/" || req.url ~
"\.(txt|TXT|ico|ICO|css|CSS|png|PNG|jpg|JPG|gif|GIF|swf|SWF|flv|FLV|mp4|MP4|mp3|MP3|js|JS|xml|XML|jpeg|JPEG)$")
{
unset req.http.Cookie;
remove req.http.Referer;
remove req.http.User-Agent;
remove req.http.Accept-Language;
remove req.http.Accept-Charset;
remove req.http.Accept;
remove req.http.Cache-Control;
}
if (req.http.Accept-Encoding) {
if (req.url ~ "\.(jpg|png|gif|gz|tgz|bz2|tbz|mp3|ogg|flv|mp4)$") {
remove req.http.Accept-Encoding;
}
elsif (req.http.Accept-Encoding ~ "gzip") {
set req.http.Accept-Encoding = "gzip";
}
else {
remove req.http.Accept-Encoding;
}
if (req.request == "GET" && req.url ~
"\.(svg|swf|ico|mp3|mp4|m4a|ogg|mov|avi|wmv)$") {
return (lookup);
}
if (req.request == "GET" && req.url ~ "\.(png|gif|jpg|jpeg)$") {
return (lookup);
}
}
return (lookup);
}
sub vcl_pipe {
set bereq.http.connection = "close";
return (pipe);
}
sub vcl_pass {
return (pass);
}
sub vcl_hash {
if (req.http.Cookie) {
set req.hash += req.http.Cookie;
}
set req.hash += req.url;
if (req.http.host) {
set req.hash += req.http.host;
}
else {
set req.hash += server.ip;
}
return (hash);
}
sub vcl_hit {
return (deliver);
}
sub vcl_miss {
return (fetch);
}
sub vcl_fetch {
unset beresp.http.Etag;
if (!beresp.cacheable) {
set beresp.http.X-Cacheable = "NO:Not Cacheable";
}
elsif(req.http.Cookie ~"(UserID|_session)") {
set beresp.http.X-Cacheable = "NO:Got Session";
return (pass);
}
elsif ( beresp.http.Cache-Control ~ "private") {
set beresp.http.X-Cacheable = "NO:Cache-Control=private";
return (pass);
}
elsif ( beresp.ttl < 1s ) {
set beresp.ttl = 5s;
set beresp.grace = 5s;
set beresp.http.X-Cacheable = "YES:FORCED";
}
else {
set beresp.http.X-Cacheable = "YES";
}
if (req.url ~
"\.(jpg|png|gif|gz|tgz|bz2|tbz|mp3|ogg|flv|swf|mp4|mp3|js|xml)$") {
unset beresp.http.set-cookie;
}
if (beresp.http.Set-Cookie) {
return (pass);
}
if (beresp.status == 404 || beresp.status == 503) {
set beresp.ttl = 1s;
}
set beresp.http.X-Cacheable = beresp.ttl;
return (deliver);
}
sub vcl_deliver {
if (obj.hits > 0) {
set resp.http.X-Varnish-Cache = "HIT Varnish (" obj.hits ")";
}
else {
set resp.http.X-Varnish-Cache = "MISS Varnish";
}
return (deliver);
}
sub vcl_error {
set obj.http.Content-Type = "text/html; charset=utf-8";
synthetic {"
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "
http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html>
<head>
<title>"} obj.status " " obj.response {"</title>
</head>
<body>
<h1>Error "} obj.status " " obj.response {"</h1>
<p>"} obj.response {"</p>
<h3>Guru Meditation:</h3>
<p>XID: "} req.xid {"</p>
<hr>
<p>Varnish cache server</p>
</body>
</html>
"};
return (deliver);
}
------
# varnishstats -1
client_conn 9514820 148.86 Client connections accepted
client_drop 0 0.00 Connection dropped, no sess/wrk
client_req 102670372 1606.26 Client requests received
cache_hit 96847567 1515.16 Cache hits
cache_hitpass 5716515 89.43 Cache hits for pass
cache_miss 106255 1.66 Cache misses
backend_conn 321210 5.03 Backend conn. success
backend_unhealthy 0 0.00 Backend conn. not attempted
backend_busy 0 0.00 Backend conn. too many
backend_fail 4889 0.08 Backend conn. failures
backend_reuse 5496709 85.99 Backend conn. reuses
backend_toolate 39922 0.62 Backend conn. was closed
backend_recycle 5536644 86.62 Backend conn. recycles
backend_unused 0 0.00 Backend conn. unused
fetch_head 2267 0.04 Fetch head
fetch_length 3542759 55.43 Fetch with Length
fetch_chunked 6938 0.11 Fetch chunked
fetch_eof 0 0.00 Fetch EOF
fetch_bad 0 0.00 Fetch had bad headers
fetch_close 104849 1.64 Fetch wanted close
fetch_oldhttp 0 0.00 Fetch pre HTTP/1.1 closed
fetch_zero 2161065 33.81 Fetch zero len
fetch_failed 0 0.00 Fetch failed
n_sess_mem 5257 . N struct sess_mem
n_sess 4645 . N struct sess
n_object 105631 . N struct object
n_vampireobject 0 . N unresurrected objects
n_objectcore 106147 . N struct objectcore
n_objecthead 57775 . N struct objecthead
n_smf 0 . N struct smf
n_smf_frag 0 . N small free smf
n_smf_large 0 . N large free smf
n_vbe_conn 8 . N struct vbe_conn
n_wrk 521 . N worker threads
n_wrk_create 8114 0.13 N worker threads created
n_wrk_failed 0 0.00 N worker threads not created
n_wrk_max 1323 0.02 N worker threads limited
n_wrk_queue 0 0.00 N queued work requests
n_wrk_overflow 232093 3.63 N overflowed work requests
n_wrk_drop 0 0.00 N dropped work requests
n_backend 11 . N backends
n_expired 521 . N expired objects
n_lru_nuked 0 . N LRU nuked objects
n_lru_saved 0 . N LRU saved objects
n_lru_moved 1257422 . N LRU moved objects
n_deathrow 0 . N objects on deathrow
losthdr 0 0.00 HTTP header overflows
n_objsendfile 0 0.00 Objects sent with sendfile
n_objwrite 24858882 388.91 Objects sent with write
n_objoverflow 0 0.00 Objects overflowing workspace
s_sess 9513431 148.84 Total Sessions
s_req 102670372 1606.26 Total Requests
s_pipe 27 0.00 Total pipe
s_pass 5716519 89.43 Total pass
s_fetch 5817878 91.02 Total fetch
s_hdrbytes 25797680938 403599.57 Total header bytes
s_bodybytes 274844776909 4299891.69 Total body bytes
sess_closed 1141952 17.87 Session Closed
sess_pipeline 62084 0.97 Session Pipeline
sess_readahead 92195 1.44 Session Read Ahead
sess_linger 102206982 1599.01 Session Linger
sess_herd 84599464 1323.54 Session herd
shm_records 3977250830 62223.30 SHM records
shm_writes 227215458 3554.74 SHM writes
shm_flushes 2 0.00 SHM flushes due to overflow
shm_cont 720671 11.27 SHM MTX contention
shm_cycles 1800 0.03 SHM cycles through buffer
sm_nreq 0 0.00 allocator requests
sm_nobj 0 . outstanding allocations
sm_balloc 0 . bytes allocated
sm_bfree 0 . bytes free
sma_nreq 3759248 58.81 SMA allocator requests
sma_nobj 209942 . SMA outstanding allocations
sma_nbytes 1685800871 . SMA outstanding bytes
sma_balloc 30860533837 . SMA bytes allocated
sma_bfree 29174732966 . SMA bytes free
sms_nreq 4896 0.08 SMS allocator requests
sms_nobj 0 . SMS outstanding allocations
sms_nbytes 0 . SMS outstanding bytes
sms_balloc 2075904 . SMS bytes allocated
sms_bfree 2075904 . SMS bytes freed
backend_req 5817885 91.02 Backend requests made
n_vcl 1 0.00 N vcl total
n_vcl_avail 1 0.00 N vcl available
n_vcl_discard 0 0.00 N vcl discarded
n_purge 1 . N total active purges
n_purge_add 1 0.00 N new purges added
n_purge_retire 0 0.00 N old purges deleted
n_purge_obj_test 0 0.00 N objects tested
n_purge_re_test 0 0.00 N regexps tested against
n_purge_dups 0 0.00 N duplicate purges removed
hcb_nolock 102654743 1606.01 HCB Lookups without lock
hcb_lock 57436 0.90 HCB Lookups with lock
hcb_insert 57436 0.90 HCB Inserts
esi_parse 0 0.00 Objects ESI parsed (unlock)
esi_errors 0 0.00 ESI parse errors (unlock)
accept_fail 1261 0.02 Accept failures
client_drop_late 0 0.00 Connection dropped late
uptime 63919 1.00 Client uptime
Thank you,
Roberto.
2011/1/12 Kristian Lyngstol <kristian at varnish-software.com>
> On Wed, Jan 12, 2011 at 09:44:37AM -0300, Roberto O. Fernández Crisial
> wrote:
> > I expect Varnish request the object from webserver, show HIT and Age
> header
> > increase value.
> >
> > This is the sequence right now:
> >
> > 1) user ask for image
> > 2) varnish receive request
> > 3) varnish ask the webserver
> > 4) varnish cache the object
> > 5) varnish response user request
> > 6) varnish response users requests for 1800s (TTL)
> > 7) when TTL expires varnish should ask again webserver for the object and
> > cache it (but it doesn't)
> > 8) varnish response MISS for the object (Age header always shows value
> "0")
> > and ask webserver for every user request :(
>
> Aha, it sounded like you were complaining that you got a (single) miss
> after the object expired. If you are getting multiple misses, it's a
> different story.
>
> If you attach varnishlog -o output of both the first miss that gets cached,
> a cache hit and the two first miss after it is expired, I'm pretty sure we
> can figure this out.
>
> Oh, and your VCL, and while we're at it, we might as well throw in
> varnishstat -1.
>
> - Kristian
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20110112/177ca6fc/attachment-0003.html>
More information about the varnish-misc
mailing list