varnish *slowing* down site, any ideas?
Zachary Alex Stern
zacharyalexstern at gmail.com
Wed Mar 28 22:24:47 CEST 2012
I believe I may have nailed it down to hanging on this request:
13 RxHeader c Connection: close
13 RxHeader c X-Forwarded-For: 10.176.37.167
13 VCL_call c recv lookup
13 VCL_call c hash
13 Hash c
/network/4f161967582b94141a000001/get_file/4f61503f572b946e30000049/src
13 Hash c influencer.enternewmedia.com
13 VCL_return c hash
13 Hit c 1967773888
13 VCL_call c hit deliver
13 VCL_call c deliver deliver
13 TxProtocol c HTTP/1.1
13 TxStatus c 200
13 TxResponse c OK
13 TxHeader c Server: Apache/2.2.14 (Ubuntu)
13 TxHeader c X-Powered-By: PHP/5.3.2-1ubuntu4.14
13 TxHeader c Expires: Thu, 19 Nov 1981 08:52:00 GMT
13 TxHeader c Cache-Control: no-store, no-cache, must-revalidate,
post-check=0, pre-check=0
13 TxHeader c Pragma: no-cache
13 TxHeader c Vary: Accept-Encoding
13 TxHeader c Content-Type: text/plain
13 TxHeader c Date: Wed, 28 Mar 2012 20:23:12 GMT
13 TxHeader c X-Varnish: 1967774712 1967773888
13 TxHeader c Age: 697
13 TxHeader c Via: 1.1 varnish
13 TxHeader c Connection: close
13 Gzip c U D - 1443 6338 80 80 11480
13 Length c 0
13 ReqEnd c 1967774712 1332966192.134290457 1332966192.134568691
0.000132561 0.000075102 0.000203133
13 SessionClose c EOF mode
13 StatSess c 10.176.37.133 12414 0 1 1 0 0 0 392 0
0 ExpKill - 1967774563 -11
0 CLI - Rd ping
*
*
*
*
Any thoughts on next steps?
On Wed, Mar 28, 2012 at 3:57 PM, Zachary Alex Stern <
zacharyalexstern at gmail.com> wrote:
> *Output of varnishadm param.show:*
>
> acceptor_sleep_decay 0.900000 []
> acceptor_sleep_incr 0.001000 [s]
> acceptor_sleep_max 0.050000 [s]
> auto_restart on [bool]
> ban_dups on [bool]
> ban_lurker_sleep 0.010000 [s]
> between_bytes_timeout 60.000000 [s]
> cc_command "exec gcc -std=gnu99 -g -O2 -pthread -fpic
> -shared -Wl,-x -o %o %s"
> cli_buffer 8192 [bytes]
> cli_timeout 10 [seconds]
> clock_skew 10 [s]
> connect_timeout 0.700000 [s]
> critbit_cooloff 180.000000 [s]
> default_grace 10.000000 [seconds]
> default_keep 0.000000 [seconds]
> default_ttl 120.000000 [seconds]
> diag_bitmap 0x0 [bitmap]
> esi_syntax 0 [bitmap]
> expiry_sleep 1.000000 [seconds]
> fetch_chunksize 128 [kilobytes]
> fetch_maxchunksize 262144 [kilobytes]
> first_byte_timeout 60.000000 [s]
> group nogroup (65534)
> gzip_level 6 []
> gzip_memlevel 8 []
> gzip_stack_buffer 32768 [Bytes]
> gzip_tmp_space 0 []
> gzip_window 15 []
> http_gzip_support on [bool]
> http_max_hdr 64 [header lines]
> http_range_support on [bool]
> http_req_hdr_len 8192 [bytes]
> http_req_size 32768 [bytes]
> http_resp_hdr_len 8192 [bytes]
> http_resp_size 32768 [bytes]
> listen_address 0.0.0.0:80
> listen_depth 1024 [connections]
> log_hashstring on [bool]
> log_local_address off [bool]
> lru_interval 2 [seconds]
> max_esi_depth 5 [levels]
> max_restarts 4 [restarts]
> nuke_limit 50 [allocations]
> ping_interval 3 [seconds]
> pipe_timeout 60 [seconds]
> prefer_ipv6 off [bool]
> queue_max 100 [%]
> rush_exponent 3 [requests per request]
> saintmode_threshold 10 [objects]
> send_timeout 60 [seconds]
> sess_timeout 5 [seconds]
> sess_workspace 65536 [bytes]
> session_linger 50 [ms]
> session_max 100000 [sessions]
> shm_reclen 255 [bytes]
> shm_workspace 8192 [bytes]
> shortlived 10.000000 [s]
> syslog_cli_traffic on [bool]
> thread_pool_add_delay 2 [milliseconds]
> thread_pool_add_threshold 2 [requests]
> thread_pool_fail_delay 200 [milliseconds]
> thread_pool_max 2048 [threads]
> thread_pool_min 1 [threads]
> thread_pool_purge_delay 1000 [milliseconds]
> thread_pool_stack unlimited [bytes]
> thread_pool_timeout 10 [seconds]
> thread_pool_workspace 65536 [bytes]
> thread_pools 2 [pools]
> thread_stats_rate 10 [requests]
> user nobody (65534)
> vcc_err_unref on [bool]
> vcl_dir /etc/varnish
> vcl_trace off [bool]
> vmod_dir /usr/lib/varnish/vmods
> waiter default (epoll, poll)
> *
> *
> *Output of varnishstat -1:*
>
> client_conn 1164 1.23 Client connections accepted
> client_drop 0 0.00 Connection dropped, no sess/wrk
> client_req 1164 1.23 Client requests received
> cache_hit 524 0.56 Cache hits
> cache_hitpass 0 0.00 Cache hits for pass
> cache_miss 98 0.10 Cache misses
> backend_conn 546 0.58 Backend conn. success
> backend_unhealthy 0 0.00 Backend conn. not attempted
> backend_busy 0 0.00 Backend conn. too many
> backend_fail 0 0.00 Backend conn. failures
> backend_reuse 94 0.10 Backend conn. reuses
> backend_toolate 3 0.00 Backend conn. was closed
> backend_recycle 97 0.10 Backend conn. recycles
> backend_retry 0 0.00 Backend conn. retry
> fetch_head 0 0.00 Fetch head
> fetch_length 563 0.60 Fetch with Length
> fetch_chunked 14 0.01 Fetch chunked
> fetch_eof 0 0.00 Fetch EOF
> fetch_bad 0 0.00 Fetch had bad headers
> fetch_close 43 0.05 Fetch wanted close
> fetch_oldhttp 0 0.00 Fetch pre HTTP/1.1 closed
> fetch_zero 0 0.00 Fetch zero len
> fetch_failed 0 0.00 Fetch failed
> fetch_1xx 0 0.00 Fetch no body (1xx)
> fetch_204 0 0.00 Fetch no body (204)
> fetch_304 19 0.02 Fetch no body (304)
> n_sess_mem 17 . N struct sess_mem
> n_sess 0 . N struct sess
> n_object 69 . N struct object
> n_vampireobject 0 . N unresurrected objects
> n_objectcore 71 . N struct objectcore
> n_objecthead 71 . N struct objecthead
> n_waitinglist 24 . N struct waitinglist
> n_vbc 0 . N struct vbc
> n_wrk 2 . N worker threads
> n_wrk_create 24 0.03 N worker threads created
> n_wrk_failed 0 0.00 N worker threads not created
> n_wrk_max 33 0.03 N worker threads limited
> n_wrk_lqueue 0 0.00 work request queue length
> n_wrk_queued 152 0.16 N queued work requests
> n_wrk_drop 0 0.00 N dropped work requests
> n_backend 1 . N backends
> n_expired 29 . N expired objects
> n_lru_nuked 0 . N LRU nuked objects
> n_lru_moved 458 . N LRU moved objects
> losthdr 0 0.00 HTTP header overflows
> n_objsendfile 0 0.00 Objects sent with sendfile
> n_objwrite 1135 1.20 Objects sent with write
> n_objoverflow 0 0.00 Objects overflowing workspace
> s_sess 1164 1.23 Total Sessions
> s_req 1164 1.23 Total Requests
> s_pipe 0 0.00 Total pipe
> s_pass 542 0.57 Total pass
> s_fetch 639 0.68 Total fetch
> s_hdrbytes 437246 463.18 Total header bytes
> s_bodybytes 14474608 15333.27 Total body bytes
> sess_closed 1164 1.23 Session Closed
> sess_pipeline 0 0.00 Session Pipeline
> sess_readahead 0 0.00 Session Read Ahead
> sess_linger 0 0.00 Session Linger
> sess_herd 0 0.00 Session herd
> shm_records 85020 90.06 SHM records
> shm_writes 6648 7.04 SHM writes
> shm_flushes 0 0.00 SHM flushes due to overflow
> shm_cont 8 0.01 SHM MTX contention
> shm_cycles 0 0.00 SHM cycles through buffer
> sms_nreq 1 0.00 SMS allocator requests
> sms_nobj 0 . SMS outstanding allocations
> sms_nbytes 0 . SMS outstanding bytes
> sms_balloc 419 . SMS bytes allocated
> sms_bfree 419 . SMS bytes freed
> backend_req 640 0.68 Backend requests made
> n_vcl 1 0.00 N vcl total
> n_vcl_avail 1 0.00 N vcl available
> n_vcl_discard 0 0.00 N vcl discarded
> n_ban 1 . N total active bans
> n_ban_add 1 0.00 N new bans added
> n_ban_retire 0 0.00 N old bans deleted
> n_ban_obj_test 0 0.00 N objects tested
> n_ban_re_test 0 0.00 N regexps tested against
> n_ban_dups 0 0.00 N duplicate bans removed
> hcb_nolock 0 0.00 HCB Lookups without lock
> hcb_lock 0 0.00 HCB Lookups with lock
> hcb_insert 0 0.00 HCB Inserts
> esi_errors 0 0.00 ESI parse errors (unlock)
> esi_warnings 0 0.00 ESI parse warnings (unlock)
> accept_fail 0 0.00 Accept failures
> client_drop_late 0 0.00 Connection dropped late
> uptime 944 1.00 Client uptime
> dir_dns_lookups 0 0.00 DNS director lookups
> dir_dns_failed 0 0.00 DNS director failed lookups
> dir_dns_hit 0 0.00 DNS director cached lookups hit
> dir_dns_cache_full 0 0.00 DNS director full dnscache
> vmods 0 . Loaded VMODs
> n_gzip 0 0.00 Gzip operations
> n_gunzip 521 0.55 Gunzip operations
> LCK.sms.creat 1 0.00 Created locks
> LCK.sms.destroy 0 0.00 Destroyed locks
> LCK.sms.locks 3 0.00 Lock Operations
> LCK.sms.colls 0 0.00 Collisions
> 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.smp.colls 0 0.00 Collisions
> LCK.sma.creat 2 0.00 Created locks
> LCK.sma.destroy 0 0.00 Destroyed locks
> LCK.sma.locks 2922 3.10 Lock Operations
> LCK.sma.colls 0 0.00 Collisions
> 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.smf.colls 0 0.00 Collisions
> 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.hsl.colls 0 0.00 Collisions
> LCK.hcb.creat 0 0.00 Created locks
> LCK.hcb.destroy 0 0.00 Destroyed locks
> LCK.hcb.locks 0 0.00 Lock Operations
> LCK.hcb.colls 0 0.00 Collisions
> LCK.hcl.creat 16383 17.35 Created locks
> LCK.hcl.destroy 0 0.00 Destroyed locks
> LCK.hcl.locks 1175 1.24 Lock Operations
> LCK.hcl.colls 0 0.00 Collisions
> LCK.vcl.creat 1 0.00 Created locks
> LCK.vcl.destroy 0 0.00 Destroyed locks
> LCK.vcl.locks 48 0.05 Lock Operations
> LCK.vcl.colls 0 0.00 Collisions
> LCK.stat.creat 1 0.00 Created locks
> LCK.stat.destroy 0 0.00 Destroyed locks
> LCK.stat.locks 17 0.02 Lock Operations
> LCK.stat.colls 0 0.00 Collisions
> LCK.sessmem.creat 1 0.00 Created locks
> LCK.sessmem.destroy 0 0.00 Destroyed locks
> LCK.sessmem.locks 1270 1.35 Lock Operations
> LCK.sessmem.colls 0 0.00 Collisions
> LCK.wstat.creat 1 0.00 Created locks
> LCK.wstat.destroy 0 0.00 Destroyed locks
> LCK.wstat.locks 2858 3.03 Lock Operations
> LCK.wstat.colls 0 0.00 Collisions
> LCK.herder.creat 1 0.00 Created locks
> LCK.herder.destroy 0 0.00 Destroyed locks
> LCK.herder.locks 148 0.16 Lock Operations
> LCK.herder.colls 0 0.00 Collisions
> LCK.wq.creat 2 0.00 Created locks
> LCK.wq.destroy 0 0.00 Destroyed locks
> LCK.wq.locks 4200 4.45 Lock Operations
> LCK.wq.colls 0 0.00 Collisions
> LCK.objhdr.creat 119 0.13 Created locks
> LCK.objhdr.destroy 48 0.05 Destroyed locks
> LCK.objhdr.locks 1469 1.56 Lock Operations
> LCK.objhdr.colls 0 0.00 Collisions
> LCK.exp.creat 1 0.00 Created locks
> LCK.exp.destroy 0 0.00 Destroyed locks
> LCK.exp.locks 1072 1.14 Lock Operations
> LCK.exp.colls 0 0.00 Collisions
> LCK.lru.creat 2 0.00 Created locks
> LCK.lru.destroy 0 0.00 Destroyed locks
> LCK.lru.locks 98 0.10 Lock Operations
> LCK.lru.colls 0 0.00 Collisions
> LCK.cli.creat 1 0.00 Created locks
> LCK.cli.destroy 0 0.00 Destroyed locks
> LCK.cli.locks 327 0.35 Lock Operations
> LCK.cli.colls 0 0.00 Collisions
> LCK.ban.creat 1 0.00 Created locks
> LCK.ban.destroy 0 0.00 Destroyed locks
> LCK.ban.locks 1073 1.14 Lock Operations
> LCK.ban.colls 0 0.00 Collisions
> 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.vbp.colls 0 0.00 Collisions
> LCK.vbe.creat 1 0.00 Created locks
> LCK.vbe.destroy 0 0.00 Destroyed locks
> LCK.vbe.locks 1092 1.16 Lock Operations
> LCK.vbe.colls 0 0.00 Collisions
> LCK.backend.creat 1 0.00 Created locks
> LCK.backend.destroy 0 0.00 Destroyed locks
> LCK.backend.locks 1895 2.01 Lock Operations
> LCK.backend.colls 0 0.00 Collisions
> SMA.s0.c_req 172 0.18 Allocator requests
> SMA.s0.c_fail 0 0.00 Allocator failures
> SMA.s0.c_bytes 8694705 9210.49 Bytes allocated
> SMA.s0.c_freed 6874254 7282.05 Bytes freed
> SMA.s0.g_alloc 137 . Allocations outstanding
> SMA.s0.g_bytes 1820451 . Bytes outstanding
> SMA.s0.g_space 1071921373 . Bytes available
> SMA.Transient.c_req 1089 1.15 Allocator requests
> SMA.Transient.c_fail 0 0.00 Allocator failures
> SMA.Transient.c_bytes 64465868 68290.11 Bytes allocated
> SMA.Transient.c_freed 64465868 68290.11 Bytes freed
> SMA.Transient.g_alloc 0 . Allocations outstanding
> SMA.Transient.g_bytes 0 . Bytes outstanding
> SMA.Transient.g_space 0 . Bytes available
> VBE.default(127.0.0.1,,8081).vcls 1 . VCL references
> VBE.default(127.0.0.1,,8081).happy 0 . Happy health
> probes
> *
> *
> Thanks in advance.
>
> On Wed, Mar 28, 2012 at 3:45 AM, Stig Bakken <stig at zedge.net> wrote:
>
>> On Wed, Mar 28, 2012 at 1:31 AM, Zachary Alex Stern <
>> zacharyalexstern at gmail.com> wrote:
>>
>>> Hey there,
>>>
>>> We have a lot of websites (perhaps 15-20) running on apache, behind a
>>> varnish cache.
>>>
>>> One of our sites seems to experience random slowdowns when varnish is
>>> enabled. It will take between 5-20 seconds to load, fairly frequently. Our
>>> other sites all seem unaffected.
>>>
>>> When I disable varnish and have apache listen on port 80, the problem
>>> disappears entirely.
>>>
>>> Any thoughts?
>>>
>>> Here's our vcl.conf if it helps: http://pastebin.com/XPUvSPeu
>>>
>>
>> For this kind of problem, it is very useful if you post the output of
>> "varnishadm param.show" and "varnishstat -1" as well.
>>
>> - Stig
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20120328/179642ac/attachment-0001.html>
More information about the varnish-misc
mailing list