Redis slaves get disconnected when high rate of writes occur

@stanhu this is another point about splitting Redis, we are putting too much pressure on the system.

Some discussion on the Redis mailing list: https://groups.google.com/forum/#!topic/redis-db/CYEkTdgTaVM

@pcarranza @stanhu looks like a trigger-happy "sentinel" process.

evidence:

redis4 2017-04-27_14:51:59.54581 redis4 redis: 4942:M 27 Apr 14:51:59.545 * Background saving started
redis3 2017-04-27_14:52:09.89349 redis3 redis: 36524:M 27 Apr 14:52:09.893 * MASTER MODE enabled
redis4 2017-04-27_14:52:30.94514 redis4 redis: 4942:S 27 Apr 14:52:30.945 * SLAVE OF 10.45.2.6:6379 enabled (user request from 'id=5322146 addr=10.45.2.9:53407 fd=14 name=sentinel-c05dc551-cmd age=20 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=0 qbuf-free=32768 obl=36 oll=0 omem=0 events=r cmd=exec') 2
master mode enabled on prior slave 10.3 seconds after original master started bg save.
sentinel converted prior master redis4 to slave mode 21 seconds after redis3 slave was promoted to master

what are the configuration settings for timing of failover? (From the logs shown, I infer that this is set for 10 seconds -- see the timestamp gap on the redis4 log.
look also at the sentinel log files from the same time period.
are there problems with throughput to the underlying disk volume? (iowait performance graph) -- can the 1308MB be snapshotted to disk in 10s or less? on redis3 the background saving took over 5 minutes. Is there a provisioning option that can increase bandwidth of that volume?
have the settings of redis tcp-backlog been increased?
has the kernel setting somaxconn been increased see: "/proc/sys/net/core/somaxconn"
is sidekiq opening a new connection for each of the 7000 jobs being requeued?
how many concurrent connections can the redis instance handle?

It looks like the relevant configuration option is here:

https://github.com/antirez/redis/blob/3.2.5/redis.conf#L994-L1029

We are using the defaults:

10.45.2.6:6379> config get client-output-buffer-limit
1) "client-output-buffer-limit"
2) "normal 0 0 0 slave 2147483648 2147483648 180 pubsub 33554432 8388608 60"

It seems that if we make a lot of changes, I suspect this causes clients to run behind the 256 MB mark, and eventually the master decides to disconnect the clients.

I recommend that we increase this limit.

@stanhu @pcarranza have a look at perf monitoring

It does not look from that dataset that the 256mb limit was reached (at least not at a sampling interval).

info that would help triage: more dashboards on resource utilization:

VM node memory max/used/swap
VM node sockets max/used

Consider perhaps that the BGSAVE process fork on redis4 caused swapping and maybe OOM, leading to non-responsive behaviors from a client perspective during those 1st 10 seconds.

What we do know from the data and logs is that Redis3 was promoted to master 10s after Redis4 started a BGSAVE, and that the BGSAVE on Redis4 ran to completion and took 4m50s for 326MB. We also know that the BGSAVE started on Redis3 at about the same time, ran to completion, and took 5m27s for 1308MB. For whatever reason Redis3 saved the image 4x faster per MB than Redis4.

I also infer from the data and logs that there is a cluster management script asking each of the Redis nodes to perform BGSAVE at the same time.

possible action item for risk management would be to stagger the BGSAVE operations.

I also infer from the data and logs that there is a cluster management script asking each of the Redis nodes to perform BGSAVE at the same time.

No, I don't think that is correct. I believe Redis will trigger a save if m keys change in n seconds.

@stanhu yes, re: "I believe Redis will trigger a save if "m" keys change in "n" seconds."

and see:

generally: REDIS persistence
specific options: REDIS conf defaults
overrides by gitlab.com specific options: gitlab REDIS conf defaults

confirming sentinel configuration of 10s -> default['gitlab']['sentinel']['down_after_milliseconds'] = 10000 as per gitlab omnibus

what is not explained:

Redis ... is currently not able to persist on disk (no timestamp given)

what is not visible in the current logs or performance dashboard:

memory total/swap/free
sockets total/free
disk total/free by volume

something went wrong, coinciding with the BGSAVE process fork, and there may not be enough residual evidence to pinpoint what happened in the past, but may be able to catch the root cause in the future by:

