<div dir="ltr">I think the issue we have been seeing *may* be related to the polling on a shared pipe() issue that was first mentioned here: <a href="http://lkml.indiana.edu/hypermail/linux/kernel/1012.1/03515.html">http://lkml.indiana.edu/hypermail/linux/kernel/1012.1/03515.html</a>. <div>
<br></div><div>I think I narrowed the cause of the high csw/s down to multiple esi includes (2 most of the time) with s-maxage=0 on a 1M+ pageview per month site (~60conn/s according to the first line of varnishstat). Most of the page views have these esi includes that aren't being cached (not all of the 60/s). If we set s-maxage to something > 0 (say 20s) in the headers for the esi module coming from the backend to varnish the context switching issue goes away-- the csw/s degrades linearly back to the steady state at about 10k/s. </div>
<div><br></div><div style>I created a threaded version of the example code from the lkml email (<a href="https://gist.github.com/drsnyder/4735889">https://gist.github.com/drsnyder/4735889</a>). When I compile and run this code on a 2.6.32-279 or below kernel the csw/s goes to ~200k/s which defies any attempt I have made to reason about why that would be the case. If I run the same code on a 3.0+ Linux kernel, I will see about 12k csw/s. Still high, but much more reasonable. </div>
<div style><br></div><div style>We see the same csw/s behavior when we set the s-maxage=0 for the esi modules on the production site with about the same number of threads (400).</div><div style><br></div><div style>So does this polling on a shared pipe() issue affect varnish 2.1.5? It would appear so, but I'm looking for confirmation. I saw a commit referencing context switching here (<a href="https://www.varnish-cache.org/trac/changeset/05f816345a329ef52644a0239892f8be6314a3fa">https://www.varnish-cache.org/trac/changeset/05f816345a329ef52644a0239892f8be6314a3fa</a>) but I also can't imagine that this would trigger 200k/s in our environment. If it is an issue, is there anything we can do to mitigate it in the varnish configuration? Are there versions where this has been fixed?</div>
<div style><br></div><div style>We have tested sending production traffic with s-maxage=0 to an Ubuntu system running 3.2.0-27 and saw a spike in context switching but it peaked at about 20k/s with no observed impact on stability or delivery. So, switching from Centos to Ubuntu is a possible option. </div>
<div style><br></div><div style>Thanks,</div><div style>Damon</div><div><br><br><div class="gmail_quote">---------- Forwarded message ----------<br>From: <b class="gmail_sendername">Damon Snyder</b> <span dir="ltr"><<a href="mailto:damon@huddler-inc.com">damon@huddler-inc.com</a>></span><br>
Date: Thu, Jan 31, 2013 at 11:10 PM<br>Subject: Re: Feedback on session_linger (high load/n_wrk_overflow issues)<br>To: "<a href="mailto:varnish-misc@varnish-cache.org">varnish-misc@varnish-cache.org</a>" <<a href="mailto:varnish-misc@varnish-cache.org">varnish-misc@varnish-cache.org</a>><br>
<br><br><div dir="ltr">Well, I spoke too soon. Bumping session_linger brought us stability for about a day and then the high context switching returned. See the attached plot to illustrate the problem. The context switching (pulled from dstat and added to varnish) starts to ramp up. As soon it crosses the ~50k mark we start start seeing stability and latency issues (10k/s is more "normal"). So now I'm at a loss as to how to proceed.<div>
<br></div><div>Below is the current varnishstat -1 output when the system is well behaved. I wasn't able to capture it when the context switching peaked. n_wrk_overflow spiked to about 1500 at the time and the load average over the past 5 min was ~15. </div>
<div><br></div><div>This is running on a dual hex core Intel Xeon E5-2620 (24 contexts or cores) with 64GB of memory. The hitrate is about 0.65 and we are nuking (n_lru_nuked incrementing) once the system has been running for a few hours. We have long tail objects in that we have a lot of content, but only some of it is hot so it's difficult to predict our precise cache size requirements at any given time. We are using varnish-2.1.5 on Centos 5.6 with kernel 2.6.18-238.</div>
<div><br></div><div>I haven't found anything in syslog that would be of interest.</div><div><br></div><div>Thanks,</div><div>Damon</div><div><br></div><div># currently running command line</div>
<div>/usr/local/varnish-2.1.5/sbin/varnishd -P /var/run/varnish.pid -a <a href="http://10.16.50.150:6081" target="_blank">10.16.50.150:6081</a>,<a href="http://127.0.0.1:6081" target="_blank">127.0.0.1:6081</a> -f /etc/varnish/default.vcl -T <a href="http://127.0.0.1:6082" target="_blank">127.0.0.1:6082</a> -t 120 -w 100,2000,120 -u varnish -g varnish -s malloc,48G -p thread_pools 8 -p thread_pool_add_delay 2 -p listen_depth 1024 -p session_linger 110 -p lru_interval 60 -p sess_workspace 524288<br>
</div><div><br></div><div><br></div><div># varnishstat -1</div><div><div>client_conn 5021009 442.11 Client connections accepted</div><div>client_drop 0 0.00 Connection dropped, no sess/wrk</div>
<div>client_req 5020366 442.05 Client requests received</div><div>cache_hit 4597754 404.84 Cache hits</div><div>cache_hitpass 24775 2.18 Cache hits for pass</div><div>
cache_miss 2664516 234.61 Cache misses</div>
<div>backend_conn <a href="tel:3101882" value="+13101882" target="_blank">3101882</a> 273.13 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 99 0.01 Backend conn. reuses</div><div>backend_toolate 11777 1.04 Backend conn. was closed</div>
<div>backend_recycle 11877 1.05 Backend conn. recycles</div><div>backend_unused 0 0.00 Backend conn. unused</div><div>fetch_head 33 0.00 Fetch head</div><div>fetch_length 2134117 187.91 Fetch with Length</div>
<div>fetch_chunked 811172 71.42 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 156333 13.77 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 1 0.00 Fetch failed</div><div>n_sess_mem 3867 . N struct sess_mem</div>
<div>n_sess 3841 . N struct sess</div><div>n_object 757929 . N struct object</div><div>n_vampireobject 0 . N unresurrected objects</div><div>n_objectcore 758158 . N struct objectcore</div>
<div>n_objecthead 760076 . N struct objecthead</div><div>n_smf 0 . N struct smf</div><div>n_smf_frag 0 . N small free smf</div><div>n_smf_large 0 . N large free smf</div>
<div>n_vbe_conn 69 . N struct vbe_conn</div><div>n_wrk 800 . N worker threads</div><div>n_wrk_create 800 0.07 N worker threads created</div><div>
n_wrk_failed 0 0.00 N worker threads not created</div><div>n_wrk_max 0 0.00 N worker threads limited</div><div>n_wrk_queue 0 0.00 N queued work requests</div>
<div>n_wrk_overflow 171 0.02 N overflowed work requests</div><div>n_wrk_drop 0 0.00 N dropped work requests</div><div>n_backend 21 . N backends</div>
<div>n_expired 1879027 . N expired objects</div><div>n_lru_nuked 0 . N LRU nuked objects</div><div>n_lru_saved 0 . N LRU saved objects</div><div>
n_lru_moved 813472 . N LRU moved objects</div><div>n_deathrow 0 . N objects on deathrow</div><div>losthdr 0 0.00 HTTP header overflows</div><div>
n_objsendfile 0 0.00 Objects sent with sendfile</div><div>n_objwrite 5195402 457.46 Objects sent with write</div><div>n_objoverflow 0 0.00 Objects overflowing workspace</div>
<div>s_sess 5020819 442.09 Total Sessions</div><div>s_req 5020366 442.05 Total Requests</div><div>s_pipe 0 0.00 Total pipe</div><div>s_pass 437300 38.50 Total pass</div>
<div>s_fetch <a href="tel:3101668" value="+13101668" target="_blank">3101668</a> 273.11 Total fetch</div><div>s_hdrbytes 2575156242 226746.17 Total header bytes</div><div>s_bodybytes 168406835436 14828461.34 Total body bytes</div>
<div>sess_closed 5020817 442.09 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 430740934 37927.35 SHM records</div><div>shm_writes 29264523 2576.78 SHM writes</div><div>shm_flushes 51411 4.53 SHM flushes due to overflow</div><div>shm_cont 78056 6.87 SHM MTX contention</div>
<div>shm_cycles 186 0.02 SHM cycles through buffer</div><div>sm_nreq 0 0.00 allocator requests</div><div>sm_nobj 0 . outstanding allocations</div>
<div>sm_balloc 0 . bytes allocated</div><div>sm_bfree 0 . bytes free</div><div>sma_nreq 5570153 490.46 SMA allocator requests</div><div>sma_nobj 1810351 . SMA outstanding allocations</div>
<div>sma_nbytes 35306367656 . SMA outstanding bytes</div><div>sma_balloc 154583709612 . SMA bytes allocated</div><div>sma_bfree 119277341956 . SMA bytes free</div><div>
sms_nreq 32127 2.83 SMS allocator requests</div><div>sms_nobj 0 . SMS outstanding allocations</div><div>sms_nbytes 0 . SMS outstanding bytes</div>
<div>sms_balloc 29394423 . SMS bytes allocated</div><div>sms_bfree 29394423 . SMS bytes freed</div><div>backend_req <a href="tel:3101977" value="+13101977" target="_blank">3101977</a> 273.13 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_purge 31972 . N total active purges</div>
<div>n_purge_add 31972 2.82 N new purges added</div><div>n_purge_retire 0 0.00 N old purges deleted</div><div>n_purge_obj_test 3317282 292.09 N objects tested</div><div>
n_purge_re_test 530623465 46722.15 N regexps tested against</div><div>n_purge_dups 28047 2.47 N duplicate purges removed</div><div>hcb_nolock 7285152 641.47 HCB Lookups without lock</div>
<div>hcb_lock 2543066 223.92 HCB Lookups with lock</div><div>hcb_insert 2542964 223.91 HCB Inserts</div><div>esi_parse 741690 65.31 Objects ESI parsed (unlock)</div>
<div>esi_errors 0 0.00 ESI parse errors (unlock)</div><div>accept_fail 0 0.00 Accept failures</div><div>client_drop_late 0 0.00 Connection dropped late</div>
<div>uptime 11357 1.00 Client uptime</div><div>backend_retry 99 0.01 Backend conn. retry</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>fetch_1xx 0 0.00 Fetch no body (1xx)</div>
<div>fetch_204 0 0.00 Fetch no body (204)</div><div>fetch_304 14 0.00 Fetch no body (304)</div><div><br></div></div></div><div class=""><div class="h5"><div class="gmail_extra">
<br><br><div class="gmail_quote">
On Wed, Jan 30, 2013 at 3:45 PM, Damon Snyder <span dir="ltr"><<a href="mailto:damon@huddler-inc.com" target="_blank">damon@huddler-inc.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<div dir="ltr">When you 'varnishadm -T localhost:port param.show session_linger' it indicates at the bottom that "we don't know if this is a good idea... and feeback is welcome."<div><br></div><div>
We found that setting session_linger pulled us out of a bind. I wanted to add my feedback to the list in the hope that someone else might benefit from what we experienced. </div>
<div><br></div><div>We recently increased the number of esi includes on pages that get ~60-70 req/s on our platform. Some of those modules were being rendered with s-maxage set to zero so that they would be refreshed on every page load (this is so we could insert a non-cached partial into the page) which further increased the request load on varnish.</div>
<div><br></div><div>What we found is that after a few hours the load on a varnish box went from < 1 to > 10 or more and n_wkr_overflow started incrementing. After investigating further we noticed that the context switching went from ~10k/s to > 100k/s. We are running Linux specifically Centos. </div>
<div><br></div><div>No adjusting of threads or thread pools had any impact on the thrashing. After reading Kristian's <a href="http://kly.no/posts/2009_10_19__High_end_Varnish_tuning__.html" target="_blank">post</a> about high-end varnish tuning we decided to try out session_linger. We started by doubling the default from 50 to 100 to test the theory ('varnishadm -T localhost:port param.set session_linger 100'). Once we did that we saw a gradual settling of the context switching (using dstat or sar -w) and a stabilizing of the load. </div>
<div><br></div><div>It's such a great feature to be able to change this parameter via the admin interface. We have 50GB malloc'ed and some nuking on our boxes so restarting varnish doesn't come without some impact to the platform. </div>
<div><br></div><div>Intuitively increasing session_linger makes sense. If you have several esi modules rendered within a page and the gap between them is > 50ms then they'll be reallocated elsewhere. </div>
<div><br></div><div>What is not clear to me is how we should tune session_linger. We started by setting it to the 3rd quantile of render times for the esi module taken from a sampling of backend requests. This turned out to be 110ms. </div>
<span><font color="#888888">
<div><br></div><div>Damon </div></font></span></div>
</blockquote></div><br></div>
</div></div></div><br></div></div>