この記事はリクルートライフスタイル Advent Calendar 2017 の21日目の記事です。

はじめに

こんにちは！ホットペッパービューティでサーバサイド開発をしている @yuki-ogawa です。

自分はこれまで Redis を構築・運用した経験があるわけではないのですが、
最近、ホットペッパービューティーではセッション管理のために Redis が導入されたりと
プロダクションでの利用が進んでいるため、必要性を感じて個人的に勉強しています。

今回は、本番運用の上で重要になるレプリケーション機能に関連して、
2017年7月に stable がリリースされた Redis4.0 で、データ同期の仕組みが大きく変更されたため
ちょっと試してみよう、という趣旨で記事にしてみました。

Redis4.0から導入されたPSYNC2について

Redis4.0 へのバージョンアップにより様々な機能が提供されましたが、
その中の重要な機能として、新しいレプリケーションの仕組み（PSYNC2）があります。

PSYNC2 の概要については、こちらの記事が参考になります。
要約すると下記のようになるかと思います。

Redis3系以前の部分同期（PSYNC）には問題があり、slave が同一の master に再接続された時のみしか実行できなかった。
それにより、例えば master が何かしらの原因でダウンし、フェイルオーバーによって slave が master に昇格した場合、新しい master に他の slave が接続するたびに Full-Sync が走ってしまうためダウンタイムが長くなってしまうという問題が発生してしまう。
Redis4系で導入された PSYNC2 ではこの点が解決され、同一の master でなくても slave が再接続した際に部分同期することが可能になった。

試してみる

それでは、master がダウンして slave が master に昇格した時に、
Redis3系と4系で挙動にどのような違いが出るか試してみようと思います。

環境

Mac book のローカル環境内に Docker コンテナを立ち上げて比較してみました。
Redis Sentinel を利用してレプリケートされた Redis に対して自動でフェイルオーバーを行います。
Redis3系と4系のそれぞれを下記の構成で立ち上げます。
Dockerの設定まわりはdocker-redis-clusterを参考にさせていただきました。

master x 1, slave x 3, sentinel x 3の構成
Redis3系のバージョン： 3.2.11
Redis4系のバージョン： 4.0.5

方法

Redis3系, 4系それぞれの master に対して、used_memoryが 500MB 相当になるまでセット型のデータを挿入し、各 slave まで同期が完了することを確認する。
毎秒10のセット型データを挿入しながら、
master を一時停止する。

確認観点

上記の操作を行った時に、ログから下記の観点を確認してみようと思います。

昇格した master と slave 間のデータ同期が3系と4系でどのように異なっているか。
master のダウンを検知〜フェイルオーバー〜各 slave へのデータ同期が完了するまで、
どの程度時間がかかっているか。

結果

Redis3系の場合

Docker Composeのログをそのまま持ってきているので、少し見づらいです

// docker-compose pause master を実行
// Redis Sentinel により master のダウンが確認され、フェイルオーバーが走る。
sentinel_2  | 1:X 20 Dec 15:31:37.682 # +sdown master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:31:37.682 # +sdown master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:31:37.782 # +odown master mymaster 172.17.0.2 6379 #quorum 2/2
sentinel_3  | 1:X 20 Dec 15:31:37.782 # +new-epoch 1
sentinel_3  | 1:X 20 Dec 15:31:37.782 # +try-failover master mymaster 172.17.0.2 6379

：

// フェイルオーバー先の slave が選定され、master へ昇格
sentinel_3  | 1:X 20 Dec 15:31:37.788 # +vote-for-leader 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 1
sentinel_2  | 1:X 20 Dec 15:31:37.789 # +vote-for-leader e1687908fd6f5e716bc755a80dd1a57f4329f8e2 1
sentinel_2  | 1:X 20 Dec 15:31:37.790 # 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 voted for 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 1
sentinel_3  | 1:X 20 Dec 15:31:37.790 # e1687908fd6f5e716bc755a80dd1a57f4329f8e2 voted for e1687908fd6f5e716bc755a80dd1a57f4329f8e2 1
sentinel_1  | 1:X 20 Dec 15:31:37.792 # +new-epoch 1
sentinel_1  | 1:X 20 Dec 15:31:37.794 # +vote-for-leader 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 1
sentinel_2  | 1:X 20 Dec 15:31:37.795 # 040993890e99a20dfe921cd90cc7a7f215c3ebc1 voted for 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 1
sentinel_3  | 1:X 20 Dec 15:31:37.795 # 040993890e99a20dfe921cd90cc7a7f215c3ebc1 voted for 7b3a9a39d29bf1be3bb806267e168b5e6ad57365 1
sentinel_3  | 1:X 20 Dec 15:31:37.880 # +elected-leader master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:31:37.880 # +failover-state-select-slave master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:31:37.964 # +selected-slave slave 172.17.0.3:6379 172.17.0.3 6379 @ mymaster 172.17.0.2 6379