adding the metrics above to the performance charting, for all nodes, to assist triage.

I think this just happened again. Logs from the master:

2017-05-08_17:54:10.21227 redis3 redis: 22737:C 08 May 17:54:10.210 * RDB: 1192 MB of memory used by copy-on-write
2017-05-08_17:54:11.67406 redis3 redis: 37552:M 08 May 17:54:11.673 * Background saving terminated with success
2017-05-08_17:55:12.08962 redis3 redis: 37552:M 08 May 17:55:12.089 * 10000 changes in 60 seconds. Saving...
2017-05-08_17:55:13.27075 redis3 redis: 37552:M 08 May 17:55:13.270 * Background saving started by pid 23321
2017-05-08_18:00:55.30875 redis3 redis: 37552:M 08 May 18:00:55.308 # Background saving terminated by signal 9
2017-05-08_18:00:55.81749 redis3 redis: 37552:M 08 May 18:00:55.817 * 10 changes in 300 seconds. Saving...
2017-05-08_18:00:56.98428 redis3 redis: 37552:M 08 May 18:00:56.984 * Background saving started by pid 25162
2017-05-08_18:01:27.57288 redis3 redis: 37552:S 08 May 18:01:27.572 # Connection with slave 10.45.2.9:6379 lost.
2017-05-08_18:01:27.57300 redis3 redis: 37552:S 08 May 18:01:27.572 # Connection with slave 10.45.2.10:6379 lost.
2017-05-08_18:01:27.57321 redis3 redis: 37552:S 08 May 18:01:27.573 # Connection with slave 10.45.2.8:6379 lost.
2017-05-08_18:01:27.57325 redis3 redis: 37552:S 08 May 18:01:27.573 # Connection with slave 10.45.2.7:6379 lost.
2017-05-08_18:01:27.57328 redis3 redis: 37552:S 08 May 18:01:27.573 * SLAVE OF 10.45.2.9:6379 enabled (user request from 'id=6477140 addr=10.45.2.8:51687 fd=9 name=sentinel-734d44a1-cmd age=20 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=0 qbuf-free=32768 obl=36 oll=0 omem=0 events=r cmd=exec')
2017-05-08_18:01:27.58068 redis3 redis: 37552:S 08 May 18:01:27.580 # CONFIG REWRITE executed with success.
2017-05-08_18:01:28.57904 redis3 redis: 37552:S 08 May 18:01:28.578 * Connecting to MASTER 10.45.2.9:6379
2017-05-08_18:01:28.57914 redis3 redis: 37552:S 08 May 18:01:28.579 * MASTER <-> SLAVE sync started
2017-05-08_18:01:28.57952 redis3 redis: 37552:S 08 May 18:01:28.579 * Non blocking connect for SYNC fired the event.
2017-05-08_18:01:28.58029 redis3 redis: 37552:S 08 May 18:01:28.580 * Master replied to PING, replication can continue...
2017-05-08_18:01:28.58097 redis3 redis: 37552:S 08 May 18:01:28.580 * Partial resynchronization not possible (no cached master)

mentioned in issue #1575 (closed)

This happened:

Which then led to this failover:

It looks to me that the lrem, rpush, and mget actions are all done by Sidekiq limit-fetch. At first, I thought this meant a lot of jobs got pushed onto the queue. But I don't see any evidence of that happening:

@stanhu Could it jus be contention?

@pcarranza It's a good question. We could be looking at two different causes. The latest issue may have been a failover due to some contention issue. We know for a fact that running rake cache:clear seems to have induced the failover.

mentioned in issue #1798 (closed)

Redis information gathering: https://gitlab.com/gitlab-com/infrastructure/issues/1802

mentioned in issue #1802 (closed)

mentioned in issue #1631 (closed)

Hello @stanhu I was looking at this issue: what you observed here about the MISCONF error happens after the failover, or the two things are unrelated? The MISCONF error should only be provided when the instance is not able to correctly persist on disk because of an hard error (like permissions error in the directory, fork() error and similar, but NOT when the child is killed by a signal), given that Redis is no longer able to guarantee that the writes will be persisted on disk. You can disable this feature but it is much better to track the root cause.

