[Varnish] #1340: Multiple backend requests per miss
Varnish
varnish-bugs at varnish-cache.org
Mon Sep 9 16:30:20 CEST 2013
#1340: Multiple backend requests per miss
----------------------+-------------------
Reporter: lkarsten | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: build | Version: trunk
Severity: normal | Keywords:
----------------------+-------------------
In master (8f06d0f) varnishd sends multiple requests to the backend when
an object times out.
Expected behaviour: As in 3.0; a single backend request goes out and the
connections are either kept waiting or given a graced version.
default.vcl in use.
Setup: apache2 with mod_expires and max-age=5s, varnish in front of this,
and siege sends requests to a single url.
varnishd startup args:
2013-09-09 16:23:36,985 - fry - INFO - run[fryer1]:
/opt/varnish/sbin/varnishd -T localhost:6082 -a :6081 -f
/opt/varnish/etc/testsuite.vcl -smalloc,20M -p thread_pool_max=3000 -p
thread_pool_min=1000 -P /opt/varnish/var/varnishd.pid
Siege args:
2013-09-09 16:23:41,160 - fry - INFO - run[fryer2]: ulimit -n 65548; siege
-t 30s -c 15 http://fryer1.varnish-
software.com:6081/cacheabledata/set_hot1/index.html
apache2 access log: (first req is initial miss)
{{{
127.0.0.1 - - [09/Sep/2013:16:23:41 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
127.0.0.1 - - [09/Sep/2013:16:23:46 +0200] "GET
/cacheabledata/set_hot1/index.html HTTP/1.1" 200 884 "-" "JoeDog/1.00 [en]
(X11; I; Siege 2.70)"
}}}
Counters after completed siege run (30s):
{{{
LCK.backend.creat 1
LCK.backend.destroy 0
LCK.backend.locks 193
LCK.ban.creat 1
LCK.ban.destroy 0
LCK.ban.locks 65
LCK.busyobj.creat 89
LCK.busyobj.destroy 89
LCK.busyobj.locks 519
LCK.cli.creat 1
LCK.cli.destroy 0
LCK.cli.locks 25
LCK.exp.creat 1
LCK.exp.destroy 0
LCK.exp.locks 37
LCK.hcb.creat 1
LCK.hcb.destroy 0
LCK.hcb.locks 2
LCK.hcl.creat 0
LCK.hcl.destroy 0
LCK.hcl.locks 0
LCK.herder.creat 0
LCK.herder.destroy 0
LCK.herder.locks 0
LCK.hsl.creat 0
LCK.hsl.destroy 0
LCK.hsl.locks 0
LCK.lru.creat 2
LCK.lru.destroy 0
LCK.lru.locks 20
LCK.mempool.creat 6
LCK.mempool.destroy 0
LCK.mempool.locks 665
LCK.nbusyobj.creat 0
LCK.nbusyobj.destroy 0
LCK.nbusyobj.locks 0
LCK.objhdr.creat 18
LCK.objhdr.destroy 0
LCK.objhdr.locks 5058036
LCK.sess.creat 15
LCK.sess.destroy 15
LCK.sess.locks 0
LCK.sessmem.creat 0
LCK.sessmem.destroy 0
LCK.sessmem.locks 0
LCK.sma.creat 2
LCK.sma.destroy 0
LCK.sma.locks 350
LCK.smf.creat 0
LCK.smf.destroy 0
LCK.smf.locks 0
LCK.smp.creat 0
LCK.smp.destroy 0
LCK.smp.locks 0
LCK.sms.creat 1
LCK.sms.destroy 0
LCK.sms.locks 0
LCK.vbp.creat 1
LCK.vbp.destroy 0
LCK.vbp.locks 0
LCK.vcapace.creat 1
LCK.vcapace.destroy 0
LCK.vcapace.locks 0
LCK.vcl.creat 1
LCK.vcl.destroy 0
LCK.vcl.locks 195
LCK.vxid.creat 1
LCK.vxid.destroy 0
LCK.vxid.locks 46
LCK.wq.creat 3
LCK.wq.destroy 0
LCK.wq.locks 4372
LCK.wstat.creat 1
LCK.wstat.destroy 0
LCK.wstat.locks 1264553
MAIN.backend_busy 0
MAIN.backend_conn 15
MAIN.backend_fail 0
MAIN.backend_recycle 89
MAIN.backend_req 89
MAIN.backend_retry 0
MAIN.backend_reuse 74
MAIN.backend_toolate 0
MAIN.backend_unhealthy 0
MAIN.bans 1
MAIN.bans_added 1
MAIN.bans_deleted 0
MAIN.bans_dups 0
MAIN.bans_gone 1
MAIN.bans_persisted_bytes 13
MAIN.bans_persisted_fragmentation 0
MAIN.bans_req 0
MAIN.bans_tested 0
MAIN.bans_tests_tested 0
MAIN.busy_sleep 17
MAIN.busy_wakeup 17
MAIN.cache_hit 1264208
MAIN.cache_hitpass 0
MAIN.cache_miss 6
MAIN.client_req 1264297
MAIN.client_req_400 0
MAIN.client_req_413 0
MAIN.client_req_417 0
MAIN.dir_dns_cache_full 0
MAIN.dir_dns_failed 0
MAIN.dir_dns_hit 0
MAIN.dir_dns_lookups 0
MAIN.esi_errors 0
MAIN.esi_warnings 0
MAIN.fetch_1xx 0
MAIN.fetch_204 0
MAIN.fetch_304 0
MAIN.fetch_bad 0
MAIN.fetch_chunked 0
MAIN.fetch_close 0
MAIN.fetch_eof 0
MAIN.fetch_failed 0
MAIN.fetch_head 0
MAIN.fetch_length 89
MAIN.fetch_oldhttp 0
MAIN.fetch_zero 0
MAIN.hcb_insert 1
MAIN.hcb_lock 1
MAIN.hcb_nolock 1264297
MAIN.losthdr 0
MAIN.n_backend 1
MAIN.n_expired 3
MAIN.n_gunzip 89
MAIN.n_gzip 0
MAIN.n_lru_moved 11
MAIN.n_lru_nuked 0
MAIN.n_object 3
MAIN.n_objectcore 19
MAIN.n_objecthead 17
MAIN.n_vampireobject 0
MAIN.n_vcl 1
MAIN.n_vcl_avail 1
MAIN.n_vcl_discard 0
MAIN.n_waitinglist 15
MAIN.pools 2
MAIN.s_bodybytes 676398895
MAIN.s_error 0
MAIN.s_fetch 89
MAIN.s_hdrbytes 537495411
MAIN.s_pass 83
MAIN.s_pipe 0
MAIN.s_req 1264297
MAIN.s_sess 15
MAIN.sess_closed 0
MAIN.sess_conn 15
MAIN.sess_drop 0
MAIN.sess_dropped 0
MAIN.sess_fail 0
MAIN.sess_herd 62
MAIN.sess_pipe_overflow 0
MAIN.sess_pipeline 0
MAIN.sess_queued 0
MAIN.sess_readahead 0
MAIN.shm_cont 96781
MAIN.shm_cycles 17
MAIN.shm_flushes 0
MAIN.shm_records 54370348
MAIN.shm_writes 2528937
MAIN.sms_balloc 0
MAIN.sms_bfree 0
MAIN.sms_nbytes 0
MAIN.sms_nobj 0
MAIN.sms_nreq 0
MAIN.thread_queue_len 0
MAIN.threads 2000
MAIN.threads_created 2000
MAIN.threads_destroyed 0
MAIN.threads_failed 0
MAIN.threads_limited 0
MAIN.uptime 32
MAIN.vmods 0
MAIN.vsm_cooling 0
MAIN.vsm_free 973296
MAIN.vsm_overflow 0
MAIN.vsm_overflowed 0
MAIN.vsm_used 83961312
MEMPOOL.busyobj.allocs 89
MEMPOOL.busyobj.frees 89
MEMPOOL.busyobj.live 0
MEMPOOL.busyobj.pool 15
MEMPOOL.busyobj.randry 5
MEMPOOL.busyobj.recycle 84
MEMPOOL.busyobj.surplus 0
MEMPOOL.busyobj.sz_needed 65568
MEMPOOL.busyobj.sz_wanted 65536
MEMPOOL.busyobj.timeout 0
MEMPOOL.busyobj.toosmall 0
MEMPOOL.req0.allocs 31
MEMPOOL.req0.frees 31
MEMPOOL.req0.live 0
MEMPOOL.req0.pool 10
MEMPOOL.req0.randry 0
MEMPOOL.req0.recycle 31
MEMPOOL.req0.surplus 0
MEMPOOL.req0.sz_needed 65568
MEMPOOL.req0.sz_wanted 65536
MEMPOOL.req0.timeout 6
MEMPOOL.req0.toosmall 0
MEMPOOL.req1.allocs 46
MEMPOOL.req1.frees 46
MEMPOOL.req1.live 0
MEMPOOL.req1.pool 10
MEMPOOL.req1.randry 0
MEMPOOL.req1.recycle 46
MEMPOOL.req1.surplus 0
MEMPOOL.req1.sz_needed 65568
MEMPOOL.req1.sz_wanted 65536
MEMPOOL.req1.timeout 9
MEMPOOL.req1.toosmall 0
MEMPOOL.sess0.allocs 6
MEMPOOL.sess0.frees 6
MEMPOOL.sess0.live 0
MEMPOOL.sess0.pool 10
MEMPOOL.sess0.randry 0
MEMPOOL.sess0.recycle 6
MEMPOOL.sess0.surplus 0
MEMPOOL.sess0.sz_needed 528
MEMPOOL.sess0.sz_wanted 496
MEMPOOL.sess0.timeout 6
MEMPOOL.sess0.toosmall 0
MEMPOOL.sess1.allocs 9
MEMPOOL.sess1.frees 9
MEMPOOL.sess1.live 0
MEMPOOL.sess1.pool 10
MEMPOOL.sess1.randry 0
MEMPOOL.sess1.recycle 9
MEMPOOL.sess1.surplus 0
MEMPOOL.sess1.sz_needed 528
MEMPOOL.sess1.sz_wanted 496
MEMPOOL.sess1.timeout 9
MEMPOOL.sess1.toosmall 0
MEMPOOL.vbc.allocs 15
MEMPOOL.vbc.frees 0
MEMPOOL.vbc.live 15
MEMPOOL.vbc.pool 10
MEMPOOL.vbc.randry 4
MEMPOOL.vbc.recycle 11
MEMPOOL.vbc.surplus 0
MEMPOOL.vbc.sz_needed 120
MEMPOOL.vbc.sz_wanted 88
MEMPOOL.vbc.timeout 0
MEMPOOL.vbc.toosmall 0
MGT.child_died 0
MGT.child_dump 0
MGT.child_exit 0
MGT.child_panic 0
MGT.child_start 1
MGT.child_stop 0
MGT.uptime 33
SMA.Transient.c_bytes 11747000
SMA.Transient.c_fail 0
SMA.Transient.c_freed 11351168
SMA.Transient.c_req 178
SMA.Transient.g_alloc 6
SMA.Transient.g_bytes 395832
SMA.Transient.g_space 0
SMA.s0.c_bytes 0
SMA.s0.c_fail 0
SMA.s0.c_freed 0
SMA.s0.c_req 0
SMA.s0.g_alloc 0
SMA.s0.g_bytes 0
SMA.s0.g_space 20971520
VBE.default(127.0.0.1,,80).happy 0
VBE.default(127.0.0.1,,80).vcls 1
}}}
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1340>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list