>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 < [email protected]> 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 < > [email protected]> 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 <[email protected]> wrote: >> >>> On Wed, Mar 28, 2012 at 1:31 AM, Zachary Alex Stern < >>> [email protected]> 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!
_______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