@antirez I think they are related. When this issue occurs, we see the MISCONF error repeatedly for a while. Somehow the problem goes away--perhaps there is an out-of-memory issue here that fixes itself after keys are expired? Is there somewhere we should look for more logs?

@stanhu near OOM the most plausible cause of MISCONF is fork() returning an error, so the children cannot be created and the result is RDB status failure (preventing further writes). But in that case you should see in the logs somewhere:

Can't save in background: fork: ....

This protection can be disabled if wanted, and writes can be accepted even if the latest RDB persistence attempt failed. However the risk is that there is a persistence error for a long time that does not get noticed (disk full is the simplest).

Yeah, I didn't see that message in the Redis logs over the last 30 days. We do see the MISCONF error a number of times:

Is there some other message we should look for?

For example, we saw those error messages yesterday, and this is the slave log:

2017-05-18_07:34:47.19966 redis5 redis: 46174:S 18 May 07:34:47.199 * Background saving terminated with success
2017-05-18_07:35:48.05699 redis5 redis: 46174:S 18 May 07:35:48.056 * 10000 changes in 60 seconds. Saving...
2017-05-18_07:35:49.06124 redis5 redis: 46174:S 18 May 07:35:49.061 * Background saving started by pid 53013
2017-05-18_07:37:42.33368 redis5 redis: 46174:S 18 May 07:37:42.333 # Connection with master lost.
2017-05-18_07:37:42.33380 redis5 redis: 46174:S 18 May 07:37:42.333 * Caching the disconnected master state.
2017-05-18_07:37:42.33389 redis5 redis: 46174:S 18 May 07:37:42.333 * Discarding previously cached master state.
2017-05-18_07:37:42.33399 redis5 redis: 46174:S 18 May 07:37:42.333 * SLAVE OF 10.45.2.7:6379 enabled (user request from 'id=330101 addr=10.45.2.9:41766 fd=20 name=sentinel-c05dc551-cmd age=60 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=0 qbuf-free=32768 obl=36 oll=0 omem=0 events=r cmd=exec')
2017-05-18_07:37:42.34300 redis5 redis: 46174:S 18 May 07:37:42.342 # CONFIG REWRITE executed with success.
2017-05-18_07:37:42.99606 redis5 redis: 46174:S 18 May 07:37:42.996 * Connecting to MASTER 10.45.2.7:6379
2017-05-18_07:37:42.99623 redis5 redis: 46174:S 18 May 07:37:42.996 * MASTER <-> SLAVE sync started
2017-05-18_07:37:42.99673 redis5 redis: 46174:S 18 May 07:37:42.996 * Non blocking connect for SYNC fired the event.
2017-05-18_07:37:42.99712 redis5 redis: 46174:S 18 May 07:37:42.997 * Master replied to PING, replication can continue...
2017-05-18_07:37:42.99785 redis5 redis: 46174:S 18 May 07:37:42.997 * Partial resynchronization not possible (no cached master)
2017-05-18_07:37:42.99861 redis5 redis: 46174:S 18 May 07:37:42.998 * Full resync from master: 3501a3950341b7b7f076e2aeb15a97b60470ad52:227933160318
2017-05-18_07:41:37.67582 redis5 redis: 53013:C 18 May 07:41:37.675 * DB saved on disk
2017-05-18_07:41:38.50576 redis5 redis: 53013:C 18 May 07:41:38.505 * RDB: 200 MB of memory used by copy-on-write
2017-05-18_07:41:39.64595 redis5 redis: 46174:S 18 May 07:41:39.645 * Background saving terminated with success
2017-05-18_07:42:40.01385 redis5 redis: 46174:S 18 May 07:42:40.013 * 10000 changes in 60 seconds. Saving...
2017-05-18_07:42:40.99383 redis5 redis: 46174:S 18 May 07:42:40.993 * Background saving started by pid 53560
2017-05-18_07:43:08.70480 redis5 redis: 46174:S 18 May 07:43:08.704 * MASTER <-> SLAVE sync: receiving 19077385915 bytes from master
2017-05-18_07:49:06.45701 redis5 redis: 53560:C 18 May 07:49:06.456 * DB saved on disk
2017-05-18_07:49:07.23154 redis5 redis: 53560:C 18 May 07:49:07.231 * RDB: 7 MB of memory used by copy-on-write
2017-05-18_07:49:08.29497 redis5 redis: 46174:S 18 May 07:49:08.294 * Background saving terminated with success
2017-05-18_07:53:32.90696 redis5 redis: 46174:S 18 May 07:53:32.906 * MASTER <-> SLAVE sync: Flushing old data
2017-05-18_07:57:54.95551 redis5 redis: 46174:S 18 May 07:57:54.955 * MASTER <-> SLAVE sync: Loading DB in memory
2017-05-18_08:04:59.08282 redis5 redis: 46174:S 18 May 08:04:59.082 * MASTER <-> SLAVE sync: Finished with success
2017-05-18_08:04:59.18249 redis5 redis: 46174:S 18 May 08:04:59.182 * 1 changes in 900 seconds. Saving...
2017-05-18_08:04:59.87173 redis5 redis: 46174:S 18 May 08:04:59.871 * Background saving started by pid 57227
2017-05-18_08:06:43.17582 redis5 redis: 46174:S 18 May 08:06:43.175 # Connection with master lost.
2017-05-18_08:06:43.17589 redis5 redis: 46174:S 18 May 08:06:43.175 * Caching the disconnected master state.
2017-05-18_08:06:43.17590 redis5 redis: 46174:S 18 May 08:06:43.175 * Discarding previously cached master state.
2017-05-18_08:06:43.17592 redis5 redis: 46174:S 18 May 08:06:43.175 * SLAVE OF 10.45.2.9:6379 enabled (user request from 'id=331103 addr=10.45.2.9:56370 fd=11 name=sentinel-c05dc551-cmd age=61 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=0 qbuf-free=32768 obl=36 oll=0 omem=0 events=r cmd=exec')
2017-05-18_08:06:43.18239 redis5 redis: 46174:S 18 May 08:06:43.182 # CONFIG REWRITE executed with success.
2017-05-18_08:06:43.99410 redis5 redis: 46174:S 18 May 08:06:43.994 * Connecting to MASTER 10.45.2.9:6379
2017-05-18_08:06:43.99432 redis5 redis: 46174:S 18 May 08:06:43.994 * MASTER <-> SLAVE sync started
2017-05-18_08:06:43.99478 redis5 redis: 46174:S 18 May 08:06:43.994 * Non blocking connect for SYNC fired the event.
2017-05-18_08:06:43.99517 redis5 redis: 46174:S 18 May 08:06:43.995 * Master replied to PING, replication can continue...
2017-05-18_08:06:43.99588 redis5 redis: 46174:S 18 May 08:06:43.995 * Partial resynchronization not possible (no cached master)
2017-05-18_08:10:11.20143 redis5 redis: 46174:S 18 May 08:10:11.201 * Full resync from master: 405b30be07f1a319117af61bbb7ceb46665f0155:228381440163
2017-05-18_08:11:16.74687 redis5 redis: 57227:C 18 May 08:11:16.746 * DB saved on disk
2017-05-18_08:11:17.36848 redis5 redis: 57227:C 18 May 08:11:17.368 * RDB: 992 MB of memory used by copy-on-write
2017-05-18_08:11:18.31573 redis5 redis: 46174:S 18 May 08:11:18.315 * Background saving terminated with success
2017-05-18_08:12:19.01566 redis5 redis: 46174:S 18 May 08:12:19.015 * 10000 changes in 60 seconds. Saving...
2017-05-18_08:12:19.78093 redis5 redis: 46174:S 18 May 08:12:19.780 * Background saving started by pid 57941
2017-05-18_08:16:59.62432 redis5 redis: 46174:S 18 May 08:16:59.624 * MASTER <-> SLAVE sync: receiving 19070291980 bytes from master
2017-05-18_08:18:51.64337 redis5 redis: 57941:C 18 May 08:18:51.643 * DB saved on disk
2017-05-18_08:18:52.30519 redis5 redis: 57941:C 18 May 08:18:52.305 * RDB: 14 MB of memory used by copy-on-write
2017-05-18_08:18:53.09367 redis5 redis: 46174:S 18 May 08:18:53.093 * Background saving terminated with success
2017-05-18_08:25:13.05585 redis5 redis: 46174:S 18 May 08:25:13.055 * MASTER <-> SLAVE sync: Flushing old data
2017-05-18_08:28:34.10169 redis5 redis: 46174:S 18 May 08:28:34.101 * MASTER <-> SLAVE sync: Loading DB in memory
2017-05-18_08:34:34.90049 redis5 redis: 46174:S 18 May 08:34:34.900 * MASTER <-> SLAVE sync: Finished with success
2017-05-18_08:34:35.00036 redis5 redis: 46174:S 18 May 08:34:35.000 * 1 changes in 900 seconds. Saving...
2017-05-18_08:34:35.75995 redis5 redis: 46174:S 18 May 08:34:35.759 * Background saving started by pid 61787
2017-05-18_08:41:08.45128 redis5 redis: 61787:C 18 May 08:41:08.451 * DB saved on disk
2017-05-18_08:41:09.09481 redis5 redis: 61787:C 18 May 08:41:09.094 * RDB: 1335 MB of memory used by copy-on-write
2017-05-18_08:41:09.98238 redis5 redis: 46174:S 18 May 08:41:09.982 * Background saving terminated with success
2017-05-18_08:42:10.01644 redis5 redis: 46174:S 18 May 08:42:10.016 * 10000 changes in 60 seconds. Saving...
2017-05-18_08:42:10.79253 redis5 redis: 46174:S 18 May 08:42:10.792 * Background saving started by pid 62495
2017-05-18_08:48:48.30136 redis5 redis: 62495:C 18 May 08:48:48.301 * DB saved on disk
2017-05-18_08:48:48.96873 redis5 redis: 62495:C 18 May 08:48:48.968 * RDB: 553 MB of memory used by copy-on-write
2017-05-18_08:48:49.87533 redis5 redis: 46174:S 18 May 08:48:49.875 * Background saving terminated with success
2017-05-18_08:49:50.01821 redis5 redis: 46174:S 18 May 08:49:50.018 * 10000 changes in 60 seconds. Saving...
2017-05-18_08:49:50.73467 redis5 redis: 46174:S 18 May 08:49:50.734 * Background saving started by pid 63115
2017-05-18_08:56:29.71040 redis5 redis: 63115:C 18 May 08:56:29.710 * DB saved on disk
2017-05-18_08:56:30.38542 redis5 redis: 63115:C 18 May 08:56:30.385 * RDB: 569 MB of memory used by copy-on-write
2017-05-18_08:56:31.29477 redis5 redis: 46174:S 18 May 08:56:31.294 * Background saving terminated with success
2017-05-18_08:57:32.03779 redis5 redis: 46174:S 18 May 08:57:32.037 * 10000 changes in 60 seconds. Saving...
2017-05-18_08:57:32.80113 redis5 redis: 46174:S 18 May 08:57:32.801 * Background saving started by pid 305

