LoginSignup
3
2

More than 5 years have passed since last update.

@chaspy(Takeshi Kondo)

Galera ClusterでDBサービス正常終了時はsplit-brainは発生しない

Posted at

はじめに

MariaDB Galera Clusterでsplit-brainに悩まされてるみなさんこんにちは。

split-brainとは、クラスタが何らかの理由で分断されてしまった場合、その両方が「俺は何を信じればいいんだ？」という状態になり、両方ともデータベースが利用不能になる現象のことを言います。

split-brainが起きる仕組みについては以下のドキュメントを参照ください。

Weighted Quorum — Galera Cluster Documentation

対策としてはクラスタ内のノード数を奇数にしておくことや、Galera Arbitratorを採用することが考えられます。このあたりも詳細リンク先を見てください。

どんなときに分断するの

Split-Brainのテストについて、以下のドキュメントに記載されています。

Testing the Cluster — Galera Cluster Documentation

このドキュメントによると、以下のパターンでテスト可能なようです。

  • mysqldプロセスのkill
  • iptablesを用いた通信断
  • ノードの強制シャットダウン

サービス正常終了時は分断しないの

サービスを正常に終了した場合にはsplit-brainが起きないことは経験上分かっているのですが、ログ上どのような動きをするのかを追いかけてみようと思います。

split-brain検証

というわけで実験です。

バージョン

5.5.45です。

# rpm -qa | grep -e Maria -e galera
MariaDB-compat-5.5.45-1.el6.x86_64
MariaDB-client-5.5.45-1.el6.x86_64
galera-25.3.9-1.rhel6.el6.x86_64
MariaDB-common-5.5.45-1.el6.x86_64
MariaDB-Galera-server-5.5.45-1.el6.x86_64

クラスタ状態

クラスタサイズが2になっています。

# mysql -uroot -e "show status like 'wsrep_cluster%';"
+--------------------------+--------------------------------------+
| Variable_name            | Value                                |
+--------------------------+--------------------------------------+
| wsrep_cluster_conf_id    | 8                                    |
| wsrep_cluster_size       | 2                                    |
| wsrep_cluster_state_uuid | cf819ec9-e382-11e7-a390-768e47ae6c01 |
| wsrep_cluster_status     | Primary                              |
+--------------------------+--------------------------------------+

正常にservice終了した場合

残ったノードのクラスタ状態はこんな感じで、Primaryとして残存しています。

# mysql -uroot -e "show status like 'wsrep_cluster%';"
+--------------------------+--------------------------------------+
| Variable_name            | Value                                |
+--------------------------+--------------------------------------+
| wsrep_cluster_conf_id    | 9                                    |
| wsrep_cluster_size       | 1                                    |
| wsrep_cluster_state_uuid | cf819ec9-e382-11e7-a390-768e47ae6c01 |
| wsrep_cluster_status     | Primary                              |
+--------------------------+--------------------------------------+

クラスタサイズが変わったので、conf_idも進んでいます。

ではログを見てみましょう。終了した側のログは以下。

171218 14:27:23 [Note] /usr/sbin/mysqld: Normal shutdown

