redisクラスタ障害解析
障害の表示:
ビジネス・レベルのプロンプト・クエリーredisに失敗しました
クラスタ構成:
3マスタ3スレーブ、ノードごとのデータは8 GB
マシン分布:
同じラックで、
xx.x.xxx.199
xx.x.xxx.200
xx.x.xxx.201
redis-serverプロセスのステータス:
コマンドps-eo pid,lstart|grep$pidにより、
プロセスが3ヶ月も続いていることがわかりました
障害発生前のクラスタのノード状態:
xx.x.xxx.200:8371(bedab2c537fe94f8c0363ac4ae97d56832316e65) master
xx.x.xxx.199:8373(792020fe66c00ae56e27cd7a048ba6bb2b67adb6) slave
xx.x.xxx.201:8375(5ab4f85306da6d633e4834b4d3327f45af02171b) master
xx.x.xxx.201:8372(826607654f5ec81c3756a4a21f357e644efe605a) slave
xx.x.xxx.199:8370(462cadcb41e635d460425430d318f2fe464665c5) master
xx.x.xxx.200:8374(1238085b578390f3c8efa30824fd9a4baba10ddf) slave
--------------------------------------以下はログ分析-----------------------------------------------------------ステップ1:
プライマリノード8371は、ノード8373からの接続を失う.
46590:M 09 Sep 18:57:51.379 # Connection with slave xx.x.xxx.199:8373 lost.
ステップ2:
プライマリノード8370/8375は、8371が接続されていないと判定する:
42645:M 09 Sep 18:57:50.117 * Marking node bedab2c537fe94f8c0363ac4ae97d56832316e65 as failing (quorum reached).
ステップ3:
ノード8372/8373/8374から、プライマリノード8375から8371が接続されていないというメッセージが受信される.
46986:S 09 Sep 18:57:50.120 * FAIL message received from 5ab4f85306da6d633e4834b4d3327f45af02171b about bedab2c537fe94f8c0363ac4ae97d56832316e65
ステップ4:
プライマリノード8370/8375ライセンス8373アップグレードプライマリノード転送:
42645:M 09 Sep 18:57:51.055 # Failover auth granted to 792020fe66c00ae56e27cd7a048ba6bb2b67adb6 for epoch 16
ステップ5:
マスタノード8371は、自身の構成を変更し、8373のスレーブノードとなる.
46590:M 09 Sep 18:57:51.488 # Configuration change detected. Reconfiguring myself as a replica of 792020fe66c00ae56e27cd7a048ba6bb2b67adb6
ステップ6:
メインノード8370/8375/8373は、8371の失敗状態を明確にする.
42645:M 09 Sep 18:57:51.522 * Clear FAIL state for node bedab2c537fe94f8c0363ac4ae97d56832316e65: master without slots is reachable again.
ステップ7:
新規スレーブノード8371は、新規マスターノード8373から開始され、第1の全量同期データ:
8373ログ:
4255:M 09 Sep 18:57:51.906 * Full resync requested by slave xx.x.xxx.200:8371
4255:M 09 Sep 18:57:51.906 * Starting BGSAVE for SYNC with target: disk
4255:M 09 Sep 18:57:51.941 * Background saving started by pid 5230
8371ログ:
46590:S 09 Sep 18:57:51.948 * Full resync from master: d7751c4ebf1e63d3baebea1ed409e0e7243a4423:440721826993
ステップ8:
プライマリノード8370/8375は、8373(新しいプライマリ)が接続されていないと判定する.
42645:M 09 Sep 18:58:00.320 * Marking node 792020fe66c00ae56e27cd7a048ba6bb2b67adb6 as failing (quorum reached).
ステップ9:
プライマリノード8370/8375判定8373(新規プライマリ)リカバリ:
60295:M 09 Sep 18:58:18.181 * Clear FAIL state for node 792020fe66c00ae56e27cd7a048ba6bb2b67adb6: is reachable again and nobody is serving its slots after some time.
ステップ10:
マスターノード8373は、全量同期に必要なBGSAVE動作を完了する.
5230:C 09 Sep 18:59:01.474 * DB saved on disk
5230:C 09 Sep 18:59:01.491 * RDB: 7112 MB of memory used by copy-on-write
4255:M 09 Sep 18:59:01.877 * Background saving terminated with success
ステップ11:
ノード8371からプライマリノード8373からのデータの受信が開始される.
46590:S 09 Sep 18:59:02.263 * MASTER SLAVE sync: receiving 2657606930 bytes from master
ステップ12:
プライマリノード8373は、ノード8371からoutput bufferが制限されていることを発見する.
4255:M 09 Sep 19:00:19.014 # Client id=14259015 addr=xx.x.xxx.200:21772 fd=844 name= age=148 idle=148 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16349 oll=4103 omem=95944066 events=rw cmd=psync scheduled to be closed ASAP for overcoming of output buffer limits.
4255:M 09 Sep 19:00:19.015 # Connection with slave xx.x.xxx.200:8371 lost.
ステップ13:
ノード8371からプライマリノード8373からのデータの同期に失敗し、接続が切断され、第1の全量同期に失敗した.
46590:S 09 Sep 19:00:19.018 # I/O error trying to sync with MASTER: connection lost
46590:S 09 Sep 19:00:20.102 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:20.102 * MASTER SLAVE sync started
ステップ14:
ノード8371から同期を再開し、接続に失敗し、メインノード8373の接続数がいっぱいになった.
46590:S 09 Sep 19:00:21.103 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:21.103 * MASTER SLAVE sync started
46590:S 09 Sep 19:00:21.104 * Non blocking connect for SYNC fired the event.
46590:S 09 Sep 19:00:21.104 # Error reply to PING from master: '-ERR max number of clients reached'
ステップ15:
ノード8371からプライマリノード8373に再接続し、2回目にフル同期を開始する.
8371ログ:
46590:S 09 Sep 19:00:49.175 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:49.175 * MASTER SLAVE sync started
46590:S 09 Sep 19:00:49.175 * Non blocking connect for SYNC fired the event.
46590:S 09 Sep 19:00:49.176 * Master replied to PING, replication can continue...
46590:S 09 Sep 19:00:49.179 * Partial resynchronization not possible (no cached master)
46590:S 09 Sep 19:00:49.501 * Full resync from master: d7751c4ebf1e63d3baebea1ed409e0e7243a4423:440780763454
8373ログ:
4255:M 09 Sep 19:00:49.176 * Slave xx.x.xxx.200:8371 asks for synchronization
4255:M 09 Sep 19:00:49.176 * Full resync requested by slave xx.x.xxx.200:8371
4255:M 09 Sep 19:00:49.176 * Starting BGSAVE for SYNC with target: disk
4255:M 09 Sep 19:00:49.498 * Background saving started by pid 18413
18413:C 09 Sep 19:01:52.466 * DB saved on disk
18413:C 09 Sep 19:01:52.620 * RDB: 2124 MB of memory used by copy-on-write
4255:M 09 Sep 19:01:53.186 * Background saving terminated with success
ステップ16:
ノード8371からデータの同期に成功し、メモリのロードを開始する.
46590:S 09 Sep 19:01:53.190 * MASTER SLAVE sync: receiving 2637183250 bytes from master
46590:S 09 Sep 19:04:51.485 * MASTER SLAVE sync: Flushing old data
46590:S 09 Sep 19:05:58.695 * MASTER SLAVE sync: Loading DB in memory
ステップ17:
クラスタが正常に戻りました:
42645:M 09 Sep 19:05:58.786 * Clear FAIL state for node bedab2c537fe94f8c0363ac4ae97d56832316e65: slave is reachable again.
ステップ18:
ノード8371からのデータの同期に成功し、7分かかりました.
46590:S 09 Sep 19:08:19.303 * MASTER SLAVE sync: Finished with success
8371不整合原因分析:
何台かの機器が同じラックにあるため、ネットワークが途切れることはあり得ません.
そこでSLOWLOG GETコマンドでスロークエリーログを見てみると、KEYSコマンドが実行され、8.3秒かかりました.
クラスタノードのタイムアウト設定を確認すると、5 s(cluster-node-timeout 5000)
ノードが接続されていない理由:
クライアントは8.3 sのコマンドを1本実行し、
2016/9/9 18:57:43 KEYSコマンドの実行開始
2016/9/9 18:57:50 8371不一致と判断された(redisログ)
2016/9/9 18:57:51 KEYSコマンドの実行完了
まとめると、次のような質問があります.
1.cluster-node-timeout設定が比較的短いため、遅いクエリKEYSはクラスタ判定ノード8371の接続を失った
2.8371が接続されていないため、8373のアップグレードを主とし、主従同期を開始する
3.client-output-buffer-limitの構成の制限により、初回のフル同期に失敗しました
4.PHPクライアントの接続プールに問題があるため、サーバーに狂ったように接続し、SYN攻撃のような効果を生んだ
5.初回フル同期に失敗した後、ノードからプライマリノードを再接続するのに30秒かかった(最大接続数1 wを超えた)
Client-output-buffer-limitパラメータについて:
対策:
1.単一インスタンスのカットを4 G以下にしないと、プライマリ・スレーブの切り替えに時間がかかる
2.client-output-buffer-limitパラメータを調整し、同期が半分に失敗しないようにする
3.cluster-node-timeoutを15 s以上調整する
4.cluster-node-timeoutを超える時間のかかる遅いクエリーは、プライマリ・セカンダリ・スイッチが発生するため禁止されます.
5.クライアントのSYN攻撃のような狂った接続方式を修復する
原文の出典:http://blog.csdn.net/daiyudong2020/article/details/52496725
End;
ビジネス・レベルのプロンプト・クエリーredisに失敗しました
クラスタ構成:
3マスタ3スレーブ、ノードごとのデータは8 GB
マシン分布:
同じラックで、
xx.x.xxx.199
xx.x.xxx.200
xx.x.xxx.201
redis-serverプロセスのステータス:
コマンドps-eo pid,lstart|grep$pidにより、
プロセスが3ヶ月も続いていることがわかりました
障害発生前のクラスタのノード状態:
xx.x.xxx.200:8371(bedab2c537fe94f8c0363ac4ae97d56832316e65) master
xx.x.xxx.199:8373(792020fe66c00ae56e27cd7a048ba6bb2b67adb6) slave
xx.x.xxx.201:8375(5ab4f85306da6d633e4834b4d3327f45af02171b) master
xx.x.xxx.201:8372(826607654f5ec81c3756a4a21f357e644efe605a) slave
xx.x.xxx.199:8370(462cadcb41e635d460425430d318f2fe464665c5) master
xx.x.xxx.200:8374(1238085b578390f3c8efa30824fd9a4baba10ddf) slave
--------------------------------------以下はログ分析-----------------------------------------------------------ステップ1:
プライマリノード8371は、ノード8373からの接続を失う.
46590:M 09 Sep 18:57:51.379 # Connection with slave xx.x.xxx.199:8373 lost.
ステップ2:
プライマリノード8370/8375は、8371が接続されていないと判定する:
42645:M 09 Sep 18:57:50.117 * Marking node bedab2c537fe94f8c0363ac4ae97d56832316e65 as failing (quorum reached).
ステップ3:
ノード8372/8373/8374から、プライマリノード8375から8371が接続されていないというメッセージが受信される.
46986:S 09 Sep 18:57:50.120 * FAIL message received from 5ab4f85306da6d633e4834b4d3327f45af02171b about bedab2c537fe94f8c0363ac4ae97d56832316e65
ステップ4:
プライマリノード8370/8375ライセンス8373アップグレードプライマリノード転送:
42645:M 09 Sep 18:57:51.055 # Failover auth granted to 792020fe66c00ae56e27cd7a048ba6bb2b67adb6 for epoch 16
ステップ5:
マスタノード8371は、自身の構成を変更し、8373のスレーブノードとなる.
46590:M 09 Sep 18:57:51.488 # Configuration change detected. Reconfiguring myself as a replica of 792020fe66c00ae56e27cd7a048ba6bb2b67adb6
ステップ6:
メインノード8370/8375/8373は、8371の失敗状態を明確にする.
42645:M 09 Sep 18:57:51.522 * Clear FAIL state for node bedab2c537fe94f8c0363ac4ae97d56832316e65: master without slots is reachable again.
ステップ7:
新規スレーブノード8371は、新規マスターノード8373から開始され、第1の全量同期データ:
8373ログ:
4255:M 09 Sep 18:57:51.906 * Full resync requested by slave xx.x.xxx.200:8371
4255:M 09 Sep 18:57:51.906 * Starting BGSAVE for SYNC with target: disk
4255:M 09 Sep 18:57:51.941 * Background saving started by pid 5230
8371ログ:
46590:S 09 Sep 18:57:51.948 * Full resync from master: d7751c4ebf1e63d3baebea1ed409e0e7243a4423:440721826993
ステップ8:
プライマリノード8370/8375は、8373(新しいプライマリ)が接続されていないと判定する.
42645:M 09 Sep 18:58:00.320 * Marking node 792020fe66c00ae56e27cd7a048ba6bb2b67adb6 as failing (quorum reached).
ステップ9:
プライマリノード8370/8375判定8373(新規プライマリ)リカバリ:
60295:M 09 Sep 18:58:18.181 * Clear FAIL state for node 792020fe66c00ae56e27cd7a048ba6bb2b67adb6: is reachable again and nobody is serving its slots after some time.
ステップ10:
マスターノード8373は、全量同期に必要なBGSAVE動作を完了する.
5230:C 09 Sep 18:59:01.474 * DB saved on disk
5230:C 09 Sep 18:59:01.491 * RDB: 7112 MB of memory used by copy-on-write
4255:M 09 Sep 18:59:01.877 * Background saving terminated with success
ステップ11:
ノード8371からプライマリノード8373からのデータの受信が開始される.
46590:S 09 Sep 18:59:02.263 * MASTER SLAVE sync: receiving 2657606930 bytes from master
ステップ12:
プライマリノード8373は、ノード8371からoutput bufferが制限されていることを発見する.
4255:M 09 Sep 19:00:19.014 # Client id=14259015 addr=xx.x.xxx.200:21772 fd=844 name= age=148 idle=148 flags=S db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16349 oll=4103 omem=95944066 events=rw cmd=psync scheduled to be closed ASAP for overcoming of output buffer limits.
4255:M 09 Sep 19:00:19.015 # Connection with slave xx.x.xxx.200:8371 lost.
ステップ13:
ノード8371からプライマリノード8373からのデータの同期に失敗し、接続が切断され、第1の全量同期に失敗した.
46590:S 09 Sep 19:00:19.018 # I/O error trying to sync with MASTER: connection lost
46590:S 09 Sep 19:00:20.102 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:20.102 * MASTER SLAVE sync started
ステップ14:
ノード8371から同期を再開し、接続に失敗し、メインノード8373の接続数がいっぱいになった.
46590:S 09 Sep 19:00:21.103 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:21.103 * MASTER SLAVE sync started
46590:S 09 Sep 19:00:21.104 * Non blocking connect for SYNC fired the event.
46590:S 09 Sep 19:00:21.104 # Error reply to PING from master: '-ERR max number of clients reached'
ステップ15:
ノード8371からプライマリノード8373に再接続し、2回目にフル同期を開始する.
8371ログ:
46590:S 09 Sep 19:00:49.175 * Connecting to MASTER xx.x.xxx.199:8373
46590:S 09 Sep 19:00:49.175 * MASTER SLAVE sync started
46590:S 09 Sep 19:00:49.175 * Non blocking connect for SYNC fired the event.
46590:S 09 Sep 19:00:49.176 * Master replied to PING, replication can continue...
46590:S 09 Sep 19:00:49.179 * Partial resynchronization not possible (no cached master)
46590:S 09 Sep 19:00:49.501 * Full resync from master: d7751c4ebf1e63d3baebea1ed409e0e7243a4423:440780763454
8373ログ:
4255:M 09 Sep 19:00:49.176 * Slave xx.x.xxx.200:8371 asks for synchronization
4255:M 09 Sep 19:00:49.176 * Full resync requested by slave xx.x.xxx.200:8371
4255:M 09 Sep 19:00:49.176 * Starting BGSAVE for SYNC with target: disk
4255:M 09 Sep 19:00:49.498 * Background saving started by pid 18413
18413:C 09 Sep 19:01:52.466 * DB saved on disk
18413:C 09 Sep 19:01:52.620 * RDB: 2124 MB of memory used by copy-on-write
4255:M 09 Sep 19:01:53.186 * Background saving terminated with success
ステップ16:
ノード8371からデータの同期に成功し、メモリのロードを開始する.
46590:S 09 Sep 19:01:53.190 * MASTER SLAVE sync: receiving 2637183250 bytes from master
46590:S 09 Sep 19:04:51.485 * MASTER SLAVE sync: Flushing old data
46590:S 09 Sep 19:05:58.695 * MASTER SLAVE sync: Loading DB in memory
ステップ17:
クラスタが正常に戻りました:
42645:M 09 Sep 19:05:58.786 * Clear FAIL state for node bedab2c537fe94f8c0363ac4ae97d56832316e65: slave is reachable again.
ステップ18:
ノード8371からのデータの同期に成功し、7分かかりました.
46590:S 09 Sep 19:08:19.303 * MASTER SLAVE sync: Finished with success
8371不整合原因分析:
何台かの機器が同じラックにあるため、ネットワークが途切れることはあり得ません.
そこでSLOWLOG GETコマンドでスロークエリーログを見てみると、KEYSコマンドが実行され、8.3秒かかりました.
クラスタノードのタイムアウト設定を確認すると、5 s(cluster-node-timeout 5000)
ノードが接続されていない理由:
クライアントは8.3 sのコマンドを1本実行し、
2016/9/9 18:57:43 KEYSコマンドの実行開始
2016/9/9 18:57:50 8371不一致と判断された(redisログ)
2016/9/9 18:57:51 KEYSコマンドの実行完了
まとめると、次のような質問があります.
1.cluster-node-timeout設定が比較的短いため、遅いクエリKEYSはクラスタ判定ノード8371の接続を失った
2.8371が接続されていないため、8373のアップグレードを主とし、主従同期を開始する
3.client-output-buffer-limitの構成の制限により、初回のフル同期に失敗しました
4.PHPクライアントの接続プールに問題があるため、サーバーに狂ったように接続し、SYN攻撃のような効果を生んだ
5.初回フル同期に失敗した後、ノードからプライマリノードを再接続するのに30秒かかった(最大接続数1 wを超えた)
Client-output-buffer-limitパラメータについて:
# The syntax of every client-output-buffer-limit directive is the following:
#
# client-output-buffer-limit
#
# A client is immediately disconnected once the hard limit is reached, or if
# the soft limit is reached and remains reached for the specified number of
# seconds (continuously).
# So for instance if the hard limit is 32 megabytes and the soft limit is
# 16 megabytes / 10 seconds, the client will get disconnected immediately
# if the size of the output buffers reach 32 megabytes, but will also get
# disconnected if the client reaches 16 megabytes and continuously overcomes
# the limit for 10 seconds.
#
# By default normal clients are not limited because they don't receive data
# without asking (in a push way), but just after a request, so only
# asynchronous clients may create a scenario where data is requested faster
# than it can read.
#
# Instead there is a default limit for pubsub and slave clients, since
# subscribers and slaves receive data in a push fashion.
#
# Both the hard or the soft limit can be disabled by setting them to zero.
client-output-buffer-limit normal 0 0 0
client-output-buffer-limit slave 256mb 64mb 60
client-output-buffer-limit pubsub 32mb 8mb 60 対策:
1.単一インスタンスのカットを4 G以下にしないと、プライマリ・スレーブの切り替えに時間がかかる
2.client-output-buffer-limitパラメータを調整し、同期が半分に失敗しないようにする
3.cluster-node-timeoutを15 s以上調整する
4.cluster-node-timeoutを超える時間のかかる遅いクエリーは、プライマリ・セカンダリ・スイッチが発生するため禁止されます.
5.クライアントのSYN攻撃のような狂った接続方式を修復する
原文の出典:http://blog.csdn.net/daiyudong2020/article/details/52496725
End;