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