Master log is:

2017-05-18_07:56:35.17770 redis4 redis: 10091:M 18 May 07:56:35.177 * Background saving terminated with success
2017-05-18_07:57:36.09258 redis4 redis: 10091:M 18 May 07:57:36.092 * 10000 changes in 60 seconds. Saving...
2017-05-18_07:57:37.05150 redis4 redis: 10091:M 18 May 07:57:37.051 * Background saving started by pid 5917
2017-05-18_07:59:30.44843 redis4 redis: 10091:M 18 May 07:59:30.447 # Background saving terminated by signal 9
2017-05-18_07:59:30.69776 redis4 redis: 10091:M 18 May 07:59:30.697 * 10000 changes in 60 seconds. Saving...
2017-05-18_07:59:31.63620 redis4 redis: 10091:M 18 May 07:59:31.636 * Background saving started by pid 6071
2017-05-18_08:04:46.37041 redis4 redis: 10091:M 18 May 08:04:46.369 # Background saving terminated by signal 9
2017-05-18_08:04:46.88376 redis4 redis: 10091:M 18 May 08:04:46.883 * 10 changes in 300 seconds. Saving...
2017-05-18_08:04:47.84844 redis4 redis: 10091:M 18 May 08:04:47.848 * Background saving started by pid 6534
2017-05-18_08:06:03.05888 redis4 redis: 10091:S 18 May 08:06:03.058 # Connection with slave 10.45.2.10:6379 lost.
2017-05-18_08:06:03.05916 redis4 redis: 10091:S 18 May 08:06:03.059 # Connection with slave 10.45.2.9:6379 lost.
2017-05-18_08:06:03.05932 redis4 redis: 10091:S 18 May 08:06:03.059 # Connection with slave 10.45.2.6:6379 lost.
2017-05-18_08:06:03.05954 redis4 redis: 10091:S 18 May 08:06:03.059 # Connection with slave 10.45.2.8:6379 lost.
2017-05-18_08:06:03.05971 redis4 redis: 10091:S 18 May 08:06:03.059 * SLAVE OF 10.45.2.9:6379 enabled (user request from 'id=364208 addr=10.45.2.9:42710 fd=10 name=sentinel-c05dc551-cmd age=21 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=0 qbuf-free=32768 obl=36 oll=0 omem=0 events=r cmd=exec')
2017-05-18_08:06:03.06774 redis4 redis: 10091:S 18 May 08:06:03.067 # CONFIG REWRITE executed with success.
2017-05-18_08:06:03.44623 redis4 redis: 10091:S 18 May 08:06:03.446 * Connecting to MASTER 10.45.2.9:6379
2017-05-18_08:06:03.44633 redis4 redis: 10091:S 18 May 08:06:03.446 * MASTER <-> SLAVE sync started
2017-05-18_08:06:03.44675 redis4 redis: 10091:S 18 May 08:06:03.446 * Non blocking connect for SYNC fired the event.
2017-05-18_08:06:03.44723 redis4 redis: 10091:S 18 May 08:06:03.447 * Master replied to PING, replication can continue...
2017-05-18_08:06:03.44896 redis4 redis: 10091:S 18 May 08:06:03.448 * Partial resynchronization not possible (no cached master)
2017-05-18_08:10:11.20191 redis4 redis: 10091:S 18 May 08:10:11.201 * Full resync from master: 405b30be07f1a319117af61bbb7ceb46665f0155:228381440163
2017-05-18_08:10:12.48005 redis4 redis: 6534:C 18 May 08:10:12.479 * DB saved on disk
2017-05-18_08:10:13.21147 redis4 redis: 6534:C 18 May 08:10:13.211 * RDB: 575 MB of memory used by copy-on-write
2017-05-18_08:10:14.28124 redis4 redis: 10091:S 18 May 08:10:14.281 * Background saving terminated with success
2017-05-18_08:16:59.62459 redis4 redis: 10091:S 18 May 08:16:59.624 * MASTER <-> SLAVE sync: receiving 19070291980 bytes from master
2017-05-18_08:25:07.53920 redis4 redis: 10091:S 18 May 08:25:07.538 * MASTER <-> SLAVE sync: Flushing old data
2017-05-18_08:29:06.08509 redis4 redis: 10091:S 18 May 08:29:06.084 * MASTER <-> SLAVE sync: Loading DB in memory
2017-05-18_08:35:54.46257 redis4 redis: 10091:S 18 May 08:35:54.462 * MASTER <-> SLAVE sync: Finished with success
2017-05-18_08:35:54.46269 redis4 redis: 10091:S 18 May 08:35:54.462 * 1 changes in 900 seconds. Saving...
2017-05-18_08:35:55.07617 redis4 redis: 10091:S 18 May 08:35:55.076 * Background saving started by pid 11292
2017-05-18_08:41:58.24777 redis4 redis: 11292:C 18 May 08:41:58.247 * DB saved on disk
2017-05-18_08:41:58.75524 redis4 redis: 11292:C 18 May 08:41:58.755 * RDB: 1347 MB of memory used by copy-on-write
2017-05-18_08:41:59.54827 redis4 redis: 10091:S 18 May 08:41:59.548 * Background saving terminated with success
2017-05-18_08:43:00.09424 redis4 redis: 10091:S 18 May 08:43:00.094 * 10000 changes in 60 seconds. Saving...
2017-05-18_08:43:00.71530 redis4 redis: 10091:S 18 May 08:43:00.715 * Background saving started by pid 11950