：

// 最後にデータ同期が走った slave_3 の同期が完了するまで
slave_3     | 1:S 20 Dec 15:32:19.004 # Connection with master lost.
slave_3     | 1:S 20 Dec 15:32:19.005 * Caching the disconnected master state.
slave_3     | 1:S 20 Dec 15:32:19.005 * Discarding previously cached master state.
slave_3     | 1:S 20 Dec 15:32:19.007 * SLAVE OF 172.17.0.3:6379 enabled (user request from 'id=14 addr=172.17.0.7:35642 fd=11 name=sentinel-e1687908-cmd age=40 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')
slave_3     | 1:S 20 Dec 15:32:19.643 * Connecting to MASTER 172.17.0.3:6379
slave_3     | 1:S 20 Dec 15:32:19.645 * MASTER <-> SLAVE sync started
slave_3     | 1:S 20 Dec 15:32:19.645 * Non blocking connect for SYNC fired the event.
slave_3     | 1:S 20 Dec 15:32:19.645 * Master replied to PING, replication can continue...
slave_3     | 1:S 20 Dec 15:32:19.646 * Partial resynchronization not possible (no cached master)
slave_3     | 1:S 20 Dec 15:32:19.655 * Full resync from master: b75d114b930fe4343862d3691d12f6effea05831:540002993
slave_3     | 1:S 20 Dec 15:32:22.074 * MASTER <-> SLAVE sync: receiving 95868775 bytes from master
slave_3     | 1:S 20 Dec 15:32:22.395 * MASTER <-> SLAVE sync: Flushing old data
slave_3     | 1:S 20 Dec 15:32:26.340 * MASTER <-> SLAVE sync: Loading DB in memory
slave_3     | 1:S 20 Dec 15:32:28.189 * MASTER <-> SLAVE sync: Finished with success

最後の slave_3 のデータ同期時にログに残っている通り、
フェイルオーバーにより master が変わっているため部分同期が実行できず、
Full-Resync が走っていることがわかります。

* Partial resynchronization not possible (no cached master)
* Full resync from master: b75d114b930fe4343862d3691d12f6effea05831:540002993

また、最初に Redis Sentinel が master down を検知してから、（15:31:37.782）
最後に slave_3 のデータ同期が完了するまで、（15:32:28.189）
おおよそ50秒程度かかっていることが分かります。

Redis4系の場合

// docker-compose pause master を実行
// Redis Sentinel により master のダウンが確認され、フェイルオーバーが走る。
sentinel_1  | 1:X 20 Dec 15:45:31.591 # +sdown master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:45:31.873 # +sdown master mymaster 172.17.0.2 6379
sentinel_2  | 1:X 20 Dec 15:45:31.912 # +sdown master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:45:31.964 # +odown master mymaster 172.17.0.2 6379 #quorum 2/2
sentinel_3  | 1:X 20 Dec 15:45:31.964 # +new-epoch 1
sentinel_3  | 1:X 20 Dec 15:45:31.964 # +try-failover master mymaster 172.17.0.2 6379

：

