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>