REDIS主從頻繁切換事件排查

傑哥很忙發表於2020-06-05
Redis事件

目錄

前言

目前生產配置了2臺redis一主一從1.193和12.6，和3個哨兵。1.193，3.10，12.6，搭建的redis高可用環境。突然發生了redis頻繁無響應。

現象

2臺生產redis突然發生頻繁的主從切換。由於目前redis配置主從切換全量同步先生成rdb資料檔案儲存到硬碟，然後將rdb檔案傳輸到從庫。因此redis目錄下產生了大量的rdb檔案

20200604172608.png

20200604172703.png

可以看出大約7分鐘左右會產生一個rdb檔案。

排查

檢視2個redis服務日誌，可以看到兩個redis每隔一段時間就會變為主,且有許多連線丟失的情況，同時存在頻繁主從全量同步。

1.193 redis
...
[3932] 04 Jun 14:18:32.846 * MASTER MODE enabled (user request from 'id=107487221 addr=172.19.12.1:49610 fd=188 name=sentinel-872f1eee-cmd age=71 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')
[3932] 04 Jun 14:18:32.862 # CONFIG REWRITE executed with success.
[3932] 04 Jun 14:18:44.983 * Slave 172.18.12.6:6380 asks for synchronization
[3932] 04 Jun 14:18:44.983 * Full resync requested by slave 172.18.12.6:6380
[3932] 04 Jun 14:18:44.983 * Starting BGSAVE for SYNC with target: disk
[3932] 04 Jun 14:18:45.061 * Background saving started by pid 140176
[3932] 04 Jun 14:22:42.416 # fork operation complete
[3932] 04 Jun 14:22:44.381 * Background saving terminated with success
[3932] 04 Jun 14:22:49.186 # Connection with slave 172.18.12.6:6380 lost.
[3932] 04 Jun 14:22:59.373 * SLAVE OF 172.18.12.6:6380 enabled (user request from 'id=107487264 addr=172.18.12.6:56951 fd=188 name=sentinel-7a359562-cmd age=10 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')
[3932] 04 Jun 14:22:59.388 # CONFIG REWRITE executed with success.
[3932] 04 Jun 14:22:59.700 * Connecting to MASTER 172.18.12.6:6380
[3932] 04 Jun 14:22:59.700 * MASTER <-> SLAVE sync started
[3932] 04 Jun 14:22:59.700 * Non blocking connect for SYNC fired the event.
[3932] 04 Jun 14:22:59.700 * Master replied to PING, replication can continue...
[3932] 04 Jun 14:22:59.700 * Partial resynchronization not possible (no cached master)
[3932] 04 Jun 14:22:59.763 * Full resync from master: f391e124ded4a1bbe62f0e1d0214b823943f3461:1
[3932] 04 Jun 14:25:52.642 * MASTER MODE enabled (user request from 'id=107487264 addr=172.18.12.6:56951 fd=188 name=sentinel-7a359562-cmd age=183 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')
[3932] 04 Jun 14:25:52.658 # CONFIG REWRITE executed with success.
[3932] 04 Jun 14:26:04.077 * Slave 172.18.12.6:6380 asks for synchronization
[3932] 04 Jun 14:26:04.077 * Full resync requested by slave 172.18.12.6:6380
[3932] 04 Jun 14:26:04.077 * Starting BGSAVE for SYNC with target: disk
[3932] 04 Jun 14:26:04.171 * Background saving started by pid 1428
[3932] 04 Jun 14:30:08.342 # fork operation complete
[3932] 04 Jun 14:30:10.277 * Background saving terminated with success
[3932] 04 Jun 14:30:15.659 # Connection with slave 172.18.12.6:6380 lost.
[3932] 04 Jun 14:30:25.705 * SLAVE OF 172.18.12.6:6380 enabled (user request from 'id=107487335 addr=172.18.12.6:57160 fd=161 name=sentinel-7a359562-cmd age=17 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')
[3932] 04 Jun 14:30:25.721 # CONFIG REWRITE executed with success.
[3932] 04 Jun 14:30:26.064 * Connecting to MASTER 172.18.12.6:6380
[3932] 04 Jun 14:30:26.064 * MASTER <-> SLAVE sync started
...
  • MASTER MODE enabled 被哨兵設定為主
  • CONFIG REWRITE executed with success配置重寫成功
  • Slave 172.18.12.6:6380 asks for synchronization從redis請求主從同步
  • Full resync requested by slave 172.18.12.6:6380全量同步
  • Starting BGSAVE for SYNC with target: disk後臺儲存到硬碟
  • Background saving started by pid 140176子程式開始儲存
  • fork operation complete子執行緒操作完成
  • Background saving terminated with success儲存成功
  • Connection with slave 172.18.12.6:6380 lost.連線到從連線丟失
  • SLAVE OF 172.18.12.6:6380 enabled 被哨兵設定為從
  • Connecting to MASTER 172.18.12.6:6380連線到主
  • MASTER <-> SLAVE sync started主從同步開始
  • Partial resynchronization not possible (no cached master)無法部分同步
  • Full resync from master: f391e124ded4a1bbe62f0e1d0214b823943f3461:1全量同步