// フェイルオーバー先の slave が選定され、master へ昇格
sentinel_3  | 1:X 20 Dec 15:45:31.970 # +vote-for-leader 7898c8ba9a63a7e06dc855355802e545ab495d9c 1
sentinel_2  | 1:X 20 Dec 15:45:31.975 # +new-epoch 1
sentinel_2  | 1:X 20 Dec 15:45:31.978 # +vote-for-leader 7898c8ba9a63a7e06dc855355802e545ab495d9c 1
sentinel_2  | 1:X 20 Dec 15:45:31.978 # +odown master mymaster 172.17.0.2 6379 #quorum 3/2
sentinel_2  | 1:X 20 Dec 15:45:31.978 # Next failover delay: I will not start a failover before Wed Dec 20 15:45:42 2017
sentinel_3  | 1:X 20 Dec 15:45:31.979 # 3d8d153f374a52d10ca6c9b4a1f325e80c09f7c5 voted for 7898c8ba9a63a7e06dc855355802e545ab495d9c 1
sentinel_1  | 1:X 20 Dec 15:45:31.981 # +new-epoch 1
sentinel_1  | 1:X 20 Dec 15:45:31.984 # +vote-for-leader 7898c8ba9a63a7e06dc855355802e545ab495d9c 1
sentinel_3  | 1:X 20 Dec 15:45:31.985 # 0e1a63a63d6a04bf7c51175682ed5463ef5564e9 voted for 7898c8ba9a63a7e06dc855355802e545ab495d9c 1
sentinel_3  | 1:X 20 Dec 15:45:32.027 # +elected-leader master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:45:32.027 # +failover-state-select-slave master mymaster 172.17.0.2 6379
sentinel_3  | 1:X 20 Dec 15:45:32.111 # +selected-slave slave 172.17.0.3:6379 172.17.0.3 6379 @ mymaster 172.17.0.2 6379

：

// 最後にデータ同期が走った slave_3 の同期が完了するまで
slave_3     | 1:S 20 Dec 15:45:34.132 # Connection with master lost.
slave_3     | 1:S 20 Dec 15:45:34.133 * Caching the disconnected master state.
slave_3     | 1:S 20 Dec 15:45:34.133 * SLAVE OF 172.17.0.3:6379 enabled (user request from 'id=5 addr=172.17.0.7:35758 fd=11 name=sentinel-7898c8ba-cmd age=107 idle=0 flags=x db=0 sub=0 psub=0 multi=3 qbuf=14 qbuf-free=32754 obl=36 oll=0 omem=0 events=r cmd=exec')
slave_3     | 1:S 20 Dec 15:45:34.933 * Connecting to MASTER 172.17.0.3:6379
slave_3     | 1:S 20 Dec 15:45:34.934 * MASTER <-> SLAVE sync started
slave_3     | 1:S 20 Dec 15:45:34.934 * Non blocking connect for SYNC fired the event.
slave_3     | 1:S 20 Dec 15:45:34.935 * Master replied to PING, replication can continue...
slave_3     | 1:S 20 Dec 15:45:34.936 * Trying a partial resynchronization (request a08a1d2d8cf902db64e06fcdbb6a3a8c43baec1f:539997214).
slave_3     | 1:S 20 Dec 15:45:34.938 * Successful partial resynchronization with master.
slave_3     | 1:S 20 Dec 15:45:34.938 # Master replication ID changed to 2d2550ff67d8bc83486ae4ca93ba863e667e7263
slave_3     | 1:S 20 Dec 15:45:34.939 * MASTER <-> SLAVE sync: Master accepted a Partial Resynchronization.

Redis4系では最後の slave_3 のデータ同期時のログに下記のように記録されていました。
無事に部分同期が行われていることが分かります。

* Partial resynchronization request from 172.17.0.5:6379 accepted. Sending 563 bytes of backlog starting from offset 539997214.
* Trying a partial resynchronization (request a08a1d2d8cf902db64e06fcdbb6a3a8c43baec1f:539997214).
* Successful partial resynchronization with master.

また、Redis4系では、
最初に Redis Sentinel が master down を検知してから、（15:45:31.964）
最後に slave_3 のデータ同期が完了するまで、（15:45:34.939）
おおよそ3秒程度で済んでいることが分かります。

最後に

この記事では、Redis4.0 で新たに導入された PSYNC2 に焦点を当てつつ、
Redis3系と4系のフェイルオーバー時のデータ同期を比較して、4系で大きく改善していることを確認できました。

RELEASE NOTESにも記載がある通り、
Redis4.0は今までと比べても内部が大きく変更されたバージョンアップであり魅力的な機能が提供されるようになりましたが、まだまだバグは多く、マイナーバージョンのリリースが続いている状況です。
すぐに移行できるというわけではなさそうですが、タイミングを見極めつつ適切な時期に移行していけるとよいですね。