Ceph/RADOS 障害発生時のノウハウ 4. Ceph のログ使い勝手の改善

上記の表は、ある検証項目を実施したときに 6ノードの Ceph クラスタで出力されたログのログレベル分布です。 セルの値はログ出力件数です。頻度の高いものは赤、比較的低いものは緑色になっています。各 Ceph ノードのメモリ上のログ領域は 1万行に設定されているため、ログは全部で 6万件あります。 しかし、このログでカバーしている時間的範囲は 6 ノード合計で 210秒程度に過ぎません。 つまり、問題が発生からログを取得するまでの時間的猶予が非常に限られている状況です。現実的な時間的猶予でログを取得できるようにするためにはメモリ上のログ領域を拡大するだけでなくセルの赤い箇所のログを削減する必要があると思われます。

上記の表は、先程の表でセルが赤かった箇所のログを出ないようにログレベルを変更した後の様子です。先程と同じく 6ノード全部で 6万行のログ領域に対して 6ノード合計で 330秒間のログを格納してログは全部で 3万件に抑えられています。つまり、検証項目を実施したときに 6ノードの Ceph クラスタで出力されたログが全て残っている状況です。 このようにログ出力頻度の高い箇所を避けるようにログレベルを設定することでメモリ上にログが残る時間を延長することが可能です。本稿での検証は、90分間のメモリログが取得できるログレベル設定を目標とします。

<ログの解析の難しさ>

上記は Ceph OSD サーバーで出力されたログのサンプルです。各ログ行は数カラムのタイムスタンプ部から始まりますが、その部分は省略しています。最初のカラムの 7fe4d6eb6700 のような値はスレッド毎の値です。2番目のカラムはログレベルです。3番目のカラム以降がログメッセージです。
障害発生時に上記ログから切り分けを行おうとした場合を想定すると、まず、各ログを出力しているソースコード上の場所を、ログメッセージに含まれるキーワード等でソースコードを検索して特定し、次に、前後のログ行を出力しているソースコード上の場所から処理の流れを類推することになります。

「1. OpenStack/Ceph の現状と課題」の「1.2. Ceph を選択する課題」で述べたように、Ceph のコード規模は Linuxカーネルに含まれるすべてのファイルシステムのコード (linux-4.7/fs) の総量におよそ匹敵する大きさがあります。現実的な時間的コストで、ログメッセージに含まれるキーワードでソースコードを検索してログ出力箇所を特定し、さらに複数のログ出力箇所からそれらを通る処理ルートを類推するためには、予め何らかの準備が必要と思われます。

■ ステップ 3： 障害パターン毎の特徴なログの抽出

OpenStack/Ceph 異常系テストの実施の際にステップ 1 の仕組みで障害パターン毎のログアーカイブを取得します。各ログアーカイブに対してステップ 2 のスクリプトを実行することで、障害パターン毎のログのサブシステムおよびログレベルの分布を抽出します。各障害パターンのログレベル分布を、障害がない状態で同じオペレーションを実行したときにログレベル分布と比較することで、その障害パターンによって出力された可能性が高いログを抽出します。

上記の図は、OpenStack/Ceph 異常系テストのテスト項目 (故障パターン) のうち、テスト項目 #1 の通常の状態と、テスト項目 #34 の 3台中 2台の Ceph MON でダウンが発生した場合でのログレベル分布を比較した例です。丸で囲ったサブシステムとログレベルのログがテスト項目 #34 でのみ出力されていたことを表します。

「3. OpenStack/Ceph 異常系テスト (1)」の「3.4. テスト結果」で述べたとおり、テスト項目 #34 では、コマンド (ceph –watch) の出力から Ceph MON がダウンしていることが判別できませんでした。