檢視哨兵日誌(下面是其中一個哨兵日誌)，每個哨兵日誌都顯示頻繁發生重新選舉。

172.17.1.193的哨兵
[132436] 04 Jun 14:07:19.705 # +sdown master master 172.17.1.193 6379
[132436] 04 Jun 14:07:19.939 # +new-epoch 3
[132436] 04 Jun 14:07:19.955 # +vote-for-leader 7a359562268faaf4b588343b75fea8afbd6a2816 3
[132436] 04 Jun 14:07:20.345 # -sdown master master 172.17.1.193 6379
[132436] 04 Jun 14:07:21.234 # +config-update-from sentinel 7a359562268faaf4b588343b75fea8afbd6a2816 172.18.12.6 16380 @ master 172.17.1.193 6379
[132436] 04 Jun 14:07:21.234 # +switch-master master 172.17.1.193 6379 172.18.12.6 6380
[132436] 04 Jun 14:07:21.234 * +slave slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
[132436] 04 Jun 14:07:31.280 * +convert-to-slave slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
[132436] 04 Jun 14:10:23.333 # +sdown master master 172.18.12.6 6380
[132436] 04 Jun 14:10:23.442 # +odown master master 172.18.12.6 6380 #quorum 2/2
[132436] 04 Jun 14:10:23.442 # +new-epoch 4
[132436] 04 Jun 14:10:23.442 # +try-failover master master 172.18.12.6 6380
[132436] 04 Jun 14:10:23.442 # +vote-for-leader 1e28fa3c46c51d90d497412d75326034b9e439a0 4
[132436] 04 Jun 14:10:23.458 # 7a359562268faaf4b588343b75fea8afbd6a2816 voted for 7a359562268faaf4b588343b75fea8afbd6a2816 4
[132436] 04 Jun 14:10:23.489 # 872f1eee7d73890b2b4d75a2a0bead3f0a33603e voted for 7a359562268faaf4b588343b75fea8afbd6a2816 4
[132436] 04 Jun 14:10:24.643 # -sdown master master 172.18.12.6 6380
[132436] 04 Jun 14:10:24.643 # -odown master master 172.18.12.6 6380
[132436] 04 Jun 14:10:34.456 # -failover-abort-not-elected master master 172.18.12.6 6380
[132436] 04 Jun 14:12:33.734 # +sdown slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
[132436] 04 Jun 14:13:46.929 # -sdown slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
...
  • +sdown master master主觀下線主redis
  • new-epoch 3新一輪投票
  • vote-for-leader 7a359562268faaf4b588343b75fea8afbd6a2816 3選舉哨兵領導者
  • +sdown master master客觀下線主redis
  • config-update-from sentinel從哨兵更新配置，更新到本地，最終選舉出的主redis
  • switch-master master切換到主redis
  • slave slave 設定從redis
  • convert-to-slave主節點轉換為從節點
  • failover-abort-not-elected 選舉中止

+sdown表示認定主觀下線，-sdown是撤銷主觀下線

另一臺哨兵日誌