171218 14:27:23 [Note] WSREP: Stop replication
171218 14:27:23 [Note] WSREP: Closing send monitor...
171218 14:27:23 [Note] WSREP: Closed send monitor.
171218 14:27:23 [Note] WSREP: gcomm: terminating thread
171218 14:27:23 [Note] WSREP: gcomm: joining thread
171218 14:27:23 [Note] WSREP: gcomm: closing backend
171218 14:27:24 [Note] WSREP: view(view_id(NON_PRIM,0d383606,20) memb {
        0d383606,0
} joined {
} left {
} partitioned {
        d219a6d0,0
})
171218 14:27:24 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
171218 14:27:24 [Note] WSREP: view((empty))
171218 14:27:24 [Note] WSREP: gcomm: closed
171218 14:27:24 [Note] WSREP: Flow-control interval: [16, 16]
171218 14:27:24 [Note] WSREP: Received NON-PRIMARY.
171218 14:27:24 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 3189)
171218 14:27:24 [Note] WSREP: Received self-leave message.
171218 14:27:24 [Note] WSREP: Flow-control interval: [0, 0]
171218 14:27:24 [Note] WSREP: Received SELF-LEAVE. Closing connection.
171218 14:27:24 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 3189)
171218 14:27:24 [Note] WSREP: RECV thread exiting 0: Success
171218 14:27:24 [Note] WSREP: New cluster view: global state: cf819ec9-e382-11e7-a390-768e47ae6c01:3189, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
171218 14:27:24 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
171218 14:27:24 [Note] WSREP: New cluster view: global state: cf819ec9-e382-11e7-a390-768e47ae6c01:3189, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 3
171218 14:27:24 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
171218 14:27:24 [Note] WSREP: applier thread exiting (code:0)
171218 14:27:24 [Note] WSREP: recv_thread() joined.
171218 14:27:24 [Note] WSREP: Closing replication queue.
171218 14:27:24 [Note] WSREP: Closing slave action queue.
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:24 [Note] WSREP: applier thread exiting (code:6)
171218 14:27:26 [Note] WSREP: rollbacker thread exiting
171218 14:27:26 [Note] Event Scheduler: Purging the queue. 0 events
171218 14:27:26 [Note] WSREP: dtor state: CLOSED
171218 14:27:26 [Note] WSREP: apply mon: entered 0
171218 14:27:26 [Note] WSREP: apply mon: entered 0
171218 14:27:26 [Note] WSREP: mon: entered 14 oooe fraction 0 oool fraction 0
171218 14:27:26 [Note] WSREP: cert index usage at exit 0
171218 14:27:26 [Note] WSREP: cert trx map usage at exit 0
171218 14:27:26 [Note] WSREP: deps set usage at exit 0
171218 14:27:26 [Note] WSREP: avg deps dist 0
171218 14:27:26 [Note] WSREP: avg cert interval 0
171218 14:27:26 [Note] WSREP: cert index size 0
171218 14:27:26 [Note] WSREP: Service thread queue flushed.
171218 14:27:26 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0
171218 14:27:26 [Note] WSREP: MemPool(LocalTrxHandle): hit ratio: 0, misses: 0, in use: 0, in pool: 0
171218 14:27:26 [Note] WSREP: MemPool(SlaveTrxHandle): hit ratio: 0, misses: 0, in use: 0, in pool: 0
171218 14:27:26 [Note] WSREP: Shifting CLOSED -> DESTROYED (TO: 3189)
171218 14:27:26 [Note] WSREP: Flushing memory map to disk...
171218 14:27:26  InnoDB: Starting shutdown...
171218 14:27:27  InnoDB: Shutdown completed; log sequence number 3331948072
171218 14:27:27 [Note] /usr/sbin/mysqld: Shutdown complete

171218 14:27:27 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

さっそくNormal shutdownと出ていますから、通常に終了時は区別されているようです。残った側のノードのログを見てみましょう。

