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