Weird 5 seconds delay
Kevin Lemonnier
kevin.lemonnier at cognix-systems.com
Tue Jul 11 14:57:59 CEST 2017
Hi,
I've posted on serverfault and on IRC, but since this is a bit (or very)
urgent, I'll try it here too.
I have a strange problem with varnish, it's in front of an API and it's
caching the whole responses. It mostly works fine, but from time to time
a request will take 5 seconds (or rarely 10 seconds, or 15 seconds ..
always an increment of 5) more than usual to return.
I've tried bypassing the HAProxy in front, same, and I checked, it does
that whether the URL is already cached or not (I've checked the Age
header). So it can't be the backend since the page is in cache, it's not
what's in front of varnish, that leaves only varnish itself as the cause
of that problem.
Any idea as to what could cause that 5 seconds delay ? I've checked
varnishlog, during that delay varnish isn't doing anything. I've also
tried manually making another request during that delay, and varnish
answered fine so it's not frozen or anything, it works fine. And at the
end of that 5 seconds, it's outputting the log for the request as usual,
nothing weird in it. Example :
* << Request >> 132712
* Begin req 132711 rxreq
* Timestamp Start: 1499701302.309413 0.000000 0.000000
* Timestamp Req: 1499701302.309413 0.000000 0.000000
* ReqStart 127.0.0.1 43955
* ReqMethod GET
* ReqURL /url
* ReqProtocol HTTP/1.1
* ReqHeader User-Agent: curl/7.38.0
* ReqHeader Host: host
* ReqHeader Accept: ///
* ReqHeader X-Forwarded-Proto: https
* ReqHeader X-Forwarded-For: ip
* ReqHeader Connection: close
* ReqUnset X-Forwarded-For: ip
* ReqHeader X-Forwarded-For: ip, 127.0.0.1
* VCL_call RECV
* ReqUnset X-Forwarded-For: ip, 127.0.0.1
* ReqHeader X-Forwarded-For: ip, 127.0.0.1, 127.0.0.1
* VCL_return hash
* VCL_call HASH
* VCL_return lookup
* Hit 2147582482
* VCL_call HIT
* VCL_return deliver
* RespProtocol HTTP/1.1
* RespStatus 200
* RespReason OK
* RespHeader Date: Mon, 10 Jul 2017 15:10:00 GMT
* RespHeader Server: gunicorn/19.7.1
* RespHeader content-type: application/json; charset=UTF-8
* RespHeader X-Varnish: 132712 98834
* RespHeader Age: 1902
* RespHeader Via: 1.1 varnish-v4
* VCL_call DELIVER
* RespHeader X-Cacheable: YES
* RespUnset Server: gunicorn/19.7.1
* RespUnset Via: 1.1 varnish-v4
* RespUnset X-Varnish: 132712 98834
* VCL_return deliver
* Timestamp Process: 1499701302.309480 0.000067 0.000067
* RespHeader Content-Length: 251799
* Debug "RES_MODE 2"
* RespHeader Connection: close
* RespHeader Accept-Ranges: bytes
* Timestamp Resp: 1499701302.309571 0.000159 0.000092
* Debug "XXX REF 2"
* ReqAcct 198 0 198 197 251799 251996
* End
I realize varnish believes that was treated quickly, but on curl's side
it took 5 seconds. Curl is used directly on the varnish server, so it's
not network latency. It's a bit hard to reproduce, I'm using a script
that does queries in a loop and shows the curl time_total to finally get
it to happen.
Could it be something Linux side ? Maybe some kind of limit, or a socket
cleanup job or something that would pause the request. It happens maybe
once every 400 or 500 requests, sometimes more, sometimes less.
Attached is the varnishstat -1 asked on the mailing list page.
--
Kevin
-------------- next part --------------
MAIN.uptime 14218 1.00 Child process uptime
MAIN.sess_conn 8750 0.62 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.sess_pipe_overflow 0 0.00 Session pipe overflow
MAIN.client_req_400 0 0.00 Client requests received,
subject to 400 errors
MAIN.client_req_411 0 0.00 Client requests received,
subject to 411 errors
MAIN.client_req_413 0 0.00 Client requests received,
subject to 413 errors
MAIN.client_req_417 0 0.00 Client requests received,
subject to 417 errors
MAIN.client_req 9629 0.68 Good Client requests
received
MAIN.cache_hit 5218 0.37 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass
MAIN.cache_miss 4142 0.29 Cache misses
MAIN.backend_conn 34 0.00 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 4132 0.29 Backend conn. reuses
MAIN.backend_toolate 23 0.00 Backend conn. was closed
MAIN.backend_recycle 4163 0.29 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 2543 0.18 Fetch with Length
MAIN.fetch_chunked 1622 0.11 Fetch chunked
MAIN.fetch_eof 0 0.00 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_close 0 0.00 Fetch wanted close
MAIN.fetch_oldhttp 0 0.00 Fetch pre HTTP/1.1 closed
MAIN.fetch_zero 0 0.00 Fetch zero len body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 0 0.00 Fetch no body (304)
MAIN.fetch_failed 0 0.00 Fetch body failed
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.01 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 4 0.00 Number of requests sent to
sleep on busy objhdr
MAIN.busy_wakeup 4 0.00 Number of requests woken
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.n_object 3477 . N struct object
MAIN.n_vampireobject 0 . N unresurrected objects
MAIN.n_objectcore 3485 . N struct objectcore
MAIN.n_objecthead 3486 . N struct objecthead
MAIN.n_waitinglist 41 . N struct waitinglist
MAIN.n_backend 1 . N backends
MAIN.n_expired 201 . N expired objects
MAIN.n_lru_nuked 0 . N LRU nuked objects
MAIN.n_lru_moved 4779 . N LRU moved objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 8750 0.62 Total Sessions
MAIN.s_req 9629 0.68 Total Requests
MAIN.s_pipe 0 0.00 Total pipe
MAIN.s_pass 23 0.00 Total pass
MAIN.s_fetch 4165 0.29 Total fetch
MAIN.s_synth 246 0.02 Total synth
MAIN.s_req_hdrbytes 4837934 340.27 Request header bytes
MAIN.s_req_bodybytes 0 0.00 Request body bytes
MAIN.s_resp_hdrbytes 2206256 155.17 Response header bytes
MAIN.s_resp_bodybytes 303132867 21320.36 Reponse body bytes
MAIN.s_pipe_hdrbytes 0 0.00 Pipe request header bytes
MAIN.s_pipe_in 0 0.00 Piped bytes from client
MAIN.s_pipe_out 0 0.00 Piped bytes to client
MAIN.sess_closed 26 0.00 Session Closed
MAIN.sess_pipeline 0 0.00 Session Pipeline
MAIN.sess_readahead 0 0.00 Session Read Ahead
MAIN.sess_herd 1864 0.13 Session herd
MAIN.shm_records 761102 53.53 SHM records
MAIN.shm_writes 77346 5.44 SHM writes
MAIN.shm_flushes 0 0.00 SHM flushes due to overflow
MAIN.shm_cont 107 0.01 SHM MTX contention
MAIN.shm_cycles 0 0.00 SHM cycles through buffer
MAIN.sms_nreq 0 0.00 SMS allocator requests
MAIN.sms_nobj 0 . SMS outstanding allocations
MAIN.sms_nbytes 0 . SMS outstanding bytes
MAIN.sms_balloc 0 . SMS bytes allocated
MAIN.sms_bfree 0 . SMS bytes freed
MAIN.backend_req 4166 0.29 Backend requests made
MAIN.n_vcl 1 0.00 N vcl total
MAIN.n_vcl_avail 1 0.00 N vcl available
MAIN.n_vcl_discard 0 0.00 N vcl discarded
MAIN.bans 247 . Count of bans
MAIN.bans_completed 242 . Number of bans marked
'completed'
MAIN.bans_obj 0 . Number of bans using obj.*
MAIN.bans_req 246 . Number of bans using req.*
MAIN.bans_added 247 0.02 Bans added
MAIN.bans_deleted 0 0.00 Bans deleted
MAIN.bans_tested 3602 0.25 Bans tested against objects
(lookup)
MAIN.bans_obj_killed 464 0.03 Objects killed by bans
(lookup)
MAIN.bans_lurker_tested 0 0.00 Bans tested against objects
(lurker)
MAIN.bans_tests_tested 5878 0.41 Ban tests tested against
objects (lookup)
MAIN.bans_lurker_tests_tested 0 0.00 Ban tests tested
against objects (lurker)
MAIN.bans_lurker_obj_killed 0 0.00 Objects killed by bans
(lurker)
MAIN.bans_dups 241 0.02 Bans superseded by
other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way for
lookup
MAIN.bans_persisted_bytes 40202 . Bytes used by the
persisted ban lists
MAIN.bans_persisted_fragmentation 36141 . Extra bytes in
persisted ban lists due to fragmentation
MAIN.n_purges 0 . Number of purge
operations
MAIN.n_obj_purged 0 . number of purged
objects
MAIN.exp_mailed 4606 0.32 Number of objects
mailed to expiry thread
MAIN.exp_received 4606 0.32 Number of objects
received by expiry thread
MAIN.hcb_nolock 9360 0.66 HCB Lookups
without lock
MAIN.hcb_lock 3679 0.26 HCB Lookups with
lock
MAIN.hcb_insert 3679 0.26 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse errors
(unlock)
MAIN.esi_warnings 0 0.00 ESI parse warnings
(unlock)
MAIN.vmods 0 . Loaded VMODs
MAIN.n_gzip 1306 0.09 Gzip operations
MAIN.n_gunzip 4569 0.32 Gunzip operations
MAIN.vsm_free 972528 . Free VSM space
MAIN.vsm_used 83962080 . Used VSM space
MAIN.vsm_cooling 0 . Cooling VSM space
MAIN.vsm_overflow 0 . Overflow VSM space
MAIN.vsm_overflowed 0 0.00 Overflowed VSM
space
MGT.uptime 14219 1.00 Management process
uptime
MGT.child_start 1 0.00 Child process
started
MGT.child_exit 0 0.00 Child process
normal exit
MGT.child_stop 0 0.00 Child process
unexpected exit
MGT.child_died 0 0.00 Child process died
(signal)
MGT.child_dump 0 0.00 Child process core
dumped
MGT.child_panic 0 0.00 Child process
panic
MEMPOOL.vbc.live 9 . In use
MEMPOOL.vbc.pool 10 . In Pool
MEMPOOL.vbc.sz_wanted 88 . Size requested
MEMPOOL.vbc.sz_needed 120 . Size allocated
MEMPOOL.vbc.allocs 34 0.00 Allocations
MEMPOOL.vbc.frees 25 0.00 Frees
MEMPOOL.vbc.recycle 34 0.00 Recycled from pool
MEMPOOL.vbc.timeout 24 0.00 Timed out from
pool
MEMPOOL.vbc.toosmall 0 0.00 Too small to
recycle
MEMPOOL.vbc.surplus 0 0.00 Too many for pool
MEMPOOL.vbc.randry 0 0.00 Pool ran dry
MEMPOOL.busyobj.live 1 . In use
MEMPOOL.busyobj.pool 10 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_needed 65568 . Size allocated
MEMPOOL.busyobj.allocs 4166 0.29 Allocations
MEMPOOL.busyobj.frees 4165 0.29 Frees
MEMPOOL.busyobj.recycle 4166 0.29 Recycled from pool
MEMPOOL.busyobj.timeout 361 0.03 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 0 0.00 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_needed 65568 . Size allocated
MEMPOOL.req0.allocs 4800 0.34 Allocations
MEMPOOL.req0.frees 4800 0.34 Frees
MEMPOOL.req0.recycle 4800 0.34 Recycled from pool
MEMPOOL.req0.timeout 380 0.03 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 0 0.00 Pool ran dry
MEMPOOL.sess0.live 0 . In use
MEMPOOL.sess0.pool 10 . In Pool
MEMPOOL.sess0.sz_wanted 384 . Size requested
MEMPOOL.sess0.sz_needed 416 . Size allocated
MEMPOOL.sess0.allocs 4354 0.31 Allocations
MEMPOOL.sess0.frees 4354 0.31 Frees
MEMPOOL.sess0.recycle 4354 0.31 Recycled from pool
MEMPOOL.sess0.timeout 703 0.05 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 0 0.00 Pool ran dry
MEMPOOL.req1.live 1 . In use
MEMPOOL.req1.pool 10 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_needed 65568 . Size allocated
MEMPOOL.req1.allocs 4832 0.34 Allocations
MEMPOOL.req1.frees 4831 0.34 Frees
MEMPOOL.req1.recycle 4832 0.34 Recycled from pool
MEMPOOL.req1.timeout 399 0.03 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 0 0.00 Pool ran dry
MEMPOOL.sess1.live 3 . In use
MEMPOOL.sess1.pool 10 . In Pool
MEMPOOL.sess1.sz_wanted 384 . Size requested
MEMPOOL.sess1.sz_needed 416 . Size allocated
MEMPOOL.sess1.allocs 4397 0.31 Allocations
MEMPOOL.sess1.frees 4394 0.31 Frees
MEMPOOL.sess1.recycle 4397 0.31 Recycled from pool
MEMPOOL.sess1.timeout 735 0.05 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 0 0.00 Pool ran dry
SMA.s0.c_req 8291 0.58 Allocator requests
SMA.s0.c_fail 0 0.00 Allocator failures
SMA.s0.c_bytes 343450365 24156.03 Bytes allocated
SMA.s0.c_freed 22911069 1611.41 Bytes freed
SMA.s0.g_alloc 6960 . Allocations
outstanding
SMA.s0.g_bytes 320539296 . Bytes outstanding
SMA.s0.g_space 1252324704 . Bytes available
SMA.Transient.c_req 47 0.00 Allocator requests
SMA.Transient.c_fail 0 0.00 Allocator failures
SMA.Transient.c_bytes 1503638 105.76 Bytes allocated
SMA.Transient.c_freed 1503638 105.76 Bytes freed
SMA.Transient.g_alloc 0 . Allocations
outstanding
SMA.Transient.g_bytes 0 . Bytes outstanding
SMA.Transient.g_space 0 . Bytes available
VBE.vs1_weather_8080(127.0.0.1,::1,8080).vcls 1 . VCL
references
VBE.vs1_weather_8080(127.0.0.1,::1,8080).happy 0 . Happy
health probes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).bereq_hdrbytes 2070935
145.66 Request header bytes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).bereq_bodybytes 0
0.00 Request body bytes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).beresp_hdrbytes 766225
53.89 Response header bytes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).beresp_bodybytes 132439724
9314.93 Response body bytes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).pipe_hdrbytes 0
0.00 Pipe request header bytes
VBE.vs1_weather_8080(127.0.0.1,::1,8080).pipe_out 0
0.00 Piped bytes to backend
VBE.vs1_weather_8080(127.0.0.1,::1,8080).pipe_in 0
0.00 Piped bytes from backend
LCK.sms.creat 0
0.00 Created locks
LCK.sms.destroy 0
0.00 Destroyed locks
LCK.sms.locks 0
0.00 Lock Operations
LCK.smp.creat 0
0.00 Created locks
LCK.smp.destroy 0
0.00 Destroyed locks
LCK.smp.locks 0
0.00 Lock Operations
LCK.sma.creat 2
0.00 Created locks
LCK.sma.destroy 0
0.00 Destroyed locks
LCK.sma.locks 9716
0.68 Lock Operations
LCK.smf.creat 0
0.00 Created locks
LCK.smf.destroy 0
0.00 Destroyed locks
LCK.smf.locks 0
0.00 Lock Operations
LCK.hsl.creat 0
0.00 Created locks
LCK.hsl.destroy 0
0.00 Destroyed locks
LCK.hsl.locks 0
0.00 Lock Operations
LCK.hcb.creat 1
0.00 Created locks
LCK.hcb.destroy 0
0.00 Destroyed locks
LCK.hcb.locks 3959
0.28 Lock Operations
LCK.hcl.creat 0
0.00 Created locks
LCK.hcl.destroy 0
0.00 Destroyed locks
LCK.hcl.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 9128
0.64 Lock Operations
LCK.sessmem.creat 0
0.00 Created locks
LCK.sessmem.destroy 0
0.00 Destroyed locks
LCK.sessmem.locks 0
0.00 Lock Operations
LCK.sess.creat 8751
0.62 Created locks
LCK.sess.destroy 8748
0.62 Destroyed locks
LCK.sess.locks 0
0.00 Lock Operations
LCK.wstat.creat 1
0.00 Created locks
LCK.wstat.destroy 0
0.00 Destroyed locks
LCK.wstat.locks 18670
1.31 Lock Operations
LCK.herder.creat 0
0.00 Created locks
LCK.herder.destroy 0
0.00 Destroyed locks
LCK.herder.locks 0
0.00 Lock Operations
LCK.wq.creat 3
0.00 Created locks
LCK.wq.destroy 0
0.00 Destroyed locks
LCK.wq.locks 47476
3.34 Lock Operations
LCK.objhdr.creat 3688
0.26 Created locks
LCK.objhdr.destroy 201
0.01 Destroyed locks
LCK.objhdr.locks 76467
5.38 Lock Operations
LCK.exp.creat 1
0.00 Created locks
LCK.exp.destroy 0
0.00 Destroyed locks
LCK.exp.locks 18794
1.32 Lock Operations
LCK.lru.creat 2
0.00 Created locks
LCK.lru.destroy 0
0.00 Destroyed locks
LCK.lru.locks 14328
1.01 Lock Operations
LCK.cli.creat 1
0.00 Created locks
LCK.cli.destroy 0
0.00 Destroyed locks
LCK.cli.locks 4752
0.33 Lock Operations
LCK.ban.creat 1
0.00 Created locks
LCK.ban.destroy 0
0.00 Destroyed locks
LCK.ban.locks 58726
4.13 Lock Operations
LCK.vbp.creat 1
0.00 Created locks
LCK.vbp.destroy 0
0.00 Destroyed locks
LCK.vbp.locks 0
0.00 Lock Operations
LCK.backend.creat 1
0.00 Created locks
LCK.backend.destroy 0
0.00 Destroyed locks
LCK.backend.locks 8411
0.59 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.nbusyobj.creat 0
0.00 Created locks
LCK.nbusyobj.destroy 0
0.00 Destroyed locks
LCK.nbusyobj.locks 0
0.00 Lock Operations
LCK.busyobj.creat 4166
0.29 Created locks
LCK.busyobj.destroy 4165
0.29 Destroyed locks
LCK.busyobj.locks 36357
2.56 Lock Operations
LCK.mempool.creat 6
0.00 Created locks
LCK.mempool.destroy 0
0.00 Destroyed locks
LCK.mempool.locks 123234
8.67 Lock Operations
LCK.vxid.creat 1
0.00 Created locks
LCK.vxid.destroy 0
0.00 Destroyed locks
LCK.vxid.locks 41
0.00 Lock Operations
LCK.pipestat.creat 1
0.00 Created locks
LCK.pipestat.destroy 0
0.00 Destroyed locks
LCK.pipestat.locks 0
0.00 Lock Operations
More information about the varnish-misc
mailing list