171218 15:20:44 [Note] WSREP: forgetting 0d383606 (tcp://192.168.100.102:4567)
171218 15:20:44 [Note] WSREP: Node d219a6d0 state prim
171218 15:20:44 [Note] WSREP: view(view_id(PRIM,d219a6d0,21) memb {
        d219a6d0,0
} joined {
} left {
} partitioned {
        0d383606,0
})
171218 15:20:44 [Note] WSREP: save pc into disk
171218 15:20:44 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
171218 15:20:44 [Note] WSREP: forgetting 0d383606 (tcp://192.168.100.102:4567)
171218 15:20:44 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 9451a788-e3bb-11e7-a7df-820fcfa02a5d
171218 15:20:44 [Note] WSREP: STATE EXCHANGE: sent state msg: 9451a788-e3bb-11e7-a7df-820fcfa02a5d
171218 15:20:44 [Note] WSREP: STATE EXCHANGE: got state msg: 9451a788-e3bb-11e7-a7df-820fcfa02a5d from 0 (maria1)
171218 15:20:44 [Note] WSREP: Quorum results:
        version    = 3,
        component  = PRIMARY,
        conf_id    = 8,
        members    = 1/1 (joined/total),
        act_id     = 3189,
        last_appl. = 0,
        protocols  = 0/7/3 (gcs/repl/appl),
        group UUID = cf819ec9-e382-11e7-a390-768e47ae6c01
171218 15:20:44 [Note] WSREP: Flow-control interval: [16, 16]
171218 15:20:44 [Note] WSREP: New cluster view: global state: cf819ec9-e382-11e7-a390-768e47ae6c01:3189, view# 9: Primary, number of nodes: 1, my index: 0, protocol version 3
171218 15:20:44 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
171218 15:20:44 [Note] WSREP: REPL Protocols: 7 (3, 2)
171218 15:20:44 [Note] WSREP: Service thread queue flushed.
171218 15:20:44 [Note] WSREP: Assign initial position for certification: 3189, protocol version: 3
171218 15:20:44 [Note] WSREP: Service thread queue flushed.
171218 15:20:49 [Note] WSREP:  cleaning up 0d383606 (tcp://192.168.100.102:4567)

(激しく時刻がズレててすみません...)

downしたnode(識別番号：0d383606)が落ちるとき、SELF-LEAVEと言って自らをグループから外し、それをメッセージとして送っているのでしょうか？

0d383606、このIPアドレスが192.168.100.102ですが、このノードをforgettingとしてメンバーから除外し、stateを更新し、最後にcleaning upとしています。

クラスタ閉塞は起きず、正常通り1台運用になっていますね。

mysqldプロセスをkillした場合

再びサービスを起動し、クラスタサイズが2であることを確認。

killall mysqldを実行すると、killallはデフォルトだとSIGTERM（15）なので、正常終了になります。

galeraのドキュメントにあった通り、-9でkillシグナルを送りましょう。

killされた側のmysqlのログにはほとんど出ません。プロセスないやで、ぐらいです。

171218 16:12:55 mysqld_safe Number of processes running now: 0
171218 16:12:55 mysqld_safe WSREP: not restarting wsrep node automatically
171218 16:12:55 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

次に残されたノードですが、non-Primaryになっています。

# mysql -uroot -e "show status like 'wsrep_cluster%';"
+--------------------------+--------------------------------------+
| Variable_name            | Value                                |
+--------------------------+--------------------------------------+
| wsrep_cluster_conf_id    | 18446744073709551615                 |
| wsrep_cluster_size       | 1                                    |
| wsrep_cluster_state_uuid | cf819ec9-e382-11e7-a390-768e47ae6c01 |
| wsrep_cluster_status     | non-Primary                          |
+--------------------------+--------------------------------------+

ログを見てみましょう。

171218 16:12:55 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers: tcp://192.168.100.102:4567 
171218 16:12:56 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') reconnecting to bc1c9308 (tcp://192.168.100.102:4567), attempt 0
171218 16:13:00 [Note] WSREP: evs::proto(d219a6d0, OPERATIONAL, view_id(REG,bc1c9308,24)) suspecting node: bc1c9308
171218 16:13:00 [Note] WSREP: evs::proto(d219a6d0, OPERATIONAL, view_id(REG,bc1c9308,24)) suspected node without join message, declaring inactive
171218 16:13:01 [Note] WSREP: view(view_id(NON_PRIM,bc1c9308,24) memb {
        d219a6d0,0
} joined {
} left {
} partitioned {
        bc1c9308,0
})
171218 16:13:01 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
171218 16:13:01 [Note] WSREP: Flow-control interval: [16, 16]
171218 16:13:01 [Note] WSREP: Received NON-PRIMARY.
171218 16:13:01 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 3189)
171218 16:13:01 [Note] WSREP: New cluster view: global state: cf819ec9-e382-11e7-a390-768e47ae6c01:3189, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
171218 16:13:01 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
171218 16:13:01 [Note] WSREP: view(view_id(NON_PRIM,d219a6d0,25) memb {
        d219a6d0,0
} joined {
} left {
} partitioned {
        bc1c9308,0
})
171218 16:13:01 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
171218 16:13:01 [Note] WSREP: Flow-control interval: [16, 16]
171218 16:13:01 [Note] WSREP: Received NON-PRIMARY.
171218 16:13:01 [Note] WSREP: New cluster view: global state: cf819ec9-e382-11e7-a390-768e47ae6c01:3189, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
171218 16:13:01 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
171218 16:13:41 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') reconnecting to bc1c9308 (tcp://192.168.100.102:4567), attempt 30
171218 16:14:27 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') reconnecting to bc1c9308 (tcp://192.168.100.102:4567), attempt 60
171218 16:15:12 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') reconnecting to bc1c9308 (tcp://192.168.100.102:4567), attempt 90
171218 16:15:57 [Note] WSREP: (d219a6d0, 'tcp://0.0.0.0:4567') reconnecting to bc1c9308 (tcp://192.168.100.102:4567), attempt 120
(以降リコネクトを続ける)

nonlive peersと、相手との断絶を検知したあと、たぶんあいつ死んだわとview_id(REG,bc1c9308,24)) suspected node without join message, declaring inactiveで言ってますね。

quorumのログとか出るのかなーと思ったんですが、しれーっとnon-primaryになってますね。

おわりに

galera clusterはサービス正常終了と突然死をちゃんと区別していることがわかりました。実装上の詳細はわからないのですが、ちゃんとSTATE EXCHANGEされてますから、そこで終了していることが知らされているのでしょう。

実験でした。

3
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
3
2