上記の図はテスト項目を実施したときの Ceph クラスタの構成です。
具体的には、2台の Ceph MON がダウンしたにも関わらず、コマンド (ceph –watch) の出力上では、1台の Ceph MON が停止し HELTH_WARN に状態遷移し、当該 Ceph MON 再起動後に HEALTH_OK に状態したように見え、もう 1台の Ceph MON が停止したことが分かりませんでした。
Ceph MON クラスタは奇数台数で構成され、その動作には多数派を形成できる台数 (＝定足数) が健全である必要があります。テスト項目 #34 では、3台で構成された Ceph MON クラスタのうち 2台がダウンしてしまうため、健全な Ceph MON の台数＝1 が定足数＝2 に満たない状況となります。また、コマンド (ceph –watch) の動作は Ceph MON クラスタが動作していることに依存します。よって、Ceph MON クラスタの定足数がない状態で発生した、もう 1台の Ceph MON が停止、再起動の事象を、コマンド (ceph –watch) が正常に動作せず検知できなかったものと思われます。

上記の図は、テスト項目 #1 の通常の状態ログレベル分布を比較して抽出された、テスト項目 #34 でのみ出力されていたログの時系列での件数分布です。

 上記の図は、テスト項目 #1 の通常の状態とのログレベル分布を比較して抽出された、テスト項目 #34 でのみ出力されていたログ行です。赤線で囲った部分は、2台の Ceph MON への通信が、その他全てのノード上で失敗している状況を表示しています。

上記の図は、テスト項目 #34 でダウンさせた Ceph MON 2台を灰色で示し、テスト項目 #1 の通常の状態のログレベル分布を比較してテスト項目 #34 でのみ出力されていたログにある通信失敗の箇所を赤文字で示しています。つまり、テスト項目 #34 の実施によって検出された、コマンド (ceph –watch) で現象 (3台中 2台の Ceph MON ダウン) を検知できない問題に対する代替手段として、故障パターンに特徴的なログの内容 (通信が失敗している箇所) から現象を推測する方法が確認できたと思います。

■ ステップ 4： ログレベル設定

全てのサブシステムおよびログレベルの組み合わせのうち、ステップ 3 で抽出した障害パターンに特徴的なログを出力したサブシステムおよびログレベルの組み合わせを抽出します。
抽出されたサブシステムおよびログレベルの総和でログレベルを設定します。このログレベル設定でログ頻度が高くなり過ぎてメモリログが短時間でサイクルしてしまう場合は、ログ出力頻度の高い箇所を避けるようにログレベルを調整することでメモリ上にログが残る時間を延長します。

図は、「5. OpenStack/Ceph 異常系テスト (2) 」で述べるテストを通して得られたログから抽出したログレベル設定です。緑色のマーク部分はデフォルトのメモリログレベルから変更していることを表します。

■ ステップ 5： 処理ルートデータベースの作成

ソースコード上の関数呼び出し箇所を洗い出し、それぞれについて呼び出し元クラス：：メソッド、呼び出し先クラス：：メソッドを抽出します。次に、処理ルートを抽出し、処理ルートデータベースとします。
処理ルートの抽出は、呼び出されることのないクラス：：メソッドから何も呼び出さないクラス：：メソッドに至るまでの一連の関数呼び出し関係を機械的に検索することで行います。関数呼び出しを行うかどうかは多くの場合に条件がありますが、この機械的な検索において条件は考慮しません。つまり、関数呼び出しの条件は常に真です。よって処理ルートデータベースには実際には通ることのない処理ルートが多数含まれます。

■ ステップ 6： ログ出力箇所を通る処理ルートを検索する仕組みの作成

任意のログに対してステップ 2 のスクリプトを実行することにより、ログに含まれているログ出力箇所のリストが得られます。これらのログ出力箇所のうちの 1個から N個を含むような処理ルートをステップ 5の処理ルートデータベースから検索します。

上記の図は、処理ルートデータベースを検索した結果のうち、検索で見つかった処理ルートの数の表示です。

 上記の図は、処理ルートデータベースを検索した結果のうち、12 のログ出力箇所を通る 5つの処理ルートに関する内容です。
ログから障害の切り分けを行うことを想定した場合の、現状の Ceph ログの問題点とその対処案を検討については以上です。この後に述べる「5. OpenStack/Ceph 異常系テスト (2) 」においては、対処方法の情報として、ログだけからハード障害を切り分けできるかどうかという観点を加えています。