{"action":"closed","issue":{"url":"https://api.github.com/repos/antirez/redis/issues/4420","repository_url":"https://api.github.com/repos/antirez/redis","labels_url":"https://api.github.com/repos/antirez/redis/issues/4420/labels{/name}","comments_url":"https://api.github.com/repos/antirez/redis/issues/4420/comments","events_url":"https://api.github.com/repos/antirez/redis/issues/4420/events","html_url":"https://github.com/antirez/redis/issues/4420","id":271490107,"node_id":"MDU6SXNzdWUyNzE0OTAxMDc=","number":4420,"title":"Slave output buffers overflow under high ops/second ","user":{"login":"mjh1","id":3630965,"node_id":"MDQ6VXNlcjM2MzA5NjU=","avatar_url":"https://avatars2.githubusercontent.com/u/3630965?v=4","gravatar_id":"","url":"https://api.github.com/users/mjh1","html_url":"https://github.com/mjh1","followers_url":"https://api.github.com/users/mjh1/followers","following_url":"https://api.github.com/users/mjh1/following{/other_user}","gists_url":"https://api.github.com/users/mjh1/gists{/gist_id}","starred_url":"https://api.github.com/users/mjh1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mjh1/subscriptions","organizations_url":"https://api.github.com/users/mjh1/orgs","repos_url":"https://api.github.com/users/mjh1/repos","events_url":"https://api.github.com/users/mjh1/events{/privacy}","received_events_url":"https://api.github.com/users/mjh1/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2017-11-06T14:17:44Z","updated_at":"2018-06-28T17:14:36Z","closed_at":"2018-06-28T17:14:36Z","author_association":"NONE","body":"redis version: 3.2.10\r\n\r\nWe are using a single node redis cluster, with 3 replica slaves and we see an issue with replication once load reaches a certain point. In the master logs we see:\r\n\r\n```\r\n4296:M 26 Oct 02:18:27.717 # Client id=162 addr=172.31.19.219:55356 fd=39 name= age=19993 idle=2 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=13791 omem=268443704 events=rw cmd=replconf scheduled to be closed ASAP for overcoming of output buffer limits.\r\n4296:M 26 Oct 02:18:27.757 # Client id=164 addr=172.31.7.197:49714 fd=42 name= age=19977 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=13697 omem=268438920 events=rw cmd=replconf scheduled to be closed ASAP for overcoming of output buffer limits.\r\n4296:M 26 Oct 02:18:27.899 # Client id=15 addr=172.31.6.159:47864 fd=13 name= age=128677 idle=2 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=13387 omem=268440984 events=rw cmd=replconf scheduled to be closed ASAP for overcoming of output buffer limits.\r\n4296:M 26 Oct 02:18:28.022 # Client id=13 addr=172.31.9.82:46692 fd=10 name= age=128693 idle=2 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=13100 omem=268435808 events=rw cmd=replconf scheduled to be closed ASAP for overcoming of output buffer limits.\r\n4296:M 26 Oct 02:18:28.054 # Client id=17 addr=172.31.26.13:40528 fd=16 name= age=128662 idle=0 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=13098 omem=268440208 events=rw cmd=replconf scheduled to be closed ASAP for overcoming of output buffer limits.\r\n4296:M 26 Oct 02:18:29.250 # Connection with slave 172.31.19.219:6379 lost.\r\n4296:M 26 Oct 02:18:29.297 # Connection with slave 172.31.7.197:6379 lost.\r\n4296:M 26 Oct 02:18:29.393 # Connection with slave 172.31.6.159:6379 lost.\r\n4296:M 26 Oct 02:18:29.492 # Connection with slave 172.31.9.82:6379 lost.\r\n4296:M 26 Oct 02:18:29.596 # Connection with slave 172.31.26.13:6379 lost.\r\n4296:M 26 Oct 02:18:33.903 * Slave 172.31.7.197:6379 asks for synchronization\r\n4296:M 26 Oct 02:18:33.903 * Unable to partial resync with slave 172.31.7.197:6379 for lack of backlog (Slave request was: 927974602).\r\n4296:M 26 Oct 02:18:33.903 * Starting BGSAVE for SYNC with target: disk\r\n4296:M 26 Oct 02:18:33.910 * Background saving started by pid 33150\r\n4296:M 26 Oct 02:18:33.910 * Slave 172.31.26.13:6379 asks for synchronization\r\n4296:M 26 Oct 02:18:33.910 * Unable to partial resync with slave 172.31.26.13:6379 for lack of backlog (Slave request was: 942978679).\r\n```\r\n\r\nI can't seem to get to the bottom of why we are overflowing the output buffers. We essentially have a fixed number of items in redis being updated about every 6 seconds from one source, then we have many clients reading this data. As our test progresses, the number of clients reading the data and in general the number of reads/s increases (you can see the ops/second graph in the screenshot below). Once we reach a certain point in the test (variable depending on size of hardware) we see the above buffer overflow problem.\r\n\r\nWe've looked at the obvious things like network, cpu, memory and disk, no obvious limits being reached there (except of course the buffers in memory). The memory use gradually increases through part of the test (then there is a sharp spike upward when the problem occurs), I'm guessing the increase is mainly the use in these output buffers, is there an easy way to see a breakdown of the memory use?\r\n\r\nWe are using the datadog redis integration so have a fair amount of stats to look at, but so far we seem to only be able to see symptoms of this issue and not the cause (e.g. info command latency spikes up when the problem occurs). A screenshot of some of these stats:\r\n\r\n![screen shot 2017-11-06 at 14 05 16](https://user-images.githubusercontent.com/3630965/32444869-f39950a2-c2fb-11e7-823b-5c87be91ae35.png)\r\n\r\nWe increased the size of the buffers using the setting `client-output-buffer-limit` and found that it did prevent the issue (presumably it would just delay the problem, but we didn't test high enough). This doesn't feel like much of a solution as surely it means the data on the slaves will become more stale at higher loads?\r\n\r\nIs it helpful to add more slaves to spread the load from clients reading data? Or would that just make the problem worse as there is more replication to do?\r\n\r\nIs there any debug logging we can turn on which would be helpful to understand the problem?"}}
{"actor":{"display_login":"mjh1"}}