こんにちは。
サイオステクノロジーの宇野です。LifeKeeperの開発を担当しています。
今回から３回に分け、“Higher Availability DB”についてご紹介していきます。
HAクラスターのHAは、高可用性（High Availability）を実現するクラスターシステムのことですが、“Higher” Availabilityは、比較級の”Higher”からご推測の通り、従来のHAクラスターで提供するHAに比べて“より高い” 可用性を実現することを目指す、サイオスの造語です。
サイオスでは、“Higher Availability DB” と題して、「障害検知からフェイルオーバー完了（待機系でのサービス再開）までを30秒以内で完了する」というゴールを設定し、可用性を向上するための一連の試みを、“Higher Availability“ソリューションとしてご提案していく予定です。
今回は、その中でもPostgreSQLでより高い可用性を目指す手法について、実験結果をご報告したいと思います。
なお、本連載ではより迅速な障害検知～復旧を目指して、短縮が可能な処理ごとに３回に分け、それぞれの処理をどの程度短くできるのかを検証していきたいと思います。
第1回 リソース監視処理時間の測定と短縮方法
第2回 ノード監視処理の短縮方法
第3回 その他の短縮方法を考える
短縮できるリカバリー処理と確認方法
HAより高い可用性を考えるために、まず従来のHAクラスターでのリカバリー処理を見ていきます。一般的に、HAクラスターソフトウェア では、以下の手順でリカバリー処理が行われます。
- 一定間隔で行われる監視処理
- 監視による障害検出
- ローカルリカバリー（障害ノードでのサービス再起動によるリカバリー）
- フェイルオーバーリカバリー（ノードを変更してサービスを起動し、復旧）
これらの処理をより迅速に行う、もしくはリカバリーの望めない処理をスキップするといった方法を取れば、より早いリカバリーを目指すことが可能です。短縮することが可能な処理は以下の2つです。
- 監視処理
- フェイルオーバーリカバリー
LifeKeeper for Linux の監視処理は、デフォルトでは120秒(LKCHECKINTERVAL=120)間隔で行うよう設定されています。この間隔を短縮することで、より早く障害を検出できます。ただしその場合は、以下の点に気を付ける必要があります。
- LifeKeeper for Linuxは、LKCHECKINTERVALの間隔内で全てのリソースの監視処理を終える必要があります。監視処理の間隔を短縮しすぎて処理が終わらない状況を避けるため、リソースの数や種類を考慮して監視間隔を設定します。
- システム平常時とシステム高負荷時では、監視処理にかかる時間が変わる場合があります。
以上のことから、デフォルト値より短縮する設定はサイオスとして推奨してはいませんが、「リソース数が少なく、高負荷状態にならないシステム」という前提であれば、設定値を短くすることで障害検出までの時間短縮を実現することは可能です 。
なお、各リソースの監視処理は、通常ログ(/var/log/lifekeeper.log)に出力されません。具体的にリソースごとの監視処理にどのような処理を行い、どの程度時間がかかっているのかを確認するためには、各リソースのデバッグモードを有効にすることで確認が可能です。
例として、以下のような一般的な構成を想定して、PostgreSQL, File system, Data Replication,IPリソースの監視処理をデバッグモードで確認することで、監視間隔を検討するための情報が取得してみます。
- PostgreSQL リソースの場合
以下のパラメータを/etc/default/LifeKeeperに追加してからLifeKeeperを再起動し、その監視処理に要する時間を測定します。LKPGSQLDEBUG=5
PostgreSQL リソースのデバッグモードを無効化する場合は、パラメータを削除して、LifeKeeperを再起動することが必要です。
- File System, Data Replication, IPリソースの場合
それぞれ以下のコマンドでデバッグフラグを作成し、出力するログから処理時間を測定します。# flg_create –f debug_filesys
# flg_create –f debug_dr
# flg_create –f debug_ipフラグ設定の状況については、以下のコマンドで確認できます。
# flg_list
デバッグモードを無効にする場合は、以下のコマンドでフラグを削除します。
# flg_remove –f debug_filesys
# flg_remove –f debug_dr
# flg_remove –f debug_ip
デバッグモードは、調査目的では詳細ログを出力して使用しますが、普段の運用では、ログの出力が冗長となります。そのため、調査後には、また無効化してください。
実際の測定ログからリソースの監視処理間隔を確認する
では、実際にデバッグオプションを有効にして監視処理時間の測定を行ってみましょう。
先ほど説明した通り、各リソースの状況を確認する監視処理は、LifeKeeperの初期設定として監視パラメータ（LKCHECKINTERVAL）で設定された値（120）秒の間隔で行われます。LifeKeeper を起動した時間を起点にして、以下のように120秒間隔で各リソースの監視処理(quickCheck)スクリプトが直列に実行されます。
監視処理が完了するまでに要する時間は、負荷状況やハードウェアリソース、外的要因等の影響で変わります。現在の処理は、次回の監視処理が始まるまでに完了しなければならないので、十分な処理間隔を設けることが推奨されています。そのため、サポートの観点では、120秒より短くすることは推奨していません。誤検知した場合には、値を120秒に戻していただくことになります。
以上のことを念頭に置きつつ、現在のリソース構成ではどの程度監視処理に時間を要しているかを測定してから、以下のとおり監視間隔を縮小してみて、障害の検出速度を高めることができるか検証してみます。
監視間隔を定義するパラメータ（LKCHECKINTERVAL）は、設定ファイル/etc/default/LifeKeeperに定義されています。
LKCHECKINTERVAL=120
パラメータの値を変更した場合、lkcheck デーモンに変更した事を反映させるために、LifeKeeperの再起動を行います。
# lkstop –f; lkstart
今回の検証環境は以下のとおりです。CPUコア数とメモリを多めに設定しました。
Server : VM(vSphere6) x2
CPU: Intel(R) Xeon(R) CPU E5-2660 0 @ 2.20GHz (4 core)
MemTotal: 8073684 kB
Disk: /dev/sda: 17.2 GB
/dev/sdb: 10.7 GB
Network: 1000Mbps x2
OS : CentOS Linux release 7.2.1511
Kernel Version: 3.10.0-327.el7.x86_64
DB: postgresql v9.4.8
上記の構成のサーバーに、Protection Suite for Linux v9.1をインストールし、以下のリソース構成としました。2ノードクラスター＋Quorum/Witness サーバーの構成です。
次に、この構成で実際に行われる監視処理スクリプトで要する時間を測定します。監視処理はリソースごとに下位リソースから順に監視処理が実行されますので、Data Replicationリソース、（IPリソース、Filesystemリソース）、PostgreSQLリソースの順番でチェックされます。
監視処理が稼働している事を確認するため、Activeノード”pd108”で以下のようにデバッグオプションを有効化しました。監視処理に成功した場合、正常に稼働している事を示すログは出力されません。そのため、デバッグログを有効にすることで、正常時に監視処理が終了した時のログを確認することができるようになります。
[root@pd108 ~]# flg_list
debug_ip
debug_filesys
debug_dr
[root@pd108 ~]#
[root@pd108 ~]# grep LKPGSQLDEBUG /etc/default/LifeKeeper
LKPGSQLDEBUG=5
[root@pd108 ~]#
初期設定である120秒の監視間隔で、監視処理に要する時間を測定します。
アイドル時
まずはアイドル時（postgresqlにアクセスが無い状態）の/var/log/lifekeeper.logを確認して、監視処理で出力するログから時間を測定しました。アイドル時の監視処理に要した時間は、15秒でした。以下がログの抜粋です。
— アイドル時 —
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:/opt/LifeKeeper/lkadm/subsys/scsi/netraid/bin/mdadm
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:mdadm – v3.2.6 – 25th October 2012
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:/opt/LifeKeeper/lkadm/subsys/scsi/netraid/bin/mdadm
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:mdadm – v3.2.6 – 25th October 2012
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:getId: -b: -p:1 -i: -s:pd108.labs.sios.com /dev/sdb1
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:getId: /opt/LifeKeeper/lkadm/subsys/scsi/DEVNAME/bin/getId -b “/dev/sdb1” returned “/dev/sdb1”
Aug 19 10:56:43 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000:get mirrorinfo 0: pd108.labs.sios.com#0010#001type:1#0010#0010#0010#001#0010#0010#0010#001#0011
Aug 19 10:56:43 pd108 quickCheck[10972]: DEBUG:dr:::104001:get mirrorinfo 0: pd108.labs.sios.com#0010#001type:1#0010#0010#0010#001#0010#0010#0010#001#0011
Aug 19 10:56:43 pd108 quickCheck[10972]: DEBUG:dr:::104001:get mirrorinfo 0: pd109.labs.sios.com#0011#001172.16.1.109#0010#0010#0010#001#0010#0010#0010#001#0011
:
<省略>
:
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): DESTROY: Destroying object defined for resource (pgsql-5432)
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: starting for 5432, /usr/local/pgsql/data, /tmp, psql, pg_ctl, postgres on pd108.labs.sios.com (11071)
Aug 19 10:56:58 pd108 quickCheck[11071]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=11071] clients=<>
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=11071] clients=<>
Aug 19 10:56:58 pd108 quickCheck[11071]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=11071] utils=<>
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=11071] utils=<>
Aug 19 10:56:58 pd108 quickCheck[11071]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=11071] No pid(s) where found to clean up on behalf of 11071
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=11071] No pid(s) where found to clean up on behalf of 11071
Aug 19 10:56:58 pd108 quickCheck[11071]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=11071] Set to return 0 (signaled )
Aug 19 10:56:58 pd108 lkcheck[1928]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=11071] Set to return 0 (signaled )
— アイドル時 —
運用時
続いて、運用時（TPCC-UVa を使用したRun testを通常運用時に見立てて実施）に監視処理に要した時間を測定しました。TPCC-UVaはTPC-Cに準じたベンチマークソフトウェアですが、実際の物流業務のトランザクション処理に近い環境を作りだすことができることと、2014年に久しぶりに新しいバージョンが公開されていたことから、運用時の負荷を実現するベンチマークとして今回使用しました。
結果、Run test実施時には、CPUの使用率が50％前後まで上がりましたが、4Coreで使用していることもあり、監視処理に要した時間は15秒で、アイドル時と比較しても差は出ませんでした。ログは以下の通りです。
— Run test時—
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:/opt/LifeKeeper/lkadm/subsys/scsi/netraid/bin/mdadm
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:mdadm – v3.2.6 – 25th October 2012
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:/opt/LifeKeeper/lkadm/subsys/scsi/netraid/bin/mdadm
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:mdadm – v3.2.6 – 25th October 2012
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:getId: -b: -p:1 -i: -s:pd108.labs.sios.com /dev/sdb1
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:getId: /opt/LifeKeeper/lkadm/subsys/scsi/DEVNAME/bin/getId -b “/dev/sdb1” returned “/dev/sdb1”
Aug 18 11:22:01 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000:get mirrorinfo 0: pd108.labs.sios.com#0010#001type:1#0010#0010#0010#001#0010#0010#0010#001#0011
Aug 18 11:22:01 pd108 quickCheck[24481]: DEBUG:dr:::104001:get mirrorinfo 0: pd108.labs.sios.com#0010#001type:1#0010#0010#0010#001#0010#0010#0010#001#0011
:
<省略>
:
Aug 18 11:22:16 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: starting for 5432, /usr/local/pgsql/data, /tmp, psql, pg_ctl, postgres on pd108.labs.sios.com (24585)
Aug 18 11:22:16 pd108 quickCheck[24585]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=24585] clients=<>
Aug 18 11:22:16 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=24585] clients=<>
Aug 18 11:22:16 pd108 quickCheck[24585]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=24585] utils=<>
Aug 18 11:22:16 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=24585] utils=<>
Aug 18 11:22:16 pd108 quickCheck[24585]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=24585] No pid(s) where found to clean up on behalf of 24585
Aug 18 11:22:16 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=24585] No pid(s) where found to clean up on behalf of 24585
Aug 18 11:22:16 pd108 quickCheck[24585]: INFO:RKBase:quickCheck::000000:#011DEBUG(pgsql):#011cleaner: [our pid=24585] Set to return 0 (signaled )
Aug 18 11:22:16 pd108 lkcheck[11494]: ERROR:runit:uncaught_error::000000: DEBUG(pgsql): cleaner: [our pid=24585] Set to return 0 (signaled )
— Run test時—
なお、上記の試験を行う前に、CPU:1Core メモリ2GBの構成でもアイドル時と運用時それぞれで同じ確認を行っています。この構成ではアイドル時15秒とRun test時24秒と監視処理に要する時間に差があったのですが、より現実的なハードウェアリソースでの検証を行なおうと考え、パフォーマンスを向上させました。結果として、アイドル時も運用時も監視処理にも要する時間の差は無くなりました。メモリの使用量には大きな変化が無かったので、マルチコアCPUのパフォーマンスが影響して、差が無くなったと考えられます。
リソースの監視処理間隔を短縮する
ふたつのテストで確認した監視処理時間(約15秒)を元に、監視間隔（LKCHECKINTERVAL）の短縮を行います。まず、以下のように実際の監視間隔より監視処理が長くなった場合に出力するメッセージを確認します。
アイドル時の監視処理時間が15秒だったので、監視間隔の設定パラメータ（LKCHECKINTERVAL）を13に変更すると、ほぼ確実に以下のログが13秒間隔で出力されるようになりました。
ERROR:lkcheck:::006014:LKCHECKINTERVAL parameter is too short. It is currently set to 13 seconds. It should be at least 16 seconds. Please adjust this parameter in /etc/default/LifeKeeper and execute ‘kill 31681’ to restart the lkcheck daemon.
上記のメッセージは、監視間隔の設定パラメータ（LKCHECKINTERVAL）が短すぎる事を示しています。この場合は、監視間隔ごとに実行される監視処理は実行されず、終了しなかった監視処理が終了するまで継続されます。こうなると監視処理が指定の時間内に全て完了しなくなり、障害の検出に遅延が発生する恐れがあります。したがって、監視処理が完了するのに十分な値に、監視間隔の設定パラメータを変更する必要があります。
またPostgreSQL ARK には、初期値としてLKCHECKINTERVALを26秒以下に設定した場合、以下のメッセージを出力する仕様がありました。
INFO:pgsql:quickCheck::113039:The value of the LKCHECKINTERVAL 13 is lower than the required check interval of 26 for PostgreSQL. Increase the value of LKCHECKINTERVAL.
つまり、監視間隔の設定は26秒以上に設定する必要があります。
これらの監視に要する時間の測定結果と、PostgreSQL ARKの仕様を考慮して、LKCHECKINTERVAL を26秒に設定した状態でベンチマークを24時間実行しながら監視処理の時間を測定しました。
結論
結論としては、24時間内に稼働した監視処理はすべて26秒以内に完了していました。そのため、十分なハードウェアリソースを要したシステムであれば、監視処理に要する時間に差が出る事はないという結果となりました。
もし監視処理に時間を要するケースが発生した場合は、運用で想定していた以上の負荷、もしくは物理的な障害やソフトウェアバグなどが影響するのではないかと考えられます。
以上が、リソース監視に要する時間の測定と、測定した値を元に行った監視間隔の変更の結果です。
次回は、ノード監視の間隔を短縮した場合の挙動についてレポートします。
>>第2回 “Higher Availability” DBを目指して、LifeKeeperをチューニングしてみました。～ノード監視処理 を読む
本記事について気になる点やご質問等ありましたら、以下よりお気軽にお問い合わせください。
