Varnish Cache pages being Invalidated too soon Magento 2Varnish / Magento, Monitoring & Partial Cache ClearsCache Types are invalidatedVarnish Cache-Control: Max_Age 0 ; On Magento 2Magento 2.1 - Flushing Varnish CacheHow to cache Magento 2 with VarnishMagento 2 : X-Magento-Cache-Debug:MISS, over SSL, pages are not being cached by varnishMagento 2.2 : How to programatically clear the varnish cache by cache tagMagento2 : Will cacheable = “false” invalidate cache in varnish cache?Varnish cache not clearing from magento adminMagnto 2 : varnish cache issue?
India just shot down a satellite from the ground. At what altitude range is the resulting debris field?
Is there a korbon needed for conversion?
Why Were Madagascar and New Zealand Discovered So Late?
What is paid subscription needed for in Mortal Kombat 11?
How do I go from 300 unfinished/half written blog posts, to published posts?
Applicability of Single Responsibility Principle
Flow chart document symbol
Return the Closest Prime Number
Different result between scanning in Epson's "color negative film" mode and scanning in positive -> invert curve in post?
What happens if you roll doubles 3 times then land on "Go to jail?"
What does 算不上 mean in 算不上太美好的日子?
Increase performance creating Mandelbrot set in python
How can I kill an app using Terminal?
Is `x >> pure y` equivalent to `liftM (const y) x`
How to Reset Passwords on Multiple Websites Easily?
What is the difference between "behavior" and "behaviour"?
Is HostGator storing my password in plaintext?
Sequence of Tenses: Translating the subjunctive
Roman Numeral Treatment of Suspensions
How does the UK government determine the size of a mandate?
Valid Badminton Score?
How can I get through very long and very dry, but also very useful technical documents when learning a new tool?
Short story about space worker geeks who zone out by 'listening' to radiation from stars
How do I extract a value from a time formatted value in excel?
Varnish Cache pages being Invalidated too soon Magento 2
Varnish / Magento, Monitoring & Partial Cache ClearsCache Types are invalidatedVarnish Cache-Control: Max_Age 0 ; On Magento 2Magento 2.1 - Flushing Varnish CacheHow to cache Magento 2 with VarnishMagento 2 : X-Magento-Cache-Debug:MISS, over SSL, pages are not being cached by varnishMagento 2.2 : How to programatically clear the varnish cache by cache tagMagento2 : Will cacheable = “false” invalidate cache in varnish cache?Varnish cache not clearing from magento adminMagnto 2 : varnish cache issue?
I have setup varnish on my server and have used this with the default vcl provided by Magento 2 on my store. This has about 16,000 main pages (category, product, CMS) and want to store this all in the varnish cache. A warmup script is run each day which warms this up and for the first few days every page was stored in varnish fine with TTFB of about 40 - 60ms which was great.
Now however the cache mostly seems to be showing MISS in varnishlog for about half of requests and pages that were only warmed up a few mins ago seem to be showing MISS soon after. I have been very generous with memory here as have 24gb to play with and so originally gave it 4gb, and doubled it to 8gb but still the same issue occurs. MAIN.n_lru_nuked seems fine at 0 however so guess i'm looking in the wrong place.
I'm hoping someone can have a look over the Varnish stats below and suggest what may be causing this? I thought it may be Magento invalidating pages a bit hastily on saves or re-index but have had them invalidate without an index this morning so wondering if there is also a way to debug when a pages is becoming invalidated or a method to further debug this?
varnishstat -1
MGT.uptime 90904 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
MAIN.summs 2806804 30.88 stat summ operations
MAIN.uptime 90905 1.00 Child process uptime
MAIN.sess_conn 926975 10.20 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.client_req_400 31 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 938335 10.32 Good client requests received
MAIN.cache_hit 500846 5.51 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass.
MAIN.cache_hitmiss 2359 0.03 Cache hits for miss.
MAIN.cache_miss 253358 2.79 Cache misses
MAIN.backend_conn 206352 2.27 Backend conn. success
MAIN.backend_unhealthy 0 0.00 Backend conn. not attempted
MAIN.backend_busy 0 0.00 Backend conn. too many
MAIN.backend_fail 0 0.00 Backend conn. failures
MAIN.backend_reuse 250885 2.76 Backend conn. reuses
MAIN.backend_recycle 254263 2.80 Backend conn. recycles
MAIN.backend_retry 0 0.00 Backend conn. retry
MAIN.fetch_head 0 0.00 Fetch no body (HEAD)
MAIN.fetch_length 181357 2.00 Fetch with Length
MAIN.fetch_chunked 264446 2.91 Fetch chunked
MAIN.fetch_eof 6562 0.07 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_none 0 0.00 Fetch no body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 5034 0.06 Fetch no body (304)
MAIN.fetch_failed 0 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 200 . Total number of threads
MAIN.threads_limited 0 0.00 Threads hit max
MAIN.threads_created 200 0.00 Threads created
MAIN.threads_destroyed 0 0.00 Threads destroyed
MAIN.threads_failed 0 0.00 Thread creation failed
MAIN.thread_queue_len 0 . Length of session queue
MAIN.busy_sleep 972 0.01 Number of requests sent to sleep on busy objhdr
MAIN.busy_wakeup 972 0.01 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 0 0.00 Sessions queued for thread
MAIN.sess_dropped 0 0.00 Sessions dropped for thread
MAIN.req_dropped 0 0.00 Requests dropped
MAIN.n_object 64520 . object structs made
MAIN.n_vampireobject 0 . unresurrected objects
MAIN.n_objectcore 64620 . objectcore structs made
MAIN.n_objecthead 57476 . objecthead structs made
MAIN.n_backend 1 . Number of backends
MAIN.n_expired 0 . Number of expired objects
MAIN.n_lru_nuked 0 . Number of LRU nuked objects
MAIN.n_lru_moved 406691 . Number of LRU moved objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 926975 10.20 Total sessions seen
MAIN.s_pipe 1 0.00 Total pipe sessions seen
MAIN.s_pass 203230 2.24 Total pass-ed requests seen
MAIN.s_fetch 456588 5.02 Total backend fetches initiated
MAIN.s_synth 364 0.00 Total synthethic responses made
MAIN.s_req_hdrbytes 858808294 9447.32 Request header bytes
MAIN.s_req_bodybytes 58796630 646.79 Request body bytes
MAIN.s_resp_hdrbytes 336451106 3701.13 Response header bytes
MAIN.s_resp_bodybytes 45504621379 500573.36 Response body bytes
MAIN.s_pipe_hdrbytes 90 0.00 Pipe request header bytes
MAIN.s_pipe_in 0 0.00 Piped bytes from client
MAIN.s_pipe_out 680 0.01 Piped bytes to client
MAIN.sess_closed 919250 10.11 Session Closed
MAIN.sess_closed_err 985 0.01 Session Closed with error
MAIN.sess_readahead 11 0.00 Session Read Ahead
MAIN.sess_herd 19188 0.21 Session herd
MAIN.sc_rem_close 7006 0.08 Session OK REM_CLOSE
MAIN.sc_req_close 842716 9.27 Session OK REQ_CLOSE
MAIN.sc_req_http10 37 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 31 0.00 Session Err RX_JUNK
MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
MAIN.sc_rx_timeout 917 0.01 Session Err RX_TIMEOUT
MAIN.sc_tx_pipe 1 0.00 Session OK TX_PIPE
MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
MAIN.sc_tx_eof 76032 0.84 Session OK TX_EOF
MAIN.sc_resp_close 0 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.sc_req_http20 0 0.00 Session Err REQ_HTTP20
MAIN.sc_vcl_failure 0 0.00 Session Err VCL_FAILURE
MAIN.shm_records 103713157 1140.90 SHM records
MAIN.shm_writes 6390221 70.30 SHM writes
MAIN.shm_flushes 15491 0.17 SHM flushes due to overflow
MAIN.shm_cont 106846 1.18 SHM MTX contention
MAIN.shm_cycles 51 0.00 SHM cycles through buffer
MAIN.backend_req 457249 5.03 Backend requests made
MAIN.n_vcl 1 . Number of loaded VCLs in total
MAIN.n_vcl_avail 1 . Number of VCLs available
MAIN.n_vcl_discard 0 . Number of discarded VCLs
MAIN.vcl_fail 0 0.00 VCL failures
MAIN.bans 2 . Count of bans
MAIN.bans_completed 1 . Number of bans marked 'completed'
MAIN.bans_obj 2 . Number of bans using obj.*
MAIN.bans_req 0 . Number of bans using req.*
MAIN.bans_added 365 0.00 Bans added
MAIN.bans_deleted 363 0.00 Bans deleted
MAIN.bans_tested 15744 0.17 Bans tested against objects (lookup)
MAIN.bans_obj_killed 1033 0.01 Objects killed by bans (lookup)
MAIN.bans_lurker_tested 10719639 117.92 Bans tested against objects (lurker)
MAIN.bans_tests_tested 19834 0.22 Ban tests tested against objects (lookup)
MAIN.bans_lurker_tests_tested 10719639 117.92 Ban tests tested against objects (lurker)
MAIN.bans_lurker_obj_killed 186846 2.06 Objects killed by bans (lurker)
MAIN.bans_lurker_obj_killed_cutoff 0 0.00 Objects killed by bans for cutoff (lurker)
MAIN.bans_dups 22 0.00 Bans superseded by other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way for lookup
MAIN.bans_persisted_bytes 109136 . Bytes used by the persisted ban lists
MAIN.bans_persisted_fragmentation 108846 . 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 443817 4.88 Number of objects mailed to expiry thread
MAIN.exp_received 443691 4.88 Number of objects received by expiry thread
MAIN.hcb_nolock 754244 8.30 HCB Lookups without lock
MAIN.hcb_lock 244042 2.68 HCB Lookups with lock
MAIN.hcb_insert 244005 2.68 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse errors (unlock)
MAIN.esi_warnings 0 0.00 ESI parse warnings (unlock)
MAIN.vmods 1 . Loaded VMODs
MAIN.n_gzip 324801 3.57 Gzip operations
MAIN.n_gunzip 214393 2.36 Gunzip operations
MAIN.n_test_gunzip 0 0.00 Test gunzip operations
LCK.backend.creat 3 0.00 Created locks
LCK.backend.destroy 0 0.00 Destroyed locks
LCK.backend.locks 914803 10.06 Lock Operations
LCK.backend_tcp.creat 1 0.00 Created locks
LCK.backend_tcp.destroy 0 0.00 Destroyed locks
LCK.backend_tcp.locks 1419947 15.62 Lock Operations
LCK.ban.creat 1 0.00 Created locks
LCK.ban.destroy 0 0.00 Destroyed locks
LCK.ban.locks 21954558 241.51 Lock Operations
LCK.busyobj.creat 471560 5.19 Created locks
LCK.busyobj.destroy 472072 5.19 Destroyed locks
LCK.busyobj.locks 4644562 51.09 Lock Operations
LCK.cli.creat 1 0.00 Created locks
LCK.cli.destroy 0 0.00 Destroyed locks
LCK.cli.locks 30310 0.33 Lock Operations
LCK.exp.creat 1 0.00 Created locks
LCK.exp.destroy 0 0.00 Destroyed locks
LCK.exp.locks 1394596 15.34 Lock Operations
LCK.hcb.creat 1 0.00 Created locks
LCK.hcb.destroy 0 0.00 Destroyed locks
LCK.hcb.locks 431394 4.75 Lock Operations
LCK.lru.creat 2 0.00 Created locks
LCK.lru.destroy 0 0.00 Destroyed locks
LCK.lru.locks 850662 9.36 Lock Operations
LCK.mempool.creat 5 0.00 Created locks
LCK.mempool.destroy 0 0.00 Destroyed locks
LCK.mempool.locks 5230414 57.54 Lock Operations
LCK.objhdr.creat 243628 2.68 Created locks
LCK.objhdr.destroy 186669 2.05 Destroyed locks
LCK.objhdr.locks 28657093 315.24 Lock Operations
LCK.pipestat.creat 1 0.00 Created locks
LCK.pipestat.destroy 0 0.00 Destroyed locks
LCK.pipestat.locks 1 0.00 Lock Operations
LCK.sess.creat 926777 10.20 Created locks
LCK.sess.destroy 926953 10.20 Destroyed locks
LCK.sess.locks 1894787 20.84 Lock Operations
LCK.vbe.creat 1 0.00 Created locks
LCK.vbe.destroy 0 0.00 Destroyed locks
LCK.vbe.locks 30303 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 936781 10.31 Lock Operations
LCK.vxid.creat 1 0.00 Created locks
LCK.vxid.destroy 0 0.00 Destroyed locks
LCK.vxid.locks 151 0.00 Lock Operations
LCK.waiter.creat 2 0.00 Created locks
LCK.waiter.destroy 0 0.00 Destroyed locks
LCK.waiter.locks 871776 9.59 Lock Operations
LCK.wq.creat 3 0.00 Created locks
LCK.wq.destroy 0 0.00 Destroyed locks
LCK.wq.locks 4301794 47.32 Lock Operations
LCK.wstat.creat 1 0.00 Created locks
LCK.wstat.destroy 0 0.00 Destroyed locks
LCK.wstat.locks 1659573 18.26 Lock Operations
MEMPOOL.busyobj.live 0 . In use
MEMPOOL.busyobj.pool 12 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_actual 65504 . Size allocated
MEMPOOL.busyobj.allocs 457400 5.03 Allocations
MEMPOOL.busyobj.frees 457400 5.03 Frees
MEMPOOL.busyobj.recycle 453100 4.98 Recycled from pool
MEMPOOL.busyobj.timeout 26814 0.29 Timed out from pool
MEMPOOL.busyobj.toosmall 0 0.00 Too small to recycle
MEMPOOL.busyobj.surplus 0 0.00 Too many for pool
MEMPOOL.busyobj.randry 4300 0.05 Pool ran dry
MEMPOOL.req0.live 0 . In use
MEMPOOL.req0.pool 10 . In Pool
MEMPOOL.req0.sz_wanted 65536 . Size requested
MEMPOOL.req0.sz_actual 65504 . Size allocated
MEMPOOL.req0.allocs 477754 5.26 Allocations
MEMPOOL.req0.frees 477754 5.26 Frees
MEMPOOL.req0.recycle 476619 5.24 Recycled from pool
MEMPOOL.req0.timeout 19941 0.22 Timed out from pool
MEMPOOL.req0.toosmall 0 0.00 Too small to recycle
MEMPOOL.req0.surplus 0 0.00 Too many for pool
MEMPOOL.req0.randry 1135 0.01 Pool ran dry
MEMPOOL.sess0.live 1 . In use
MEMPOOL.sess0.pool 10 . In Pool
MEMPOOL.sess0.sz_wanted 512 . Size requested
MEMPOOL.sess0.sz_actual 480 . Size allocated
MEMPOOL.sess0.allocs 462269 5.09 Allocations
MEMPOOL.sess0.frees 462268 5.09 Frees
MEMPOOL.sess0.recycle 461283 5.07 Recycled from pool
MEMPOOL.sess0.timeout 19885 0.22 Timed out from pool
MEMPOOL.sess0.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess0.surplus 0 0.00 Too many for pool
MEMPOOL.sess0.randry 986 0.01 Pool ran dry
LCK.sma.creat 2 0.00 Created locks
LCK.sma.destroy 0 0.00 Destroyed locks
LCK.sma.locks 2874986 31.63 Lock Operations
SMA.s0.c_req 810812 8.92 Allocator requests
SMA.s0.c_fail 0 0.00 Allocator failures
SMA.s0.c_bytes 9342858679 102776.07 Bytes allocated
SMA.s0.c_freed 9228279877 101515.65 Bytes freed
SMA.s0.g_alloc 26724 . Allocations outstanding
SMA.s0.g_bytes 114578802 . Bytes outstanding
SMA.s0.g_space 8274029198 . Bytes available
SMA.Transient.c_req 666957 7.34 Allocator requests
SMA.Transient.c_fail 0 0.00 Allocator failures
SMA.Transient.c_bytes 9471571306 104191.97 Bytes allocated
SMA.Transient.c_freed 9439387738 103837.94 Bytes freed
SMA.Transient.g_alloc 53827 . Allocations outstanding
SMA.Transient.g_bytes 32183568 . Bytes outstanding
SMA.Transient.g_space 0 . Bytes available
MEMPOOL.req1.live 0 . In use
MEMPOOL.req1.pool 10 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_actual 65504 . Size allocated
MEMPOOL.req1.allocs 486959 5.36 Allocations
MEMPOOL.req1.frees 486959 5.36 Frees
MEMPOOL.req1.recycle 485736 5.34 Recycled from pool
MEMPOOL.req1.timeout 20597 0.23 Timed out from pool
MEMPOOL.req1.toosmall 0 0.00 Too small to recycle
MEMPOOL.req1.surplus 0 0.00 Too many for pool
MEMPOOL.req1.randry 1223 0.01 Pool ran dry
MEMPOOL.sess1.live 1 . In use
MEMPOOL.sess1.pool 12 . In Pool
MEMPOOL.sess1.sz_wanted 512 . Size requested
MEMPOOL.sess1.sz_actual 480 . Size allocated
MEMPOOL.sess1.allocs 464706 5.11 Allocations
MEMPOOL.sess1.frees 464705 5.11 Frees
MEMPOOL.sess1.recycle 463561 5.10 Recycled from pool
MEMPOOL.sess1.timeout 19860 0.22 Timed out from pool
MEMPOOL.sess1.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess1.surplus 0 0.00 Too many for pool
MEMPOOL.sess1.randry 1145 0.01 Pool ran dry
VBE.boot.default.happy 0 . Happy health probes
VBE.boot.default.bereq_hdrbytes 376430490 4140.92 Request header bytes
VBE.boot.default.bereq_bodybytes 58796630 646.79 Request body bytes
VBE.boot.default.beresp_hdrbytes 303625397 3340.03 Response header bytes
VBE.boot.default.beresp_bodybytes 3569114775 39262.03 Response body bytes
VBE.boot.default.pipe_hdrbytes 160 0.00 Pipe request header bytes
VBE.boot.default.pipe_out 0 0.00 Piped bytes to backend
VBE.boot.default.pipe_in 680 0.01 Piped bytes from backend
VBE.boot.default.conn 0 . Concurrent connections to backend
VBE.boot.default.req 457400 5.03 Backend requests sent
varnishlog -q 'ReqURL ~ "^/category.html"'; MISS Example
* << Request >> 4767711
- Begin req 4767710 rxreq
- Timestamp Start: 1553598632.671737 0.000000 0.000000
- Timestamp Req: 1553598632.671737 0.000000 0.000000
- ReqStart 127.0.0.1 59282
- ReqMethod GET
- ReqURL /category.html
- ReqProtocol HTTP/1.0
- ReqHeader X-Real-IP: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Port: 443
- ReqHeader Host: www.magentostore.com
- ReqHeader Connection: close
- ReqHeader Accept: */*
- ReqUnset X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1, 127.0.0.1
- VCL_call RECV
- ReqHeader grace: none
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 4767712 fetch
- Timestamp Fetch: 1553598633.282252 0.610515 0.610515
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Tue, 26 Mar 2019 11:10:32 GMT
- RespHeader Server: Apache/2.4.6 (CentOS)
- RespHeader X-Powered-By: PHP/7.1.26
- RespHeader Pragma: cache
- RespHeader Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 4767711
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish (Varnish/5.2)
- VCL_call DELIVER
- RespUnset Age: 0
- RespUnset Pragma: cache
- RespHeader Pragma: no-cache
- RespUnset Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader Expires: -1
- RespUnset Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Cache-Control: no-store, no-cache, must-revalidate, max-age=0
- RespUnset X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespUnset X-Powered-By: PHP/7.1.26
- RespUnset Server: Apache/2.4.6 (CentOS)
- RespUnset X-Varnish: 4767711
- RespUnset Via: 1.1 varnish (Varnish/5.2)
- VCL_return deliver
- Timestamp Process: 1553598633.282310 0.610573 0.000057
- RespUnset Content-Encoding: gzip
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 149297
- RespHeader Connection: close
- Gzip U D - 24773 149297 80 198104 198114
- Timestamp Resp: 1553598633.283472 0.611735 0.001162
- ReqAcct 220 0 220 373 149297 149670
- End
The above example was warmed up a matter of mins previous and showed HIT so know this was in Varnish Cache just not sure why it's no longer there soon after.
magento2 cache varnish
add a comment |
I have setup varnish on my server and have used this with the default vcl provided by Magento 2 on my store. This has about 16,000 main pages (category, product, CMS) and want to store this all in the varnish cache. A warmup script is run each day which warms this up and for the first few days every page was stored in varnish fine with TTFB of about 40 - 60ms which was great.
Now however the cache mostly seems to be showing MISS in varnishlog for about half of requests and pages that were only warmed up a few mins ago seem to be showing MISS soon after. I have been very generous with memory here as have 24gb to play with and so originally gave it 4gb, and doubled it to 8gb but still the same issue occurs. MAIN.n_lru_nuked seems fine at 0 however so guess i'm looking in the wrong place.
I'm hoping someone can have a look over the Varnish stats below and suggest what may be causing this? I thought it may be Magento invalidating pages a bit hastily on saves or re-index but have had them invalidate without an index this morning so wondering if there is also a way to debug when a pages is becoming invalidated or a method to further debug this?
varnishstat -1
MGT.uptime 90904 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
MAIN.summs 2806804 30.88 stat summ operations
MAIN.uptime 90905 1.00 Child process uptime
MAIN.sess_conn 926975 10.20 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.client_req_400 31 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 938335 10.32 Good client requests received
MAIN.cache_hit 500846 5.51 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass.
MAIN.cache_hitmiss 2359 0.03 Cache hits for miss.
MAIN.cache_miss 253358 2.79 Cache misses
MAIN.backend_conn 206352 2.27 Backend conn. success
MAIN.backend_unhealthy 0 0.00 Backend conn. not attempted
MAIN.backend_busy 0 0.00 Backend conn. too many
MAIN.backend_fail 0 0.00 Backend conn. failures
MAIN.backend_reuse 250885 2.76 Backend conn. reuses
MAIN.backend_recycle 254263 2.80 Backend conn. recycles
MAIN.backend_retry 0 0.00 Backend conn. retry
MAIN.fetch_head 0 0.00 Fetch no body (HEAD)
MAIN.fetch_length 181357 2.00 Fetch with Length
MAIN.fetch_chunked 264446 2.91 Fetch chunked
MAIN.fetch_eof 6562 0.07 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_none 0 0.00 Fetch no body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 5034 0.06 Fetch no body (304)
MAIN.fetch_failed 0 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 200 . Total number of threads
MAIN.threads_limited 0 0.00 Threads hit max
MAIN.threads_created 200 0.00 Threads created
MAIN.threads_destroyed 0 0.00 Threads destroyed
MAIN.threads_failed 0 0.00 Thread creation failed
MAIN.thread_queue_len 0 . Length of session queue
MAIN.busy_sleep 972 0.01 Number of requests sent to sleep on busy objhdr
MAIN.busy_wakeup 972 0.01 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 0 0.00 Sessions queued for thread
MAIN.sess_dropped 0 0.00 Sessions dropped for thread
MAIN.req_dropped 0 0.00 Requests dropped
MAIN.n_object 64520 . object structs made
MAIN.n_vampireobject 0 . unresurrected objects
MAIN.n_objectcore 64620 . objectcore structs made
MAIN.n_objecthead 57476 . objecthead structs made
MAIN.n_backend 1 . Number of backends
MAIN.n_expired 0 . Number of expired objects
MAIN.n_lru_nuked 0 . Number of LRU nuked objects
MAIN.n_lru_moved 406691 . Number of LRU moved objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 926975 10.20 Total sessions seen
MAIN.s_pipe 1 0.00 Total pipe sessions seen
MAIN.s_pass 203230 2.24 Total pass-ed requests seen
MAIN.s_fetch 456588 5.02 Total backend fetches initiated
MAIN.s_synth 364 0.00 Total synthethic responses made
MAIN.s_req_hdrbytes 858808294 9447.32 Request header bytes
MAIN.s_req_bodybytes 58796630 646.79 Request body bytes
MAIN.s_resp_hdrbytes 336451106 3701.13 Response header bytes
MAIN.s_resp_bodybytes 45504621379 500573.36 Response body bytes
MAIN.s_pipe_hdrbytes 90 0.00 Pipe request header bytes
MAIN.s_pipe_in 0 0.00 Piped bytes from client
MAIN.s_pipe_out 680 0.01 Piped bytes to client
MAIN.sess_closed 919250 10.11 Session Closed
MAIN.sess_closed_err 985 0.01 Session Closed with error
MAIN.sess_readahead 11 0.00 Session Read Ahead
MAIN.sess_herd 19188 0.21 Session herd
MAIN.sc_rem_close 7006 0.08 Session OK REM_CLOSE
MAIN.sc_req_close 842716 9.27 Session OK REQ_CLOSE
MAIN.sc_req_http10 37 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 31 0.00 Session Err RX_JUNK
MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
MAIN.sc_rx_timeout 917 0.01 Session Err RX_TIMEOUT
MAIN.sc_tx_pipe 1 0.00 Session OK TX_PIPE
MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
MAIN.sc_tx_eof 76032 0.84 Session OK TX_EOF
MAIN.sc_resp_close 0 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.sc_req_http20 0 0.00 Session Err REQ_HTTP20
MAIN.sc_vcl_failure 0 0.00 Session Err VCL_FAILURE
MAIN.shm_records 103713157 1140.90 SHM records
MAIN.shm_writes 6390221 70.30 SHM writes
MAIN.shm_flushes 15491 0.17 SHM flushes due to overflow
MAIN.shm_cont 106846 1.18 SHM MTX contention
MAIN.shm_cycles 51 0.00 SHM cycles through buffer
MAIN.backend_req 457249 5.03 Backend requests made
MAIN.n_vcl 1 . Number of loaded VCLs in total
MAIN.n_vcl_avail 1 . Number of VCLs available
MAIN.n_vcl_discard 0 . Number of discarded VCLs
MAIN.vcl_fail 0 0.00 VCL failures
MAIN.bans 2 . Count of bans
MAIN.bans_completed 1 . Number of bans marked 'completed'
MAIN.bans_obj 2 . Number of bans using obj.*
MAIN.bans_req 0 . Number of bans using req.*
MAIN.bans_added 365 0.00 Bans added
MAIN.bans_deleted 363 0.00 Bans deleted
MAIN.bans_tested 15744 0.17 Bans tested against objects (lookup)
MAIN.bans_obj_killed 1033 0.01 Objects killed by bans (lookup)
MAIN.bans_lurker_tested 10719639 117.92 Bans tested against objects (lurker)
MAIN.bans_tests_tested 19834 0.22 Ban tests tested against objects (lookup)
MAIN.bans_lurker_tests_tested 10719639 117.92 Ban tests tested against objects (lurker)
MAIN.bans_lurker_obj_killed 186846 2.06 Objects killed by bans (lurker)
MAIN.bans_lurker_obj_killed_cutoff 0 0.00 Objects killed by bans for cutoff (lurker)
MAIN.bans_dups 22 0.00 Bans superseded by other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way for lookup
MAIN.bans_persisted_bytes 109136 . Bytes used by the persisted ban lists
MAIN.bans_persisted_fragmentation 108846 . 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 443817 4.88 Number of objects mailed to expiry thread
MAIN.exp_received 443691 4.88 Number of objects received by expiry thread
MAIN.hcb_nolock 754244 8.30 HCB Lookups without lock
MAIN.hcb_lock 244042 2.68 HCB Lookups with lock
MAIN.hcb_insert 244005 2.68 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse errors (unlock)
MAIN.esi_warnings 0 0.00 ESI parse warnings (unlock)
MAIN.vmods 1 . Loaded VMODs
MAIN.n_gzip 324801 3.57 Gzip operations
MAIN.n_gunzip 214393 2.36 Gunzip operations
MAIN.n_test_gunzip 0 0.00 Test gunzip operations
LCK.backend.creat 3 0.00 Created locks
LCK.backend.destroy 0 0.00 Destroyed locks
LCK.backend.locks 914803 10.06 Lock Operations
LCK.backend_tcp.creat 1 0.00 Created locks
LCK.backend_tcp.destroy 0 0.00 Destroyed locks
LCK.backend_tcp.locks 1419947 15.62 Lock Operations
LCK.ban.creat 1 0.00 Created locks
LCK.ban.destroy 0 0.00 Destroyed locks
LCK.ban.locks 21954558 241.51 Lock Operations
LCK.busyobj.creat 471560 5.19 Created locks
LCK.busyobj.destroy 472072 5.19 Destroyed locks
LCK.busyobj.locks 4644562 51.09 Lock Operations
LCK.cli.creat 1 0.00 Created locks
LCK.cli.destroy 0 0.00 Destroyed locks
LCK.cli.locks 30310 0.33 Lock Operations
LCK.exp.creat 1 0.00 Created locks
LCK.exp.destroy 0 0.00 Destroyed locks
LCK.exp.locks 1394596 15.34 Lock Operations
LCK.hcb.creat 1 0.00 Created locks
LCK.hcb.destroy 0 0.00 Destroyed locks
LCK.hcb.locks 431394 4.75 Lock Operations
LCK.lru.creat 2 0.00 Created locks
LCK.lru.destroy 0 0.00 Destroyed locks
LCK.lru.locks 850662 9.36 Lock Operations
LCK.mempool.creat 5 0.00 Created locks
LCK.mempool.destroy 0 0.00 Destroyed locks
LCK.mempool.locks 5230414 57.54 Lock Operations
LCK.objhdr.creat 243628 2.68 Created locks
LCK.objhdr.destroy 186669 2.05 Destroyed locks
LCK.objhdr.locks 28657093 315.24 Lock Operations
LCK.pipestat.creat 1 0.00 Created locks
LCK.pipestat.destroy 0 0.00 Destroyed locks
LCK.pipestat.locks 1 0.00 Lock Operations
LCK.sess.creat 926777 10.20 Created locks
LCK.sess.destroy 926953 10.20 Destroyed locks
LCK.sess.locks 1894787 20.84 Lock Operations
LCK.vbe.creat 1 0.00 Created locks
LCK.vbe.destroy 0 0.00 Destroyed locks
LCK.vbe.locks 30303 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 936781 10.31 Lock Operations
LCK.vxid.creat 1 0.00 Created locks
LCK.vxid.destroy 0 0.00 Destroyed locks
LCK.vxid.locks 151 0.00 Lock Operations
LCK.waiter.creat 2 0.00 Created locks
LCK.waiter.destroy 0 0.00 Destroyed locks
LCK.waiter.locks 871776 9.59 Lock Operations
LCK.wq.creat 3 0.00 Created locks
LCK.wq.destroy 0 0.00 Destroyed locks
LCK.wq.locks 4301794 47.32 Lock Operations
LCK.wstat.creat 1 0.00 Created locks
LCK.wstat.destroy 0 0.00 Destroyed locks
LCK.wstat.locks 1659573 18.26 Lock Operations
MEMPOOL.busyobj.live 0 . In use
MEMPOOL.busyobj.pool 12 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_actual 65504 . Size allocated
MEMPOOL.busyobj.allocs 457400 5.03 Allocations
MEMPOOL.busyobj.frees 457400 5.03 Frees
MEMPOOL.busyobj.recycle 453100 4.98 Recycled from pool
MEMPOOL.busyobj.timeout 26814 0.29 Timed out from pool
MEMPOOL.busyobj.toosmall 0 0.00 Too small to recycle
MEMPOOL.busyobj.surplus 0 0.00 Too many for pool
MEMPOOL.busyobj.randry 4300 0.05 Pool ran dry
MEMPOOL.req0.live 0 . In use
MEMPOOL.req0.pool 10 . In Pool
MEMPOOL.req0.sz_wanted 65536 . Size requested
MEMPOOL.req0.sz_actual 65504 . Size allocated
MEMPOOL.req0.allocs 477754 5.26 Allocations
MEMPOOL.req0.frees 477754 5.26 Frees
MEMPOOL.req0.recycle 476619 5.24 Recycled from pool
MEMPOOL.req0.timeout 19941 0.22 Timed out from pool
MEMPOOL.req0.toosmall 0 0.00 Too small to recycle
MEMPOOL.req0.surplus 0 0.00 Too many for pool
MEMPOOL.req0.randry 1135 0.01 Pool ran dry
MEMPOOL.sess0.live 1 . In use
MEMPOOL.sess0.pool 10 . In Pool
MEMPOOL.sess0.sz_wanted 512 . Size requested
MEMPOOL.sess0.sz_actual 480 . Size allocated
MEMPOOL.sess0.allocs 462269 5.09 Allocations
MEMPOOL.sess0.frees 462268 5.09 Frees
MEMPOOL.sess0.recycle 461283 5.07 Recycled from pool
MEMPOOL.sess0.timeout 19885 0.22 Timed out from pool
MEMPOOL.sess0.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess0.surplus 0 0.00 Too many for pool
MEMPOOL.sess0.randry 986 0.01 Pool ran dry
LCK.sma.creat 2 0.00 Created locks
LCK.sma.destroy 0 0.00 Destroyed locks
LCK.sma.locks 2874986 31.63 Lock Operations
SMA.s0.c_req 810812 8.92 Allocator requests
SMA.s0.c_fail 0 0.00 Allocator failures
SMA.s0.c_bytes 9342858679 102776.07 Bytes allocated
SMA.s0.c_freed 9228279877 101515.65 Bytes freed
SMA.s0.g_alloc 26724 . Allocations outstanding
SMA.s0.g_bytes 114578802 . Bytes outstanding
SMA.s0.g_space 8274029198 . Bytes available
SMA.Transient.c_req 666957 7.34 Allocator requests
SMA.Transient.c_fail 0 0.00 Allocator failures
SMA.Transient.c_bytes 9471571306 104191.97 Bytes allocated
SMA.Transient.c_freed 9439387738 103837.94 Bytes freed
SMA.Transient.g_alloc 53827 . Allocations outstanding
SMA.Transient.g_bytes 32183568 . Bytes outstanding
SMA.Transient.g_space 0 . Bytes available
MEMPOOL.req1.live 0 . In use
MEMPOOL.req1.pool 10 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_actual 65504 . Size allocated
MEMPOOL.req1.allocs 486959 5.36 Allocations
MEMPOOL.req1.frees 486959 5.36 Frees
MEMPOOL.req1.recycle 485736 5.34 Recycled from pool
MEMPOOL.req1.timeout 20597 0.23 Timed out from pool
MEMPOOL.req1.toosmall 0 0.00 Too small to recycle
MEMPOOL.req1.surplus 0 0.00 Too many for pool
MEMPOOL.req1.randry 1223 0.01 Pool ran dry
MEMPOOL.sess1.live 1 . In use
MEMPOOL.sess1.pool 12 . In Pool
MEMPOOL.sess1.sz_wanted 512 . Size requested
MEMPOOL.sess1.sz_actual 480 . Size allocated
MEMPOOL.sess1.allocs 464706 5.11 Allocations
MEMPOOL.sess1.frees 464705 5.11 Frees
MEMPOOL.sess1.recycle 463561 5.10 Recycled from pool
MEMPOOL.sess1.timeout 19860 0.22 Timed out from pool
MEMPOOL.sess1.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess1.surplus 0 0.00 Too many for pool
MEMPOOL.sess1.randry 1145 0.01 Pool ran dry
VBE.boot.default.happy 0 . Happy health probes
VBE.boot.default.bereq_hdrbytes 376430490 4140.92 Request header bytes
VBE.boot.default.bereq_bodybytes 58796630 646.79 Request body bytes
VBE.boot.default.beresp_hdrbytes 303625397 3340.03 Response header bytes
VBE.boot.default.beresp_bodybytes 3569114775 39262.03 Response body bytes
VBE.boot.default.pipe_hdrbytes 160 0.00 Pipe request header bytes
VBE.boot.default.pipe_out 0 0.00 Piped bytes to backend
VBE.boot.default.pipe_in 680 0.01 Piped bytes from backend
VBE.boot.default.conn 0 . Concurrent connections to backend
VBE.boot.default.req 457400 5.03 Backend requests sent
varnishlog -q 'ReqURL ~ "^/category.html"'; MISS Example
* << Request >> 4767711
- Begin req 4767710 rxreq
- Timestamp Start: 1553598632.671737 0.000000 0.000000
- Timestamp Req: 1553598632.671737 0.000000 0.000000
- ReqStart 127.0.0.1 59282
- ReqMethod GET
- ReqURL /category.html
- ReqProtocol HTTP/1.0
- ReqHeader X-Real-IP: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Port: 443
- ReqHeader Host: www.magentostore.com
- ReqHeader Connection: close
- ReqHeader Accept: */*
- ReqUnset X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1, 127.0.0.1
- VCL_call RECV
- ReqHeader grace: none
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 4767712 fetch
- Timestamp Fetch: 1553598633.282252 0.610515 0.610515
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Tue, 26 Mar 2019 11:10:32 GMT
- RespHeader Server: Apache/2.4.6 (CentOS)
- RespHeader X-Powered-By: PHP/7.1.26
- RespHeader Pragma: cache
- RespHeader Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 4767711
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish (Varnish/5.2)
- VCL_call DELIVER
- RespUnset Age: 0
- RespUnset Pragma: cache
- RespHeader Pragma: no-cache
- RespUnset Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader Expires: -1
- RespUnset Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Cache-Control: no-store, no-cache, must-revalidate, max-age=0
- RespUnset X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespUnset X-Powered-By: PHP/7.1.26
- RespUnset Server: Apache/2.4.6 (CentOS)
- RespUnset X-Varnish: 4767711
- RespUnset Via: 1.1 varnish (Varnish/5.2)
- VCL_return deliver
- Timestamp Process: 1553598633.282310 0.610573 0.000057
- RespUnset Content-Encoding: gzip
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 149297
- RespHeader Connection: close
- Gzip U D - 24773 149297 80 198104 198114
- Timestamp Resp: 1553598633.283472 0.611735 0.001162
- ReqAcct 220 0 220 373 149297 149670
- End
The above example was warmed up a matter of mins previous and showed HIT so know this was in Varnish Cache just not sure why it's no longer there soon after.
magento2 cache varnish
add a comment |
I have setup varnish on my server and have used this with the default vcl provided by Magento 2 on my store. This has about 16,000 main pages (category, product, CMS) and want to store this all in the varnish cache. A warmup script is run each day which warms this up and for the first few days every page was stored in varnish fine with TTFB of about 40 - 60ms which was great.
Now however the cache mostly seems to be showing MISS in varnishlog for about half of requests and pages that were only warmed up a few mins ago seem to be showing MISS soon after. I have been very generous with memory here as have 24gb to play with and so originally gave it 4gb, and doubled it to 8gb but still the same issue occurs. MAIN.n_lru_nuked seems fine at 0 however so guess i'm looking in the wrong place.
I'm hoping someone can have a look over the Varnish stats below and suggest what may be causing this? I thought it may be Magento invalidating pages a bit hastily on saves or re-index but have had them invalidate without an index this morning so wondering if there is also a way to debug when a pages is becoming invalidated or a method to further debug this?
varnishstat -1
MGT.uptime 90904 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
MAIN.summs 2806804 30.88 stat summ operations
MAIN.uptime 90905 1.00 Child process uptime
MAIN.sess_conn 926975 10.20 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.client_req_400 31 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 938335 10.32 Good client requests received
MAIN.cache_hit 500846 5.51 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass.
MAIN.cache_hitmiss 2359 0.03 Cache hits for miss.
MAIN.cache_miss 253358 2.79 Cache misses
MAIN.backend_conn 206352 2.27 Backend conn. success
MAIN.backend_unhealthy 0 0.00 Backend conn. not attempted
MAIN.backend_busy 0 0.00 Backend conn. too many
MAIN.backend_fail 0 0.00 Backend conn. failures
MAIN.backend_reuse 250885 2.76 Backend conn. reuses
MAIN.backend_recycle 254263 2.80 Backend conn. recycles
MAIN.backend_retry 0 0.00 Backend conn. retry
MAIN.fetch_head 0 0.00 Fetch no body (HEAD)
MAIN.fetch_length 181357 2.00 Fetch with Length
MAIN.fetch_chunked 264446 2.91 Fetch chunked
MAIN.fetch_eof 6562 0.07 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_none 0 0.00 Fetch no body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 5034 0.06 Fetch no body (304)
MAIN.fetch_failed 0 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 200 . Total number of threads
MAIN.threads_limited 0 0.00 Threads hit max
MAIN.threads_created 200 0.00 Threads created
MAIN.threads_destroyed 0 0.00 Threads destroyed
MAIN.threads_failed 0 0.00 Thread creation failed
MAIN.thread_queue_len 0 . Length of session queue
MAIN.busy_sleep 972 0.01 Number of requests sent to sleep on busy objhdr
MAIN.busy_wakeup 972 0.01 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 0 0.00 Sessions queued for thread
MAIN.sess_dropped 0 0.00 Sessions dropped for thread
MAIN.req_dropped 0 0.00 Requests dropped
MAIN.n_object 64520 . object structs made
MAIN.n_vampireobject 0 . unresurrected objects
MAIN.n_objectcore 64620 . objectcore structs made
MAIN.n_objecthead 57476 . objecthead structs made
MAIN.n_backend 1 . Number of backends
MAIN.n_expired 0 . Number of expired objects
MAIN.n_lru_nuked 0 . Number of LRU nuked objects
MAIN.n_lru_moved 406691 . Number of LRU moved objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 926975 10.20 Total sessions seen
MAIN.s_pipe 1 0.00 Total pipe sessions seen
MAIN.s_pass 203230 2.24 Total pass-ed requests seen
MAIN.s_fetch 456588 5.02 Total backend fetches initiated
MAIN.s_synth 364 0.00 Total synthethic responses made
MAIN.s_req_hdrbytes 858808294 9447.32 Request header bytes
MAIN.s_req_bodybytes 58796630 646.79 Request body bytes
MAIN.s_resp_hdrbytes 336451106 3701.13 Response header bytes
MAIN.s_resp_bodybytes 45504621379 500573.36 Response body bytes
MAIN.s_pipe_hdrbytes 90 0.00 Pipe request header bytes
MAIN.s_pipe_in 0 0.00 Piped bytes from client
MAIN.s_pipe_out 680 0.01 Piped bytes to client
MAIN.sess_closed 919250 10.11 Session Closed
MAIN.sess_closed_err 985 0.01 Session Closed with error
MAIN.sess_readahead 11 0.00 Session Read Ahead
MAIN.sess_herd 19188 0.21 Session herd
MAIN.sc_rem_close 7006 0.08 Session OK REM_CLOSE
MAIN.sc_req_close 842716 9.27 Session OK REQ_CLOSE
MAIN.sc_req_http10 37 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 31 0.00 Session Err RX_JUNK
MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
MAIN.sc_rx_timeout 917 0.01 Session Err RX_TIMEOUT
MAIN.sc_tx_pipe 1 0.00 Session OK TX_PIPE
MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
MAIN.sc_tx_eof 76032 0.84 Session OK TX_EOF
MAIN.sc_resp_close 0 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.sc_req_http20 0 0.00 Session Err REQ_HTTP20
MAIN.sc_vcl_failure 0 0.00 Session Err VCL_FAILURE
MAIN.shm_records 103713157 1140.90 SHM records
MAIN.shm_writes 6390221 70.30 SHM writes
MAIN.shm_flushes 15491 0.17 SHM flushes due to overflow
MAIN.shm_cont 106846 1.18 SHM MTX contention
MAIN.shm_cycles 51 0.00 SHM cycles through buffer
MAIN.backend_req 457249 5.03 Backend requests made
MAIN.n_vcl 1 . Number of loaded VCLs in total
MAIN.n_vcl_avail 1 . Number of VCLs available
MAIN.n_vcl_discard 0 . Number of discarded VCLs
MAIN.vcl_fail 0 0.00 VCL failures
MAIN.bans 2 . Count of bans
MAIN.bans_completed 1 . Number of bans marked 'completed'
MAIN.bans_obj 2 . Number of bans using obj.*
MAIN.bans_req 0 . Number of bans using req.*
MAIN.bans_added 365 0.00 Bans added
MAIN.bans_deleted 363 0.00 Bans deleted
MAIN.bans_tested 15744 0.17 Bans tested against objects (lookup)
MAIN.bans_obj_killed 1033 0.01 Objects killed by bans (lookup)
MAIN.bans_lurker_tested 10719639 117.92 Bans tested against objects (lurker)
MAIN.bans_tests_tested 19834 0.22 Ban tests tested against objects (lookup)
MAIN.bans_lurker_tests_tested 10719639 117.92 Ban tests tested against objects (lurker)
MAIN.bans_lurker_obj_killed 186846 2.06 Objects killed by bans (lurker)
MAIN.bans_lurker_obj_killed_cutoff 0 0.00 Objects killed by bans for cutoff (lurker)
MAIN.bans_dups 22 0.00 Bans superseded by other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way for lookup
MAIN.bans_persisted_bytes 109136 . Bytes used by the persisted ban lists
MAIN.bans_persisted_fragmentation 108846 . 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 443817 4.88 Number of objects mailed to expiry thread
MAIN.exp_received 443691 4.88 Number of objects received by expiry thread
MAIN.hcb_nolock 754244 8.30 HCB Lookups without lock
MAIN.hcb_lock 244042 2.68 HCB Lookups with lock
MAIN.hcb_insert 244005 2.68 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse errors (unlock)
MAIN.esi_warnings 0 0.00 ESI parse warnings (unlock)
MAIN.vmods 1 . Loaded VMODs
MAIN.n_gzip 324801 3.57 Gzip operations
MAIN.n_gunzip 214393 2.36 Gunzip operations
MAIN.n_test_gunzip 0 0.00 Test gunzip operations
LCK.backend.creat 3 0.00 Created locks
LCK.backend.destroy 0 0.00 Destroyed locks
LCK.backend.locks 914803 10.06 Lock Operations
LCK.backend_tcp.creat 1 0.00 Created locks
LCK.backend_tcp.destroy 0 0.00 Destroyed locks
LCK.backend_tcp.locks 1419947 15.62 Lock Operations
LCK.ban.creat 1 0.00 Created locks
LCK.ban.destroy 0 0.00 Destroyed locks
LCK.ban.locks 21954558 241.51 Lock Operations
LCK.busyobj.creat 471560 5.19 Created locks
LCK.busyobj.destroy 472072 5.19 Destroyed locks
LCK.busyobj.locks 4644562 51.09 Lock Operations
LCK.cli.creat 1 0.00 Created locks
LCK.cli.destroy 0 0.00 Destroyed locks
LCK.cli.locks 30310 0.33 Lock Operations
LCK.exp.creat 1 0.00 Created locks
LCK.exp.destroy 0 0.00 Destroyed locks
LCK.exp.locks 1394596 15.34 Lock Operations
LCK.hcb.creat 1 0.00 Created locks
LCK.hcb.destroy 0 0.00 Destroyed locks
LCK.hcb.locks 431394 4.75 Lock Operations
LCK.lru.creat 2 0.00 Created locks
LCK.lru.destroy 0 0.00 Destroyed locks
LCK.lru.locks 850662 9.36 Lock Operations
LCK.mempool.creat 5 0.00 Created locks
LCK.mempool.destroy 0 0.00 Destroyed locks
LCK.mempool.locks 5230414 57.54 Lock Operations
LCK.objhdr.creat 243628 2.68 Created locks
LCK.objhdr.destroy 186669 2.05 Destroyed locks
LCK.objhdr.locks 28657093 315.24 Lock Operations
LCK.pipestat.creat 1 0.00 Created locks
LCK.pipestat.destroy 0 0.00 Destroyed locks
LCK.pipestat.locks 1 0.00 Lock Operations
LCK.sess.creat 926777 10.20 Created locks
LCK.sess.destroy 926953 10.20 Destroyed locks
LCK.sess.locks 1894787 20.84 Lock Operations
LCK.vbe.creat 1 0.00 Created locks
LCK.vbe.destroy 0 0.00 Destroyed locks
LCK.vbe.locks 30303 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 936781 10.31 Lock Operations
LCK.vxid.creat 1 0.00 Created locks
LCK.vxid.destroy 0 0.00 Destroyed locks
LCK.vxid.locks 151 0.00 Lock Operations
LCK.waiter.creat 2 0.00 Created locks
LCK.waiter.destroy 0 0.00 Destroyed locks
LCK.waiter.locks 871776 9.59 Lock Operations
LCK.wq.creat 3 0.00 Created locks
LCK.wq.destroy 0 0.00 Destroyed locks
LCK.wq.locks 4301794 47.32 Lock Operations
LCK.wstat.creat 1 0.00 Created locks
LCK.wstat.destroy 0 0.00 Destroyed locks
LCK.wstat.locks 1659573 18.26 Lock Operations
MEMPOOL.busyobj.live 0 . In use
MEMPOOL.busyobj.pool 12 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_actual 65504 . Size allocated
MEMPOOL.busyobj.allocs 457400 5.03 Allocations
MEMPOOL.busyobj.frees 457400 5.03 Frees
MEMPOOL.busyobj.recycle 453100 4.98 Recycled from pool
MEMPOOL.busyobj.timeout 26814 0.29 Timed out from pool
MEMPOOL.busyobj.toosmall 0 0.00 Too small to recycle
MEMPOOL.busyobj.surplus 0 0.00 Too many for pool
MEMPOOL.busyobj.randry 4300 0.05 Pool ran dry
MEMPOOL.req0.live 0 . In use
MEMPOOL.req0.pool 10 . In Pool
MEMPOOL.req0.sz_wanted 65536 . Size requested
MEMPOOL.req0.sz_actual 65504 . Size allocated
MEMPOOL.req0.allocs 477754 5.26 Allocations
MEMPOOL.req0.frees 477754 5.26 Frees
MEMPOOL.req0.recycle 476619 5.24 Recycled from pool
MEMPOOL.req0.timeout 19941 0.22 Timed out from pool
MEMPOOL.req0.toosmall 0 0.00 Too small to recycle
MEMPOOL.req0.surplus 0 0.00 Too many for pool
MEMPOOL.req0.randry 1135 0.01 Pool ran dry
MEMPOOL.sess0.live 1 . In use
MEMPOOL.sess0.pool 10 . In Pool
MEMPOOL.sess0.sz_wanted 512 . Size requested
MEMPOOL.sess0.sz_actual 480 . Size allocated
MEMPOOL.sess0.allocs 462269 5.09 Allocations
MEMPOOL.sess0.frees 462268 5.09 Frees
MEMPOOL.sess0.recycle 461283 5.07 Recycled from pool
MEMPOOL.sess0.timeout 19885 0.22 Timed out from pool
MEMPOOL.sess0.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess0.surplus 0 0.00 Too many for pool
MEMPOOL.sess0.randry 986 0.01 Pool ran dry
LCK.sma.creat 2 0.00 Created locks
LCK.sma.destroy 0 0.00 Destroyed locks
LCK.sma.locks 2874986 31.63 Lock Operations
SMA.s0.c_req 810812 8.92 Allocator requests
SMA.s0.c_fail 0 0.00 Allocator failures
SMA.s0.c_bytes 9342858679 102776.07 Bytes allocated
SMA.s0.c_freed 9228279877 101515.65 Bytes freed
SMA.s0.g_alloc 26724 . Allocations outstanding
SMA.s0.g_bytes 114578802 . Bytes outstanding
SMA.s0.g_space 8274029198 . Bytes available
SMA.Transient.c_req 666957 7.34 Allocator requests
SMA.Transient.c_fail 0 0.00 Allocator failures
SMA.Transient.c_bytes 9471571306 104191.97 Bytes allocated
SMA.Transient.c_freed 9439387738 103837.94 Bytes freed
SMA.Transient.g_alloc 53827 . Allocations outstanding
SMA.Transient.g_bytes 32183568 . Bytes outstanding
SMA.Transient.g_space 0 . Bytes available
MEMPOOL.req1.live 0 . In use
MEMPOOL.req1.pool 10 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_actual 65504 . Size allocated
MEMPOOL.req1.allocs 486959 5.36 Allocations
MEMPOOL.req1.frees 486959 5.36 Frees
MEMPOOL.req1.recycle 485736 5.34 Recycled from pool
MEMPOOL.req1.timeout 20597 0.23 Timed out from pool
MEMPOOL.req1.toosmall 0 0.00 Too small to recycle
MEMPOOL.req1.surplus 0 0.00 Too many for pool
MEMPOOL.req1.randry 1223 0.01 Pool ran dry
MEMPOOL.sess1.live 1 . In use
MEMPOOL.sess1.pool 12 . In Pool
MEMPOOL.sess1.sz_wanted 512 . Size requested
MEMPOOL.sess1.sz_actual 480 . Size allocated
MEMPOOL.sess1.allocs 464706 5.11 Allocations
MEMPOOL.sess1.frees 464705 5.11 Frees
MEMPOOL.sess1.recycle 463561 5.10 Recycled from pool
MEMPOOL.sess1.timeout 19860 0.22 Timed out from pool
MEMPOOL.sess1.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess1.surplus 0 0.00 Too many for pool
MEMPOOL.sess1.randry 1145 0.01 Pool ran dry
VBE.boot.default.happy 0 . Happy health probes
VBE.boot.default.bereq_hdrbytes 376430490 4140.92 Request header bytes
VBE.boot.default.bereq_bodybytes 58796630 646.79 Request body bytes
VBE.boot.default.beresp_hdrbytes 303625397 3340.03 Response header bytes
VBE.boot.default.beresp_bodybytes 3569114775 39262.03 Response body bytes
VBE.boot.default.pipe_hdrbytes 160 0.00 Pipe request header bytes
VBE.boot.default.pipe_out 0 0.00 Piped bytes to backend
VBE.boot.default.pipe_in 680 0.01 Piped bytes from backend
VBE.boot.default.conn 0 . Concurrent connections to backend
VBE.boot.default.req 457400 5.03 Backend requests sent
varnishlog -q 'ReqURL ~ "^/category.html"'; MISS Example
* << Request >> 4767711
- Begin req 4767710 rxreq
- Timestamp Start: 1553598632.671737 0.000000 0.000000
- Timestamp Req: 1553598632.671737 0.000000 0.000000
- ReqStart 127.0.0.1 59282
- ReqMethod GET
- ReqURL /category.html
- ReqProtocol HTTP/1.0
- ReqHeader X-Real-IP: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Port: 443
- ReqHeader Host: www.magentostore.com
- ReqHeader Connection: close
- ReqHeader Accept: */*
- ReqUnset X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1, 127.0.0.1
- VCL_call RECV
- ReqHeader grace: none
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 4767712 fetch
- Timestamp Fetch: 1553598633.282252 0.610515 0.610515
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Tue, 26 Mar 2019 11:10:32 GMT
- RespHeader Server: Apache/2.4.6 (CentOS)
- RespHeader X-Powered-By: PHP/7.1.26
- RespHeader Pragma: cache
- RespHeader Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 4767711
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish (Varnish/5.2)
- VCL_call DELIVER
- RespUnset Age: 0
- RespUnset Pragma: cache
- RespHeader Pragma: no-cache
- RespUnset Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader Expires: -1
- RespUnset Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Cache-Control: no-store, no-cache, must-revalidate, max-age=0
- RespUnset X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespUnset X-Powered-By: PHP/7.1.26
- RespUnset Server: Apache/2.4.6 (CentOS)
- RespUnset X-Varnish: 4767711
- RespUnset Via: 1.1 varnish (Varnish/5.2)
- VCL_return deliver
- Timestamp Process: 1553598633.282310 0.610573 0.000057
- RespUnset Content-Encoding: gzip
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 149297
- RespHeader Connection: close
- Gzip U D - 24773 149297 80 198104 198114
- Timestamp Resp: 1553598633.283472 0.611735 0.001162
- ReqAcct 220 0 220 373 149297 149670
- End
The above example was warmed up a matter of mins previous and showed HIT so know this was in Varnish Cache just not sure why it's no longer there soon after.
magento2 cache varnish
I have setup varnish on my server and have used this with the default vcl provided by Magento 2 on my store. This has about 16,000 main pages (category, product, CMS) and want to store this all in the varnish cache. A warmup script is run each day which warms this up and for the first few days every page was stored in varnish fine with TTFB of about 40 - 60ms which was great.
Now however the cache mostly seems to be showing MISS in varnishlog for about half of requests and pages that were only warmed up a few mins ago seem to be showing MISS soon after. I have been very generous with memory here as have 24gb to play with and so originally gave it 4gb, and doubled it to 8gb but still the same issue occurs. MAIN.n_lru_nuked seems fine at 0 however so guess i'm looking in the wrong place.
I'm hoping someone can have a look over the Varnish stats below and suggest what may be causing this? I thought it may be Magento invalidating pages a bit hastily on saves or re-index but have had them invalidate without an index this morning so wondering if there is also a way to debug when a pages is becoming invalidated or a method to further debug this?
varnishstat -1
MGT.uptime 90904 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
MAIN.summs 2806804 30.88 stat summ operations
MAIN.uptime 90905 1.00 Child process uptime
MAIN.sess_conn 926975 10.20 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.client_req_400 31 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 938335 10.32 Good client requests received
MAIN.cache_hit 500846 5.51 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass.
MAIN.cache_hitmiss 2359 0.03 Cache hits for miss.
MAIN.cache_miss 253358 2.79 Cache misses
MAIN.backend_conn 206352 2.27 Backend conn. success
MAIN.backend_unhealthy 0 0.00 Backend conn. not attempted
MAIN.backend_busy 0 0.00 Backend conn. too many
MAIN.backend_fail 0 0.00 Backend conn. failures
MAIN.backend_reuse 250885 2.76 Backend conn. reuses
MAIN.backend_recycle 254263 2.80 Backend conn. recycles
MAIN.backend_retry 0 0.00 Backend conn. retry
MAIN.fetch_head 0 0.00 Fetch no body (HEAD)
MAIN.fetch_length 181357 2.00 Fetch with Length
MAIN.fetch_chunked 264446 2.91 Fetch chunked
MAIN.fetch_eof 6562 0.07 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_none 0 0.00 Fetch no body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 5034 0.06 Fetch no body (304)
MAIN.fetch_failed 0 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 200 . Total number of threads
MAIN.threads_limited 0 0.00 Threads hit max
MAIN.threads_created 200 0.00 Threads created
MAIN.threads_destroyed 0 0.00 Threads destroyed
MAIN.threads_failed 0 0.00 Thread creation failed
MAIN.thread_queue_len 0 . Length of session queue
MAIN.busy_sleep 972 0.01 Number of requests sent to sleep on busy objhdr
MAIN.busy_wakeup 972 0.01 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 0 0.00 Sessions queued for thread
MAIN.sess_dropped 0 0.00 Sessions dropped for thread
MAIN.req_dropped 0 0.00 Requests dropped
MAIN.n_object 64520 . object structs made
MAIN.n_vampireobject 0 . unresurrected objects
MAIN.n_objectcore 64620 . objectcore structs made
MAIN.n_objecthead 57476 . objecthead structs made
MAIN.n_backend 1 . Number of backends
MAIN.n_expired 0 . Number of expired objects
MAIN.n_lru_nuked 0 . Number of LRU nuked objects
MAIN.n_lru_moved 406691 . Number of LRU moved objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 926975 10.20 Total sessions seen
MAIN.s_pipe 1 0.00 Total pipe sessions seen
MAIN.s_pass 203230 2.24 Total pass-ed requests seen
MAIN.s_fetch 456588 5.02 Total backend fetches initiated
MAIN.s_synth 364 0.00 Total synthethic responses made
MAIN.s_req_hdrbytes 858808294 9447.32 Request header bytes
MAIN.s_req_bodybytes 58796630 646.79 Request body bytes
MAIN.s_resp_hdrbytes 336451106 3701.13 Response header bytes
MAIN.s_resp_bodybytes 45504621379 500573.36 Response body bytes
MAIN.s_pipe_hdrbytes 90 0.00 Pipe request header bytes
MAIN.s_pipe_in 0 0.00 Piped bytes from client
MAIN.s_pipe_out 680 0.01 Piped bytes to client
MAIN.sess_closed 919250 10.11 Session Closed
MAIN.sess_closed_err 985 0.01 Session Closed with error
MAIN.sess_readahead 11 0.00 Session Read Ahead
MAIN.sess_herd 19188 0.21 Session herd
MAIN.sc_rem_close 7006 0.08 Session OK REM_CLOSE
MAIN.sc_req_close 842716 9.27 Session OK REQ_CLOSE
MAIN.sc_req_http10 37 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 31 0.00 Session Err RX_JUNK
MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
MAIN.sc_rx_timeout 917 0.01 Session Err RX_TIMEOUT
MAIN.sc_tx_pipe 1 0.00 Session OK TX_PIPE
MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
MAIN.sc_tx_eof 76032 0.84 Session OK TX_EOF
MAIN.sc_resp_close 0 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.sc_req_http20 0 0.00 Session Err REQ_HTTP20
MAIN.sc_vcl_failure 0 0.00 Session Err VCL_FAILURE
MAIN.shm_records 103713157 1140.90 SHM records
MAIN.shm_writes 6390221 70.30 SHM writes
MAIN.shm_flushes 15491 0.17 SHM flushes due to overflow
MAIN.shm_cont 106846 1.18 SHM MTX contention
MAIN.shm_cycles 51 0.00 SHM cycles through buffer
MAIN.backend_req 457249 5.03 Backend requests made
MAIN.n_vcl 1 . Number of loaded VCLs in total
MAIN.n_vcl_avail 1 . Number of VCLs available
MAIN.n_vcl_discard 0 . Number of discarded VCLs
MAIN.vcl_fail 0 0.00 VCL failures
MAIN.bans 2 . Count of bans
MAIN.bans_completed 1 . Number of bans marked 'completed'
MAIN.bans_obj 2 . Number of bans using obj.*
MAIN.bans_req 0 . Number of bans using req.*
MAIN.bans_added 365 0.00 Bans added
MAIN.bans_deleted 363 0.00 Bans deleted
MAIN.bans_tested 15744 0.17 Bans tested against objects (lookup)
MAIN.bans_obj_killed 1033 0.01 Objects killed by bans (lookup)
MAIN.bans_lurker_tested 10719639 117.92 Bans tested against objects (lurker)
MAIN.bans_tests_tested 19834 0.22 Ban tests tested against objects (lookup)
MAIN.bans_lurker_tests_tested 10719639 117.92 Ban tests tested against objects (lurker)
MAIN.bans_lurker_obj_killed 186846 2.06 Objects killed by bans (lurker)
MAIN.bans_lurker_obj_killed_cutoff 0 0.00 Objects killed by bans for cutoff (lurker)
MAIN.bans_dups 22 0.00 Bans superseded by other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way for lookup
MAIN.bans_persisted_bytes 109136 . Bytes used by the persisted ban lists
MAIN.bans_persisted_fragmentation 108846 . 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 443817 4.88 Number of objects mailed to expiry thread
MAIN.exp_received 443691 4.88 Number of objects received by expiry thread
MAIN.hcb_nolock 754244 8.30 HCB Lookups without lock
MAIN.hcb_lock 244042 2.68 HCB Lookups with lock
MAIN.hcb_insert 244005 2.68 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse errors (unlock)
MAIN.esi_warnings 0 0.00 ESI parse warnings (unlock)
MAIN.vmods 1 . Loaded VMODs
MAIN.n_gzip 324801 3.57 Gzip operations
MAIN.n_gunzip 214393 2.36 Gunzip operations
MAIN.n_test_gunzip 0 0.00 Test gunzip operations
LCK.backend.creat 3 0.00 Created locks
LCK.backend.destroy 0 0.00 Destroyed locks
LCK.backend.locks 914803 10.06 Lock Operations
LCK.backend_tcp.creat 1 0.00 Created locks
LCK.backend_tcp.destroy 0 0.00 Destroyed locks
LCK.backend_tcp.locks 1419947 15.62 Lock Operations
LCK.ban.creat 1 0.00 Created locks
LCK.ban.destroy 0 0.00 Destroyed locks
LCK.ban.locks 21954558 241.51 Lock Operations
LCK.busyobj.creat 471560 5.19 Created locks
LCK.busyobj.destroy 472072 5.19 Destroyed locks
LCK.busyobj.locks 4644562 51.09 Lock Operations
LCK.cli.creat 1 0.00 Created locks
LCK.cli.destroy 0 0.00 Destroyed locks
LCK.cli.locks 30310 0.33 Lock Operations
LCK.exp.creat 1 0.00 Created locks
LCK.exp.destroy 0 0.00 Destroyed locks
LCK.exp.locks 1394596 15.34 Lock Operations
LCK.hcb.creat 1 0.00 Created locks
LCK.hcb.destroy 0 0.00 Destroyed locks
LCK.hcb.locks 431394 4.75 Lock Operations
LCK.lru.creat 2 0.00 Created locks
LCK.lru.destroy 0 0.00 Destroyed locks
LCK.lru.locks 850662 9.36 Lock Operations
LCK.mempool.creat 5 0.00 Created locks
LCK.mempool.destroy 0 0.00 Destroyed locks
LCK.mempool.locks 5230414 57.54 Lock Operations
LCK.objhdr.creat 243628 2.68 Created locks
LCK.objhdr.destroy 186669 2.05 Destroyed locks
LCK.objhdr.locks 28657093 315.24 Lock Operations
LCK.pipestat.creat 1 0.00 Created locks
LCK.pipestat.destroy 0 0.00 Destroyed locks
LCK.pipestat.locks 1 0.00 Lock Operations
LCK.sess.creat 926777 10.20 Created locks
LCK.sess.destroy 926953 10.20 Destroyed locks
LCK.sess.locks 1894787 20.84 Lock Operations
LCK.vbe.creat 1 0.00 Created locks
LCK.vbe.destroy 0 0.00 Destroyed locks
LCK.vbe.locks 30303 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 936781 10.31 Lock Operations
LCK.vxid.creat 1 0.00 Created locks
LCK.vxid.destroy 0 0.00 Destroyed locks
LCK.vxid.locks 151 0.00 Lock Operations
LCK.waiter.creat 2 0.00 Created locks
LCK.waiter.destroy 0 0.00 Destroyed locks
LCK.waiter.locks 871776 9.59 Lock Operations
LCK.wq.creat 3 0.00 Created locks
LCK.wq.destroy 0 0.00 Destroyed locks
LCK.wq.locks 4301794 47.32 Lock Operations
LCK.wstat.creat 1 0.00 Created locks
LCK.wstat.destroy 0 0.00 Destroyed locks
LCK.wstat.locks 1659573 18.26 Lock Operations
MEMPOOL.busyobj.live 0 . In use
MEMPOOL.busyobj.pool 12 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_actual 65504 . Size allocated
MEMPOOL.busyobj.allocs 457400 5.03 Allocations
MEMPOOL.busyobj.frees 457400 5.03 Frees
MEMPOOL.busyobj.recycle 453100 4.98 Recycled from pool
MEMPOOL.busyobj.timeout 26814 0.29 Timed out from pool
MEMPOOL.busyobj.toosmall 0 0.00 Too small to recycle
MEMPOOL.busyobj.surplus 0 0.00 Too many for pool
MEMPOOL.busyobj.randry 4300 0.05 Pool ran dry
MEMPOOL.req0.live 0 . In use
MEMPOOL.req0.pool 10 . In Pool
MEMPOOL.req0.sz_wanted 65536 . Size requested
MEMPOOL.req0.sz_actual 65504 . Size allocated
MEMPOOL.req0.allocs 477754 5.26 Allocations
MEMPOOL.req0.frees 477754 5.26 Frees
MEMPOOL.req0.recycle 476619 5.24 Recycled from pool
MEMPOOL.req0.timeout 19941 0.22 Timed out from pool
MEMPOOL.req0.toosmall 0 0.00 Too small to recycle
MEMPOOL.req0.surplus 0 0.00 Too many for pool
MEMPOOL.req0.randry 1135 0.01 Pool ran dry
MEMPOOL.sess0.live 1 . In use
MEMPOOL.sess0.pool 10 . In Pool
MEMPOOL.sess0.sz_wanted 512 . Size requested
MEMPOOL.sess0.sz_actual 480 . Size allocated
MEMPOOL.sess0.allocs 462269 5.09 Allocations
MEMPOOL.sess0.frees 462268 5.09 Frees
MEMPOOL.sess0.recycle 461283 5.07 Recycled from pool
MEMPOOL.sess0.timeout 19885 0.22 Timed out from pool
MEMPOOL.sess0.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess0.surplus 0 0.00 Too many for pool
MEMPOOL.sess0.randry 986 0.01 Pool ran dry
LCK.sma.creat 2 0.00 Created locks
LCK.sma.destroy 0 0.00 Destroyed locks
LCK.sma.locks 2874986 31.63 Lock Operations
SMA.s0.c_req 810812 8.92 Allocator requests
SMA.s0.c_fail 0 0.00 Allocator failures
SMA.s0.c_bytes 9342858679 102776.07 Bytes allocated
SMA.s0.c_freed 9228279877 101515.65 Bytes freed
SMA.s0.g_alloc 26724 . Allocations outstanding
SMA.s0.g_bytes 114578802 . Bytes outstanding
SMA.s0.g_space 8274029198 . Bytes available
SMA.Transient.c_req 666957 7.34 Allocator requests
SMA.Transient.c_fail 0 0.00 Allocator failures
SMA.Transient.c_bytes 9471571306 104191.97 Bytes allocated
SMA.Transient.c_freed 9439387738 103837.94 Bytes freed
SMA.Transient.g_alloc 53827 . Allocations outstanding
SMA.Transient.g_bytes 32183568 . Bytes outstanding
SMA.Transient.g_space 0 . Bytes available
MEMPOOL.req1.live 0 . In use
MEMPOOL.req1.pool 10 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_actual 65504 . Size allocated
MEMPOOL.req1.allocs 486959 5.36 Allocations
MEMPOOL.req1.frees 486959 5.36 Frees
MEMPOOL.req1.recycle 485736 5.34 Recycled from pool
MEMPOOL.req1.timeout 20597 0.23 Timed out from pool
MEMPOOL.req1.toosmall 0 0.00 Too small to recycle
MEMPOOL.req1.surplus 0 0.00 Too many for pool
MEMPOOL.req1.randry 1223 0.01 Pool ran dry
MEMPOOL.sess1.live 1 . In use
MEMPOOL.sess1.pool 12 . In Pool
MEMPOOL.sess1.sz_wanted 512 . Size requested
MEMPOOL.sess1.sz_actual 480 . Size allocated
MEMPOOL.sess1.allocs 464706 5.11 Allocations
MEMPOOL.sess1.frees 464705 5.11 Frees
MEMPOOL.sess1.recycle 463561 5.10 Recycled from pool
MEMPOOL.sess1.timeout 19860 0.22 Timed out from pool
MEMPOOL.sess1.toosmall 0 0.00 Too small to recycle
MEMPOOL.sess1.surplus 0 0.00 Too many for pool
MEMPOOL.sess1.randry 1145 0.01 Pool ran dry
VBE.boot.default.happy 0 . Happy health probes
VBE.boot.default.bereq_hdrbytes 376430490 4140.92 Request header bytes
VBE.boot.default.bereq_bodybytes 58796630 646.79 Request body bytes
VBE.boot.default.beresp_hdrbytes 303625397 3340.03 Response header bytes
VBE.boot.default.beresp_bodybytes 3569114775 39262.03 Response body bytes
VBE.boot.default.pipe_hdrbytes 160 0.00 Pipe request header bytes
VBE.boot.default.pipe_out 0 0.00 Piped bytes to backend
VBE.boot.default.pipe_in 680 0.01 Piped bytes from backend
VBE.boot.default.conn 0 . Concurrent connections to backend
VBE.boot.default.req 457400 5.03 Backend requests sent
varnishlog -q 'ReqURL ~ "^/category.html"'; MISS Example
* << Request >> 4767711
- Begin req 4767710 rxreq
- Timestamp Start: 1553598632.671737 0.000000 0.000000
- Timestamp Req: 1553598632.671737 0.000000 0.000000
- ReqStart 127.0.0.1 59282
- ReqMethod GET
- ReqURL /category.html
- ReqProtocol HTTP/1.0
- ReqHeader X-Real-IP: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Port: 443
- ReqHeader Host: www.magentostore.com
- ReqHeader Connection: close
- ReqHeader Accept: */*
- ReqUnset X-Forwarded-For: 127.0.0.1
- ReqHeader X-Forwarded-For: 127.0.0.1, 127.0.0.1
- VCL_call RECV
- ReqHeader grace: none
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- ReqURL /category.html
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 4767712 fetch
- Timestamp Fetch: 1553598633.282252 0.610515 0.610515
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Tue, 26 Mar 2019 11:10:32 GMT
- RespHeader Server: Apache/2.4.6 (CentOS)
- RespHeader X-Powered-By: PHP/7.1.26
- RespHeader Pragma: cache
- RespHeader Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader Content-Encoding: gzip
- RespHeader Vary: Accept-Encoding
- RespHeader X-Varnish: 4767711
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish (Varnish/5.2)
- VCL_call DELIVER
- RespUnset Age: 0
- RespUnset Pragma: cache
- RespHeader Pragma: no-cache
- RespUnset Expires: Thu, 28 Mar 2019 14:57:12 GMT
- RespHeader Expires: -1
- RespUnset Cache-Control: max-age=186400, public, s-maxage=186400
- RespHeader Cache-Control: no-store, no-cache, must-revalidate, max-age=0
- RespUnset X-Magento-Tags: store,cms_b,cat_c,cat_c_644,cat_c_79,cat_c_109,cat_c_143,cat_c_182,cat_c_702,cat_c_257,cat_c_304,cat_c_342,cms_b_print_header,cms_b_usp,cms_b_social_links,cms_b_payment_methods,cat_c_726,cat_c_p_726,cms_b_iwtoplinks,cms_b_account-promo,cm
- RespUnset X-Powered-By: PHP/7.1.26
- RespUnset Server: Apache/2.4.6 (CentOS)
- RespUnset X-Varnish: 4767711
- RespUnset Via: 1.1 varnish (Varnish/5.2)
- VCL_return deliver
- Timestamp Process: 1553598633.282310 0.610573 0.000057
- RespUnset Content-Encoding: gzip
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 149297
- RespHeader Connection: close
- Gzip U D - 24773 149297 80 198104 198114
- Timestamp Resp: 1553598633.283472 0.611735 0.001162
- ReqAcct 220 0 220 373 149297 149670
- End
The above example was warmed up a matter of mins previous and showed HIT so know this was in Varnish Cache just not sure why it's no longer there soon after.
magento2 cache varnish
magento2 cache varnish
asked yesterday
harriharri
3,0261655
3,0261655
add a comment |
add a comment |
0
active
oldest
votes
Your Answer
StackExchange.ready(function()
var channelOptions =
tags: "".split(" "),
id: "479"
;
initTagRenderer("".split(" "), "".split(" "), channelOptions);
StackExchange.using("externalEditor", function()
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled)
StackExchange.using("snippets", function()
createEditor();
);
else
createEditor();
);
function createEditor()
StackExchange.prepareEditor(
heartbeatType: 'answer',
autoActivateHeartbeat: false,
convertImagesToLinks: false,
noModals: true,
showLowRepImageUploadWarning: true,
reputationToPostImages: null,
bindNavPrevention: true,
postfix: "",
imageUploader:
brandingHtml: "Powered by u003ca class="icon-imgur-white" href="https://imgur.com/"u003eu003c/au003e",
contentPolicyHtml: "User contributions licensed under u003ca href="https://creativecommons.org/licenses/by-sa/3.0/"u003ecc by-sa 3.0 with attribution requiredu003c/au003e u003ca href="https://stackoverflow.com/legal/content-policy"u003e(content policy)u003c/au003e",
allowUrls: true
,
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
);
);
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fmagento.stackexchange.com%2fquestions%2f267449%2fvarnish-cache-pages-being-invalidated-too-soon-magento-2%23new-answer', 'question_page');
);
Post as a guest
Required, but never shown
0
active
oldest
votes
0
active
oldest
votes
active
oldest
votes
active
oldest
votes
Thanks for contributing an answer to Magento Stack Exchange!
- Please be sure to answer the question. Provide details and share your research!
But avoid …
- Asking for help, clarification, or responding to other answers.
- Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2fmagento.stackexchange.com%2fquestions%2f267449%2fvarnish-cache-pages-being-invalidated-too-soon-magento-2%23new-answer', 'question_page');
);
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Sign up or log in
StackExchange.ready(function ()
StackExchange.helpers.onClickDraftSave('#login-link');
);
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Sign up using Google
Sign up using Facebook
Sign up using Email and Password
Post as a guest
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown
Required, but never shown