[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