varnish *slowing* down site, any ideas?
Stig Bakken
stig at zedge.net
Thu Mar 29 09:31:16 CEST 2012
>From your varnishstat output I see that your "n_wrk_max" is > 0, which
means varnish had problems creating threads at some point. I would try
increasing thread_pool_min to for example 100 (threads are cheap).
n_wrk_max should be 0.
- Stig
On Wed, Mar 28, 2012 at 10:24 PM, Zachary Alex Stern <
zacharyalexstern at gmail.com> wrote:
> 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
>>>
>>>
>>
>
--
Stig Bakken
CTO, Zedge.net - free your phone!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20120329/2ab90fa0/attachment-0001.html>
More information about the varnish-misc
mailing list