Is the MISCONF just showing up when the slaves are resyncing with th emaster?

@stanhu in the above logs there is basically no error, just the evidence that Sentinel failed over, this should be the old thing that we already analyzed of OOM / swap making the master slow, so that Sentinel triggers a failover. I'm grepping the Redis source code in order to enumerate all the potential causes of MISCONF.

Ok I was wrong, the MISCONF condition also is tirggered when the children is killed by the signal. In your case, the OOM killer of Linux as we saw a few days ago. This is the code:

        if (bysignal != SIGUSR1)
            server.lastbgsave_status = C_ERR;

Basically only if the signal killing the children is SIGUSR1 the error condition is cleared. Otherwise, the child killed by the kernel, is still considered unability to persist (and it is indeed), so if Redis is configured in order to warn you with write errors, it will do so.

The reason why SIGUSR1 is whitelisted, is because Redis uses this signal in order to kill the RDB saving child itself when there are the right conditions to do so, but an error condition should not be raised in that case. This happens during configuration switches, during shutdown, and a few other similar things.

So TLDR:

The master gets out of memory because of lack of physical memory compared to dataset size + COW during persistence.
This makes the master slow.
Sentinel starts a failover.
(Unrelated to 3) The Linux kernel OOM killer kills the saving child.
Since the latest RDB saving failed, an error condition is set and no further write is accepted.

