0

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.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.