172.17.3.10的哨兵
[7152] 04 Jun 14:05:34.856 # +new-epoch 3
[7152] 04 Jun 14:05:34.872 # +vote-for-leader 7a359562268faaf4b588343b75fea8afbd6a2816 3
[7152] 04 Jun 14:05:35.106 # +sdown master master 172.17.1.193 6379
[7152] 04 Jun 14:05:35.185 # +odown master master 172.17.1.193 6379 #quorum 3/2
[7152] 04 Jun 14:05:35.185 # Next failover delay: I will not start a failover before Thu Jun 04 14:06:35 2020
[7152] 04 Jun 14:05:35.247 # -sdown master master 172.17.1.193 6379
[7152] 04 Jun 14:05:35.247 # -odown master master 172.17.1.193 6379
[7152] 04 Jun 14:05:36.153 # +config-update-from sentinel 7a359562268faaf4b588343b75fea8afbd6a2816 172.18.12.6 16380 @ master 172.17.1.193 6379
[7152] 04 Jun 14:05:36.153 # +switch-master master 172.17.1.193 6379 172.18.12.6 6380
[7152] 04 Jun 14:05:36.153 * +slave slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
[7152] 04 Jun 14:08:37.880 # +sdown master master 172.18.12.6 6380
[7152] 04 Jun 14:08:38.380 # +new-epoch 4
[7152] 04 Jun 14:08:38.380 # +vote-for-leader 7a359562268faaf4b588343b75fea8afbd6a2816 4
[7152] 04 Jun 14:08:39.021 # +odown master master 172.18.12.6 6380 #quorum 3/2
[7152] 04 Jun 14:08:39.021 # Next failover delay: I will not start a failover before Thu Jun 04 14:09:39 2020
[7152] 04 Jun 14:08:39.568 # -sdown master master 172.18.12.6 6380
[7152] 04 Jun 14:08:39.568 # -odown master master 172.18.12.6 6380
[7152] 04 Jun 14:10:48.584 # +sdown slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
[7152] 04 Jun 14:12:01.781 # -sdown slave 172.17.1.193:6379 172.17.1.193 6379 @ master 172.18.12.6 6380
...

Next failover delay 選舉時間間太短，等下一次選舉，避免網路短時間內波動造成頻繁主從切換。該時間間隔是down-after-milliseconds值的10倍

結論

仔細看哨兵redis發現，伺服器1.193的哨兵也會認為1.193的redis主觀下線sdown master master 172.17.1.193 6379，懷疑有可能是redis服務的問題，而不是網路問題。
檢視日誌發現有頻繁的fork operation complete 日誌，由於有全量同步和aof同步出現，fork執行緒和子執行緒處理完通知父執行緒後的邏輯處理都會有短暫阻塞。因此在RDB和AOF持久化時造成阻塞（當時的redis資料量達到9G），可能會導致哨兵誤認為節點主觀下線。
主從同步阻塞時，當增量資料超過配置的閾值或配置的時間，則會觸發全量資料同步。

redis主從配置注意點

  1. 控制Redis例項最大可用記憶體，fork耗時跟記憶體成正比。10GB的redis記憶體大約需要20MB的記憶體頁表，因此記憶體越大fork越耗時，正常情況大約每GB需要消耗20ms左右。可以通過latest_fork_usec檢視最後一次fork時間，單位是微秒。
  2. 儘可能關閉rdb持久化方式，rdb每次會全量儲存檔案，儲存需要雙倍資料記憶體，主從同步方式可以使用無硬碟模式，儘可能使用aof每秒儲存，若是4.X版本的redis，則使用rdb-aof模式，增量資料以aof追加，aof重寫時以rbd資料儲存。
  3. 哨兵主觀下線時間配置down-after-milliseconds不要配置太短，配置太短很可能造成頻繁發生主從切換。
  4. 增大主從同步的快取大小repl-backlog-size，當主從連線斷開重連後，若增量同步資料小於快取大小， 則僅需增量同步即可，無需全量同步。預設1MB
  5. 適當增大主從斷開全量同步時間超過配置的repl-backlog-ttl值會觸發全量同步，單位時秒。
  6. 當搭建了叢集，若超過半數節點無響應，則整個叢集會掛掉。當發生主從同步，持久化時節點可能阻塞，適當調整叢集通訊超時時間。cluster-node-timeout單位是毫秒。

相關文章