Long term is to fix the problem itself. Short term to avoid errors during writes:

CONFIG SET stop-writes-on-bgsave-error no

(Also make sure to put the above in the redis.conf file, or use CONFIG REWRITE after the CONFIG SET, otherwise next restart the config will be back to the old one).

Based on this input, I'm chanigng the MISCONF error message to be more clear:

"-MISCONF Redis is configured to save RDB snapshots, but it is currently not able to persist on disk. 
Commands that may modify the data set are disabled, because this instance is configured to report errors 
during writes if RDB snapshotting fails (stop-writes-on-bgsave-error option). Please check the Redis logs 
for details about the RDB error.\r\n"

The root cause of the last outage from the 18th looks very similar to the previous one: https://gitlab.com/gitlab-com/infrastructure/issues/1819#note_30351152

However I can't see an increase in number of operations by looking at the graphs.

mentioned in issue #1819 (closed)

No need to be any increasing number of op @omame, any a few MBs of less memory for any reason (client not reading replies fast enough, slaves pending output buffers, any other Linux unrelated process doing something), and it happens again. More OP/S is just one of the potential causes that will create more COW and in turn will use more memory and trigger this problem. Cheers.

Before fixing the deployment in a long term way, is there anything you can do in order to free 5/10 GBs of RAM in that Redis box? Did you tried redis-cli --bigkeys to see if there is some obvious culprit for hte memory usage?

