Varnish hit + pass + miss reaches less than 50% of all reqs
Guillaume Quintard
guillaume at varnish-software.com
Wed Apr 17 16:19:13 UTC 2019
Hi there,
So:
MAIN.client_req 290152364 (aaaaaaaaaaall the requests)
vs
MAIN.cache_hit 7433491
MAIN.cache_hit_grace 36319 (exclude these are they are already
accounted for in MAIN.cache_hit)
MAIN.cache_hitpass 16003020 (exclude these are they are already
accounted for in MAIN.s_pass)
MAIN.cache_miss 89526521
MAIN.s_synth 11418599
MAIN.s_pipe 216
MAIN.s_pass 181773529
the difference is now 8 requests, which is fairly reasonable (some requests
may be in flight, and threads don't necessarily push their stats after
every requests)
does this clarify things a bit?
--
Guillaume Quintard
On Wed, Apr 17, 2019 at 4:51 PM Alexandre Thaveau <
Alexandre.Thaveau at mister-auto.com> wrote:
> Hi Guillaume,
>
> thanks for helping !
>
> Here it is :
> MAIN.uptime 1821762 1.00 Child process uptime
>
>
> [532/604]
> MAIN.sess_conn 152864621 83.91 Sessions accepted
> MAIN.sess_drop 0 0.00 Sessions dropped
> MAIN.sess_fail 0 0.00 Session accept failures
> MAIN.client_req_400 0 0.00 Client requests received,
> subject to 400 errors
> MAIN.client_req_417 0 0.00 Client requests received,
> subject to 417 errors
> MAIN.client_req 290152364 159.27 Good client requests received
> MAIN.cache_hit 7433491 4.08 Cache hits
> MAIN.cache_hit_grace 36319 0.02 Cache grace hits
> MAIN.cache_hitpass 16003020 8.78 Cache hits for pass
> MAIN.cache_miss 89526521 49.14 Cache misses
> MAIN.backend_conn 5078542 2.79 Backend conn. success
> MAIN.backend_unhealthy 2 0.00 Backend conn. not
> attempted
> MAIN.backend_busy 0 0.00 Backend conn. too many
> MAIN.backend_fail 6245 0.00 Backend conn. failures
> MAIN.backend_reuse 266259369 146.15 Backend conn. reuses
> MAIN.backend_recycle 267274817 146.71 Backend conn. recycles
> MAIN.backend_retry 17429 0.01 Backend conn. retry
> MAIN.fetch_head 1623 0.00 Fetch no body (HEAD)
> MAIN.fetch_length 77119616 42.33 Fetch with Length
> MAIN.fetch_chunked 188334324 103.38 Fetch chunked
> MAIN.fetch_eof 295751 0.16 Fetch EOF
> MAIN.fetch_bad 0 0.00 Fetch bad T-E
> MAIN.fetch_none 18415 0.01 Fetch no body
> MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
> MAIN.fetch_204 5427973 2.98 Fetch no body (204)
> MAIN.fetch_304 130058 0.07 Fetch no body (304)
> MAIN.fetch_failed 8591 0.00 Fetch failed (all causes)
> MAIN.fetch_no_thread 0 0.00 Fetch failed (no thread)
> MAIN.pools 2 . Number of thread pools
> MAIN.threads 400 . Total number of threads
> MAIN.threads_limited 15 0.00 Threads hit max
> MAIN.threads_created 35825 0.02 Threads created
> MAIN.threads_destroyed 35425 0.02 Threads destroyed
> MAIN.threads_failed 0 0.00 Thread creation failed
> MAIN.thread_queue_len 0 . Length of session queue
> MAIN.busy_sleep 160177 0.09 Number of requests sent
> to sleep on busy objhdr
> MAIN.busy_wakeup 160177 0.09 Number of requests woken
> after sleep on busy objhdr
> MAIN.busy_killed 0 0.00 Number of requests killed
> after sleep on busy objhdr
> MAIN.sess_queued 35718 0.02 Sessions queued for thread
> MAIN.sess_dropped 0 0.00 Sessions dropped for
> thread
> MAIN.n_object 370310 . object structs made
> MAIN.n_vampireobject 0 . unresurrected objects
> MAIN.n_objectcore 370485 . objectcore structs made
> MAIN.n_objecthead 376770 . objecthead structs made
> MAIN.n_waitinglist 388 . waitinglist structs made
> MAIN.n_backend 363 . Number of backends
> MAIN.n_expired 68570078 . Number of expired objects
> MAIN.n_lru_nuked 20474008 . Number of LRU nuked
> objects
> MAIN.n_lru_moved 6156256 . Number of LRU moved
> objects
> MAIN.n_lru_limited 3 0.00 Reached nuke_limit
> MAIN.losthdr 0 0.00 HTTP header overflows
> MAIN.s_sess 152864621 83.91 Total sessions seen
> MAIN.s_req 290152364 159.27 Total requests seen
> MAIN.s_pipe 216 0.00 Total pipe sessions seen
> MAIN.s_pass 181773529 99.78 Total pass-ed requests
> seen
> MAIN.s_fetch 271300050 148.92 Total backend fetches
> initiated
> MAIN.s_synth 11418599 6.27 Total synthethic
> responses made
> MAIN.s_req_hdrbytes 490884503465 269455.89 Request header bytes
> MAIN.s_req_bodybytes 6627058200 3637.72 Request body bytes
> MAIN.s_resp_hdrbytes 253365794945 139077.33 Response header bytes
> MAIN.s_resp_bodybytes 2259371209416 1240212.06 Response body bytes
> MAIN.s_pipe_hdrbytes 317932 0.17 Pipe request header bytes
> MAIN.s_pipe_in 0 0.00 Piped bytes from client
> MAIN.s_pipe_out 650171 0.36 Piped bytes to client
> MAIN.s_pipe_out 650171 0.36 Piped bytes to client
> MAIN.sess_closed 8450 0.00 Session Closed
> MAIN.sess_closed_err 51028839 28.01 Session Closed with error
> MAIN.sess_readahead 0 0.00 Session Read Ahead
> MAIN.sess_herd 208419766 114.41 Session herd
> MAIN.sc_rem_close 101825384 55.89 Session OK REM_CLOSE
> MAIN.sc_req_close 103 0.00 Session OK REQ_CLOSE
> MAIN.sc_req_http10 0 0.00 Session Err REQ_HTTP10
> MAIN.sc_rx_bad 0 0.00 Session Err RX_BAD
> MAIN.sc_rx_body 0 0.00 Session Err RX_BODY
> MAIN.sc_rx_junk 0 0.00 Session Err RX_JUNK
> MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
> MAIN.sc_rx_timeout 51028883 28.01 Session Err RX_TIMEOUT
> MAIN.sc_tx_pipe 216 0.00 Session OK TX_PIPE
> MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
> MAIN.sc_tx_eof 0 0.00 Session OK TX_EOF
> MAIN.sc_resp_close 6107 0.00 Session OK RESP_CLOSE
> MAIN.sc_overload 0 0.00 Session Err OVERLOAD
> MAIN.sc_pipe_overflow 0 0.00 Session Err PIPE_OVERFLOW
> MAIN.sc_range_short 0 0.00 Session Err RANGE_SHORT
> MAIN.shm_records 48096929466 26401.32 SHM records
> MAIN.shm_writes 1753278706 962.41 SHM writes
> MAIN.shm_flushes 111020519 60.94 SHM flushes due to
> overflow
> MAIN.shm_cont 6287333 3.45 SHM MTX contention
> MAIN.shm_cycles 24363 0.01 SHM cycles through buffer
> MAIN.backend_req 271344507 148.95 Backend requests made
> MAIN.n_vcl 10 . Number of loaded VCLs in
> total
> MAIN.n_vcl_avail 10 . Number of VCLs available
> MAIN.n_vcl_discard 0 . Number of discarded VCLs
> MAIN.bans 1 . Count of bans
> MAIN.bans_completed 0 . Number of bans marked
> 'completed'
> MAIN.bans_obj 0 . Number of bans using obj.*
> MAIN.bans_req 1 . Number of bans using req.*
> MAIN.bans_added 128 0.00 Bans added
> MAIN.bans_deleted 127 0.00 Bans deleted
> MAIN.bans_tested 630175 0.35 Bans tested against
> objects (lookup)
> MAIN.bans_obj_killed 112189 0.06 Objects killed by bans
> (lookup)
> MAIN.bans_lurker_tested 0 0.00 Bans tested against
> objects (lurker)
> MAIN.bans_tests_tested 1382078 0.76 Ban tests tested against
> objects (lookup)
> MAIN.bans_lurker_tests_tested 0 0.00 Ban tests tested
> against objects (lurker)
> MAIN.bans_lurker_obj_killed 0 0.00 Objects killed by
> bans (lurker)
> MAIN.bans_dups 14 0.00 Bans superseded by
> other bans
> MAIN.bans_lurker_contention 0 0.00 Lurker gave way
> for lookup
> MAIN.bans_persisted_bytes 34768 . Bytes used by the
> persisted ban lists
> MAIN.bans_persisted_fragmentation 34468 . Extra bytes in
> persisted ban lists due to fragmentation
> MAIN.n_purges 0 . Number of
> purge operations executed
> MAIN.n_obj_purged 0 . Number of
> purged objects
> MAIN.exp_mailed 110185218 60.48 Number of
> objects mailed to expiry thread
> MAIN.exp_received 110185218 60.48 Number of
> objects received by expiry thread
> MAIN.hcb_nolock 112963041 62.01 HCB Lookups
> without lock
> MAIN.hcb_lock 86256017 47.35 HCB Lookups
> with lock
> MAIN.hcb_insert 86255995 47.35 HCB Inserts
> MAIN.esi_errors 0 0.00 ESI parse
> errors (unlock)
> MAIN.esi_warnings 0 0.00 ESI parse
> warnings (unlock)
> MAIN.vmods 2 . Loaded VMODs
> MAIN.n_gzip 129789432 71.24 Gzip operations
> MAIN.n_gunzip 210646709 115.63 Gunzip
> operations
> MAIN.vsm_free 965520 . Free VSM space
> MAIN.vsm_used 83969088 . Used VSM space
> MAIN.vsm_cooling 0 . Cooling VSM
> space
> MAIN.vsm_overflow 0 . Overflow VSM
> space
> MAIN.vsm_overflowed 0 0.00 Overflowed VSM
> space
> MGT.uptime 1821761 1.00 Management
> process uptime
> MGT.child_start 1 0.00 Child process
> started
> MGT.child_exit 0 0.00 Child process
> normal exit
> MGT.child_stop 0 0.00 Child process
> unexpected exit
> MGT.child_died 0 0.00 Child process
> died (signal)
> MGT.child_dump 0 0.00 Child process
> core dumped
> MGT.child_panic 0 0.00 Child process
> panic
> MEMPOOL.busyobj.live 34 . In use
> MEMPOOL.busyobj.pool 32 . In Pool
> MEMPOOL.busyobj.sz_wanted 65536 . Size requested
> MEMPOOL.busyobj.sz_actual 65504 . Size allocated
> MEMPOOL.busyobj.allocs 271336588 148.94 Allocations
> MEMPOOL.busyobj.frees 271336554 148.94 Frees
> MEMPOOL.busyobj.recycle 270933647 148.72 Recycled from
> pool
> MEMPOOL.busyobj.timeout 988916 0.54 Timed out from
> pool
> MEMPOOL.busyobj.toosmall 0 0.00 Too small to
> recycle
> MEMPOOL.busyobj.surplus 88997 0.05 Too many for
> pool
> MEMPOOL.busyobj.randry 402941 0.22 Pool ran dry
> MEMPOOL.req0.live 23 . In use
> MEMPOOL.req0.pool 24 . In Pool
> MEMPOOL.req0.sz_wanted 131072 . Size requested
> MEMPOOL.req0.sz_actual 131040 . Size allocated
> MEMPOOL.req0.allocs 155090050 85.13 Allocations
> MEMPOOL.req0.frees 155090027 85.13 Frees
> MEMPOOL.req0.recycle 154983843 85.07 Recycled from
> pool
> MEMPOOL.req0.timeout 1025602 0.56 Timed out from
> pool
> MEMPOOL.req0.toosmall 0 0.00 Too small to
> recycle
> MEMPOOL.req0.surplus 2995 0.00 Too many for
> pool
> MEMPOOL.req0.randry 106207 0.06 Pool ran dry
> MEMPOOL.sess0.live 333 . In use
> MEMPOOL.sess0.pool 20 . In Pool
> MEMPOOL.sess0.sz_wanted 512 . Size requested
> MEMPOOL.sess0.sz_actual 480 . Size allocated
> MEMPOOL.sess0.allocs 76433149 41.96 Allocations
> MEMPOOL.sess0.frees 76432816 41.96 Frees
> MEMPOOL.sess0.recycle 76232233 41.85 Recycled from
> pool
> MEMPOOL.sess0.timeout 1809683 0.99 Timed out from
> pool
> MEMPOOL.sess0.toosmall 0 0.00 Too small to
> recycle
> MEMPOOL.sess0.surplus 18419 0.01 Too many for
> pool
> MEMPOOL.sess0.randry 200916 0.11 Pool ran dry
> MEMPOOL.req1.live 23 . In use
> MEMPOOL.req1.pool 25 . In Pool
> MEMPOOL.req1.sz_wanted 131072 . Size requested
> MEMPOOL.req1.sz_actual 131040 . Size allocated
> MEMPOOL.req1.allocs 155148876 85.16 Allocations
> MEMPOOL.req1.frees 155148853 85.16 Frees
> MEMPOOL.req1.recycle 155041566 85.11 Recycled from
> pool
> MEMPOOL.req1.timeout 1025704 0.56 Timed out from
> pool
> MEMPOOL.req1.toosmall 0 0.00 Too small to
> recycle
> MEMPOOL.req1.surplus 2749 0.00 Too many for
> pool
> MEMPOOL.req1.randry 107310 0.06 Pool ran dry
> MEMPOOL.sess1.live 314 . In use
> MEMPOOL.sess1.pool 36 . In Pool
> MEMPOOL.sess1.sz_wanted 512 . Size requested
> MEMPOOL.sess1.sz_actual 480 . Size allocated
> MEMPOOL.sess1.allocs 76431491 41.95 Allocations
> MEMPOOL.sess1.frees 76431177 41.95 Frees
> MEMPOOL.sess1.recycle 76229789 41.84 Recycled from
> pool
> MEMPOOL.sess1.timeout 1811749 0.99 Timed out from
> pool
> MEMPOOL.sess1.toosmall 0 0.00 Too small to
> recycle
> MEMPOOL.sess1.surplus 18312 0.01 Too many for
> pool
> MEMPOOL.sess1.randry 201702 0.11 Pool ran dry
> SMA.default.c_req 104863620 57.56 Allocator
> requests
> SMA.default.c_fail 20841440 11.44 Allocator
> failures
> SMA.default.c_bytes 1035542691744 568429.19 Bytes
> allocated
> SMA.default.c_freed 1018362838340 558998.84 Bytes freed
> SMA.default.g_alloc 1393168 . Allocations
> outstanding
> SMA.default.g_bytes 17179853404 . Bytes
> outstanding
> SMA.default.g_space 15780 . Bytes available
> SMA.Transient.c_req 570410809 313.11 Allocator
> requests
> SMA.Transient.c_fail 0 0.00 Allocator
> failures
> SMA.Transient.c_bytes 4076783572265 2237824.46 Bytes
> allocated
> SMA.Transient.c_freed 4076757189033 2237809.98 Bytes freed
> SMA.Transient.g_alloc 19133 . Allocations
> outstanding
> SMA.Transient.g_bytes 26383232 . Bytes
> outstanding
> SMA.Transient.g_space 0 . Bytes available
> ...
> LCK.backend.creat
> 365 0.00 Created locks
>
> [0/604]
> LCK.backend.destroy
> 0 0.00 Destroyed locks
> LCK.backend.locks
> 555822161 305.10 Lock Operations
> LCK.backend_tcp.creat
> 37 0.00 Created locks
> LCK.backend_tcp.destroy
> 0 0.00 Destroyed locks
> LCK.backend_tcp.locks
> 1076235922 590.77 Lock Operations
> LCK.ban.creat
> 1 0.00 Created locks
> LCK.ban.destroy
> 0 0.00 Destroyed locks
> LCK.ban.locks
> 373355072 204.94 Lock Operations
> LCK.busyobj.creat
> 271334966 148.94 Created locks
> LCK.busyobj.destroy
> 271336345 148.94 Destroyed locks
> LCK.busyobj.locks
> 2741594616 1504.91 Lock Operations
> LCK.cli.creat
> 1 0.00 Created locks
> LCK.cli.destroy
> 0 0.00 Destroyed locks
> LCK.cli.locks
> 607411 0.33 Lock Operations
> LCK.exp.creat
> 1 0.00 Created locks
> LCK.exp.destroy
> 0 0.00 Destroyed locks
> LCK.exp.locks
> 563288168 309.20 Lock Operations
> LCK.hcb.creat
> 1 0.00 Created locks
> LCK.hcb.destroy
> 0 0.00 Destroyed locks
> LCK.hcb.locks
> 172158514 94.50 Lock Operations
> LCK.lru.creat
> 2 0.00 Created locks
> LCK.lru.destroy
> 0 0.00 Destroyed locks
> LCK.lru.locks
> 296448067 162.73 Lock Operations
> LCK.mempool.creat
> 5 0.00 Created locks
> LCK.mempool.destroy
> 0 0.00 Destroyed locks
> LCK.mempool.locks
> 1487652815 816.60 Lock Operations
> LCK.objhdr.creat
> 86265523 47.35 Created locks
> LCK.objhdr.destroy
> 85889681 47.15 Destroyed locks
> LCK.objhdr.locks
> 3588940017 1970.04 Lock Operations
> LCK.pipestat.creat
> 1 0.00 Created locks
> LCK.pipestat.destroy
> 0 0.00 Destroyed locks
> LCK.pipestat.locks
> 216 0.00 Lock Operations
> LCK.sess.creat
> 152861317 83.91 Created locks
> LCK.sess.destroy
> 152862891 83.91 Destroyed locks
> LCK.sess.locks
> 37421700 20.54 Lock Operations
> LCK.smp.creat
> 0 0.00 Created locks
> LCK.smp.destroy
> 0 0.00 Destroyed locks
> LCK.smp.locks
> 0 0.00 Lock Operations
> LCK.vbe.creat
> 1 0.00 Created locks
> LCK.vbe.destroy
> 0 0.00 Destroyed locks
> LCK.vbe.locks
> 607832 0.33 Lock Operations
> LCK.vcapace.creat
> 1 0.00 Created locks
> LCK.vcapace.destroy
> 0 0.00 Destroyed locks
> LCK.vcapace.locks
> 0 0.00 Lock Operations
> LCK.vcl.creat
> 1 0.00 Created locks
> LCK.vcl.destroy
> 0 0.00 Destroyed locks
> LCK.vcl.locks
> 543937089 298.58 Lock Operations
> LCK.vxid.creat
> 1 0.00 Created locks
> LCK.vxid.destroy
> 0 0.00 Destroyed locks
> LCK.vxid.locks
> 45733 0.03 Lock Operations
> LCK.waiter.creat
> 2 0.00 Created locks
> LCK.waiter.destroy
> 0 0.00 Destroyed locks
> LCK.waiter.locks
> 1420757858 779.88 Lock Operations
> LCK.wq.creat
> 3 0.00 Created locks
> LCK.wq.destroy
> 0 0.00 Destroyed locks
> LCK.wq.locks
> 1773506747 973.51 Lock Operations
> LCK.wstat.creat
> 1 0.00 Created locks
> LCK.wstat.destroy
> 0 0.00 Destroyed locks
> LCK.wstat.locks
> 759559125 416.94 Lock Operations
> LCK.sma.creat
> 2 0.00 Created locks
> LCK.sma.destroy
> 0 0.00 Destroyed locks
> LCK.sma.locks
> 1328287853 729.12 Lock Operations
>
> I removed the vcl_root sections, i hope you won't need it
>
> Thanks again,
>
> Le mer. 17 avr. 2019 à 17:28, Guillaume Quintard <
> guillaume at varnish-software.com> a écrit :
>
>> Can you share the "varnishstat -1" output?
>>
>> I'm pretty sure the answer is in the passes and synth responses you
>> omitted
>>
>>
>> On Wed, Apr 17, 2019, 16:19 Alexandre Thaveau <
>> Alexandre.Thaveau at mister-auto.com> wrote:
>>
>>> Hello everybody,
>>>
>>> i was trying to get some stats from my varnish server using varnishstat.
>>> When using varnish stat, i see that :
>>> - MAIN.client_req should make 100% of my queries
>>> - MAIN.cache_hit represents 10% of MAIN.client_req
>>> - MAIN.cache_hitpass represents 7% of MAIN.client_req
>>> - MAIN.cache_miss represents 24% of MAIN.client_req
>>> - MAIN.cache_hit_grace is very low
>>>
>>> So all these sumed categories represent less than 50% of client_req, i
>>> think i'm missing something. The configuration is not maintained by me,
>>> here is a sample of what it returns if this can help :
>>> -------------------------------------
>>> cat /etc/varnish/production.vcl | grep return
>>> return(synth(900, "Moved Permanently"));
>>> return(synth(901, "Moved Permanently"));
>>> return(synth(902, "Moved Permanently"));
>>> return(synth(903, "Moved Permanently"));
>>> return(pipe);
>>> return(pipe);
>>> return(pass);
>>> return(pass);
>>> return(pass);
>>> return(synth(410, "Gone"));
>>> return(pass);
>>> return(synth(850, "Moved Permanently"));
>>> return(hash);
>>> return(hash);
>>> return(pass);
>>> return(hash);
>>> return(lookup);
>>> return(retry);
>>> return(deliver);
>>> -------------------------------------
>>>
>>> Thanks very much for your help,
>>> Regards,
>>> Alex
>>> _______________________________________________
>>> varnish-misc mailing list
>>> varnish-misc at varnish-cache.org
>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>
>>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20190417/88ff0eb8/attachment-0001.html>
More information about the varnish-misc
mailing list