https://dev.arvados.org/https://dev.arvados.org/favicon.ico?15576888422018-05-22T18:37:38ZArvadosArvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=628692018-05-22T18:37:38ZJoshua Randalljr17@sanger.ac.uk
<ul></ul><p>I've confirmed that our keepstore process is running with `GOGC=10` in its environment.</p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=628702018-05-22T18:41:13ZJoshua Randalljr17@sanger.ac.uk
<ul></ul><p>our config file:<br /><pre>
root@arvados-keep02-eglyx:~# cat /etc/arvados-keep-config.yaml
# arvados-keep-config.yaml for arvados keep nodes on eglyx
BlobSignatureTTL: 1209600s
BlobSigningKeyFile: /etc/arvados-keep-blob-signing.key
Debug: false
EnableDelete: true
Listen: :25107
LogFormat: json
ManagementToken: ""
MaxBuffers: 64
MaxRequests: 0
PIDFile: ""
RequireSignatures: false
SystemAuthTokenFile: /etc/arvados-data-manager.token
TrashCheckInterval: 24h0m0s
TrashLifetime: 168h0m0s
Volumes:
- AccessKeyFile: /etc/arvados-keep-s3.access_key
Bucket: arvados-keep-eglyx
ConnectTimeout: 0s
Endpoint: https://cog.sanger.ac.uk
IndexPageSize: 1000
LocationConstraint: false
RaceWindow: 24h0m0s
ReadOnly: false
ReadTimeout: 0s
Region: "generic"
S3Replication: 3
SecretKeyFile: /etc/arvados-keep-s3.secret_key
Type: S3
UnsafeDelete: true
</pre></p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=628712018-05-22T18:41:54ZJoshua Randalljr17@sanger.ac.uk
<ul></ul><p>version:<br /><pre>
root@arvados-keep02-eglyx:~# dpkg -l | grep keepstore
ii keepstore 1.1.4.20180510200733-1 amd64 Keep storage daemon, accessible to clients on the LAN
</pre></p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=628732018-05-22T19:10:13ZWard Vandewegeward@curii.com
<ul></ul><p>Joshua Randall wrote:</p>
<blockquote>
<p>Our keepstore nodes have repeatedly run our instances out of memory when under heavy load, resulting in the OOM killer being invoked.</p>
<p>We started out with MaxBuffers set to be close to the amount of memory on the machine (i.e. 126 * 64MiB = 8064MiB with 8.4GiB on the machine). We then repeatedly reduced it, with apparently no effect on keepstore's memory consumption.</p>
<p>We now have MaxBuffers: 64 (which should be 4GiB of RAM) on an 8.4GiB machine, and it keeps running the instances out of RAM. <br />Sometimes when the OOM killer decides to kill keepstore, we get a clear record of it being responsible for consuming pretty much all of the RAM on the instance:</p>
</blockquote>
<p>We usually reserve some extra space; the formula we use (documented at <a class="external" href="https://doc.arvados.org/install/install-keepstore.html">https://doc.arvados.org/install/install-keepstore.html</a>) is</p>
<code>
The -max-buffers argument limits keepstore’s memory usage. It should be set such that max-buffers * 64MiB + 10% fits comfortably in memory. On a host dedicated to running keepstore, divide total memory by 88MiB to suggest a suitable value. For example, if grep MemTotal /proc/meminfo reports MemTotal: 7125440 kB, compute 7125440÷(88×1024)=79 and configure -max-buffers=79.
</code>
<p>So, 64 buffers should be fine. Maybe double check that MaxBuffers in the config is really being applied?</p>
<pre>
curl http://localhost:25107/status.json | jq .
</pre>
<p>That'll tell you "BuffersMax" in the "BufferPool" block. That should line up with your MaxBuffers setting.</p>
<p>Another question, are you only seeing this with version 1.1.4.20180510200733 or also with older versions?</p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=629392018-05-23T15:53:47ZJoshua Randalljr17@sanger.ac.uk
<ul></ul><p>We now have it set to MaxBuffers: 64 on a host with 16GiB and it is still consuming all of the host memory.</p>
<p>It looks like the time when this happens corresponds with the upstream S3 gateway becoming overloaded and being slow and/or not responding for some time.</p>
<p>The keepstore logs contain entries such as:<br /><pre>
2018-05-23_15:22:09.64045 {"level":"info","msg":"reached max buffers (64), waiting","time":"2018-05-23T15:22:09.640431345Z"}
2018-05-23_15:22:09.64045 {"RequestID":"req-bm1afke8jngn6u9mv754","level":"info","msg":"request","remoteAddr":"10.101.0.126:41086","reqBytes":0,"reqForwardedFor":"","reqHost":"arvados-keep02-eglyx.node.zeta-hgiarvados.consul:25107","reqMethod":"GET","reqPath":"d3bf93a6316141799e9a18e1f5040cc2+67108864+Adf2c5bcfb215167e1e98a5b4882972d747ce23b0@5b17eccb","reqQuery":"","time":"2018-05-23T15:22:09.640274127Z"}
2018-05-23_15:22:09.64049 {"level":"info","msg":"reached max buffers (64), waiting","time":"2018-05-23T15:22:09.640472592Z"}
2018-05-23_15:22:09.64061 {"RequestID":"req-ivnjojaukedo2ax6ylon","level":"info","msg":"request","remoteAddr":"10.101.0.118:25198","reqBytes":67108864,"reqForwardedFor":"","reqHost":"arvados-keep02-eglyx.node.zeta-hgiarvados.consul:25107","reqMethod":"PUT","reqPath":"17213de7380297d3282ac1d05f97f6c6","reqQuery":"","time":"2018-05-23T15:22:09.640562090Z"}
2018-05-23_15:22:09.64064 {"level":"info","msg":"reached max buffers (64), waiting","time":"2018-05-23T15:22:09.640625896Z"}
2018-05-23_15:22:09.84774 {"RequestID":"req-zvaouknwaqvx6teszsl8","level":"info","msg":"response","remoteAddr":"10.101.0.15:11328","reqBytes":67108864,"reqForwardedFor":"","reqHost":"arvados-keep02-eglyx.node.zeta-hgiarvados.consul:25107","reqMethod":"PUT","reqPath":"baf59c5fdf67198fee12cfe1cf02bac1","reqQuery":"","respBytes":20,"respStatus":"Service Unavailable","respStatusCode":503,"time":"2018-05-23T15:22:09.847622872Z","timeToStatus":15.006072,"timeTotal":15.006079,"timeWriteBody":0.000007}
2018-05-23_15:22:09.84775 {"level":"info","msg":"waited 207.28484ms for a buffer","time":"2018-05-23T15:22:09.847716455Z"}
2018-05-23_15:22:10.45715 {"RequestID":"req-bor8zhwnpexjkgbjw8fp","level":"info","msg":"response","remoteAddr":"10.101.0.126:40970","reqBytes":0,"reqForwardedFor":"","reqHost":"arvados-keep02-eglyx.node.zeta-hgiarvados.consul:25107","reqMethod":"GET","reqPath":"cb1bd846ee8c65c878c6e0a03948f47a+67108864+A797d6c74f9042c151fa8bd8dc62b6b22d643ba81@5b17edea","reqQuery":"","respBytes":20,"respStatus":"Service Unavailable","respStatusCode":503,"time":"2018-05-23T15:22:10.457033762Z","timeToStatus":14.994317,"timeTotal":14.994330,"timeWriteBody":0.000013}
2018-05-23_15:22:10.45719 {"level":"info","msg":"waited 816.669104ms for a buffer","time":"2018-05-23T15:22:10.457143445Z"}
2018-05-23_15:22:10.79763 {"RequestID":"req-a7hobbbquin6shvw9ddg","level":"info","msg":"request","remoteAddr":"10.101.0.122:21950","reqBytes":67108864,"reqForwardedFor":"","reqHost":"arvados-keep02-eglyx.node.zeta-hgiarvados.consul:25107","reqMethod":"PUT","reqPath":"34a840f01c050e70baab6b1ea08f5a6b","reqQuery":"","time":"2018-05-23T15:22:10.797505490Z"}
</pre></p>
<p>It looks like what might be happening is that it only counts the buffers on one half of the connection, and assumes that flushing it to the backend storage will work. In this case, the S3 backend is not able to keep up and so buffers waiting to be flushed to S3 pile up during an S3 outage/slowdown until eventually they consume all memory on the machine.</p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=629402018-05-23T16:22:33ZJoshua Randalljr17@sanger.ac.uk
<ul></ul><p>status as requested:<br /><pre>
root@arvados-keep02-eglyx:~# curl http://localhost:25107/status.json | jq .
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 516 100 516 0 0 452k 0 --:--:-- --:--:-- --:--:-- 503k
{
"Volumes": [
{
"Label": "s3-bucket:\"arvados-keep-eglyx\"",
"Status": {
"MountPoint": "",
"DeviceNum": 1,
"BytesFree": 67108864000,
"BytesUsed": 1
},
"InternalStats": {
"Errors": 0,
"InBytes": 92260384888,
"OutBytes": 0,
"Ops": 3792,
"GetOps": 1687,
"PutOps": 549,
"HeadOps": 1556,
"DelOps": 0,
"ListOps": 0
}
}
],
"BufferPool": {
"BytesAllocatedCumulative": 19126026240,
"BuffersMax": 64,
"BuffersInUse": 0
},
"PullQueue": {
"InProgress": 0,
"Queued": 0
},
"TrashQueue": {
"InProgress": 0,
"Queued": 0
},
"RequestsCurrent": 1,
"RequestsMax": 128,
"Version": "1.1.4.20180510200733"
}
</pre></p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=630312018-05-31T14:54:16ZTom Cleggtom@curii.com
<ul></ul><p>Joshua Randall wrote:</p>
<blockquote>
<p>It looks like what might be happening is that it only counts the buffers on one half of the connection, and assumes that flushing it to the backend storage will work. In this case, the S3 backend is not able to keep up and so buffers waiting to be flushed to S3 pile up during an S3 outage/slowdown until eventually they consume all memory on the machine.</p>
</blockquote>
<p>I think this is about right. More detail:</p>
<p>Buffers are taken from a pool -- but we use a sync.Pool, which doesn't conserve entries (it deletes unused entries during GC, and makes new ones). So if a goroutine is still holding on to a buffer after it's returned to the pool, the pool might discard it, and allocate a new one; now we have two buffers, but we're only counting 1 against our limit.</p>
<p>(*S3Volume)Put() copies buffered data to the s3 client's http request body through an io.Pipe. If the s3 client returns without reading the whole pipe, io.Copy() stays blocked on write, and holds on to the buffer forever.</p>
<p>We do unblock the io.Copy() and release the buffer correctly when the caller (keepstore client) hangs up first -- we need similar treatment for the [partially] unread request body case.</p>
<p><a class="source" href="https://dev.arvados.org/projects/arvados/repository/arvados/entry/services/keepstore/s3_volume.go">source:services/keepstore/s3_volume.go</a></p>
<pre><code class="go syntaxhl"> <span class="k">select</span> <span class="p">{</span>
<span class="k">case</span> <span class="o"><-</span><span class="n">ctx</span><span class="o">.</span><span class="n">Done</span><span class="p">()</span><span class="o">:</span>
<span class="n">theConfig</span><span class="o">.</span><span class="n">debugLogf</span><span class="p">(</span><span class="s">"%s: taking PutReader's input away: %s"</span><span class="p">,</span> <span class="n">v</span><span class="p">,</span> <span class="n">ctx</span><span class="o">.</span><span class="n">Err</span><span class="p">())</span>
<span class="c">// Our pipe might be stuck in Write(), waiting for </span>
<span class="c">// io.Copy() to read. If so, un-stick it. This means </span>
<span class="c">// PutReader will get corrupt data, but that's OK: the </span>
<span class="c">// size and MD5 won't match, so the write will fail. </span>
<span class="k">go</span> <span class="n">io</span><span class="o">.</span><span class="n">Copy</span><span class="p">(</span><span class="n">ioutil</span><span class="o">.</span><span class="n">Discard</span><span class="p">,</span> <span class="n">bufr</span><span class="p">)</span>
<span class="c">// CloseWithError() will return once pending I/O is done. </span>
<span class="n">bufw</span><span class="o">.</span><span class="n">CloseWithError</span><span class="p">(</span><span class="n">ctx</span><span class="o">.</span><span class="n">Err</span><span class="p">())</span>
<span class="n">theConfig</span><span class="o">.</span><span class="n">debugLogf</span><span class="p">(</span><span class="s">"%s: abandoning PutReader goroutine"</span><span class="p">,</span> <span class="n">v</span><span class="p">)</span>
<span class="k">return</span> <span class="n">ctx</span><span class="o">.</span><span class="n">Err</span><span class="p">()</span>
<span class="k">case</span> <span class="o"><-</span><span class="n">ready</span><span class="o">:</span>
<span class="s">"BUG IS HERE"</span><span class="p">,</span> <span class="s">"need to call io.Copy(ioutil.Discard, bufr)"</span>
<span class="k">return</span> <span class="n">v</span><span class="o">.</span><span class="n">translateError</span><span class="p">(</span><span class="n">err</span><span class="p">)</span>
<span class="p">}</span>
</code></pre> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=630392018-05-31T17:33:16ZTom Cleggtom@curii.com
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>In Progress</i></li><li><strong>Assigned To</strong> set to <i>Tom Clegg</i></li><li><strong>Target version</strong> set to <i>2018-06-06 Sprint</i></li></ul> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=630402018-05-31T17:45:45ZTom Cleggtom@curii.com
<ul></ul><p>13517-buffer-leak @ <a class="changeset" title="13517: Fix leaked goroutine and buffer on failed S3 write. Arvados-DCO-1.1-Signed-off-by: Tom Cl..." href="https://dev.arvados.org/projects/arvados/repository/arvados/revisions/7e9b9d420b58c22c41a713b9bfbfd0f5718abb1a">7e9b9d420b58c22c41a713b9bfbfd0f5718abb1a</a></p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=630472018-05-31T19:00:00ZLucas Di Pentimalucas.dipentima@curii.com
<ul></ul><p>Is there a way to simulate this error case to write a test? AFAICS, there's a <code>runtime</code> package that may be useful to query for memory usage.<br />Otherwise, LGTM.</p> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=630592018-06-01T19:09:53ZTom Cleggtom@curii.com
<ul><li><strong>Status</strong> changed from <i>In Progress</i> to <i>Feedback</i></li></ul> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=631872018-06-06T14:47:40ZTom Cleggtom@curii.com
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>Resolved</i></li></ul> Arvados - Bug #13517: keepstore memory usage appears to not be related to MaxBuffershttps://dev.arvados.org/issues/13517?journal_id=647702018-07-23T18:52:34ZTom Morristfmorris@veritasgenetics.com
<ul><li><strong>Release</strong> set to <i>13</i></li></ul>