@antirez We did try that. You can see details here: https://gitlab.com/gitlab-com/infrastructure/issues/1631

@stanhu there is no obvious huge key to remove, all appear to be legitimate keys that all summed create the problem (but for the exception of that huge string keys). I wonder how the cache:* keys are expired, if by the application logic or via a TTL set with EXPIRE or similar.

@antirez

I wonder how the cache:* keys are expired

global default is 2 weeks set in config/application.rb
- there may be overrides somewhere and I have not yet seen them

    # Use caching across all environments
    caching_config_hash = Gitlab::Caching.params
    caching_config_hash[:namespace] = Gitlab::Caching::CACHE_NAMESPACE
    caching_config_hash[:expires_in] = 2.weeks # Cache should not grow forever

ok, why cache diff markup for 2 weeks rather than recompute it on demand after a few hours?

OTOH -- session keys are set by default to expire in 3 hours config/initializers/session_store.rb (unless override by external configuration.)

@techguru @stanhu ok that's interesting. An immediate "free a few GBs of memory" measure at this point could simply be to lower the TTL. You can do this very incrementally and check if there is any impact on cache misses. It's very plausible that it will be possible to free 5/10 GB of data without any serious impact on the database (or whatever backend is queried if there is no cache), assuming kinda of a powerlaw distribution in the caches accesses. In the worst case of completely fair access among all the cached keys, what happens is that the backend load increases proportionally to the amount of data you free, but by using incrementally shorter TTLs you should be able to immediately detect this.

Closing this issue due to #1855 (closed) done

closed

added availability label

changed milestone to %WoW ending 2017-05-30

mentioned in issue gitlab-org/gitlab#10231

Redis slaves get disconnected when high rate of writes occur

Designs

Child items 0

Activity

Admin message

Admin message

Redis slaves get disconnected when high rate of writes occur

Activity