OSS分散ストレージの調査例 - 未知のエラーメッセージが出たときの対処 - Feb. 18th, 2022 サイボウズ ストレージチーム Yuma Ogami 1

自己紹介 ▌大神 祐真 ▌サイボウズ ストレージチームにて 分散ストレージCephへの データ移行と運用に従事 2

はじめに ▌サイボウズの新インフラ基盤はKubernetesクラスタ ▌ストレージ基盤にCephを使用する ⚫旧基盤で顧客の添付ファイル等のペタバイトスケールのデータが有り、 その移行を実施中 ▌今日は、 運用中する中で調査した結果とノウハウを共有 3

調査のきっかけ ▌運用中に以下のようなwarningメッセージが出た ⚫確認している限り自然解消する ▌公式ドキュメントやupstreamのissue・PR・MLを確認したが、 このメッセージ自体の解釈の仕方の説明は無かった ▌その後、ログレベルを増やし、ログの調査も行った ▌以上を行ってもわからず、ソースコードを調査することに 4 4 slow ops, oldest one blocked for 4628 sec, osd.7 has slow ops ※ ceph -s というコマンドで 表示されたメッセージ

今回のお話 Cephのコード調査を例に、 このような大規模なソースコードを どのように読み進めるかを紹介します。 コードを引用しますが、 見て欲しい箇所は吹き出し等で示します。 どの様にに読むか雰囲気を理解してもらえれば 大丈夫です。 5 主にC++で 120万行程

Cephのアーキテクチャ(簡略版) 6 アプリ ストレージプール Ceph node disk disk node disk disk node disk disk … ブロックデバイス ブロックデバイス ブロックデバイスなど アプリ アプリ OSD OSD OSD OSD OSD OSD MON クラスタの 整合性を取る オブジェクトを 格納する この発表で対象とするCephバージョンは16.2.6

調査対象を確認 7 今回の調査対象 $ ceph -s cluster: id: be8f440c-8394-44e7-aec2-8366e616e29e health: HEALTH_WARN Degraded data redundancy: 388583/207314820 objects degraded … 57 pgs not deep-scrubbed in time 67 pgs not scrubbed in time 4 slow ops, oldest one blocked for 4628 sec, osd.7 has slow ops …

キーワードで検索 8 4 slow ops, oldest one blocked for 4628 sec, osd.7 has slow ops このようなメッセージなので、 ”slow ops, oldest one blocked for” 辺りがキーワードになる 試しに↑でソースコード内を検索してみると↓がヒットした これらがどのように作られているかが分かれば メッセージを理解する手助けになりそう ceph/src/mgr/DaemonHealthMetricCollector.cc

着目箇所を決める 9 何を知りたいか目的を持って読み進める → 今回は主にvalue.n2に着目してみる ceph/src/mgr/DaemonHealthMetricCollector.cc

何処に居るかを確認 10 ・・・ ・・・ この処理は、SlowOpsクラスの_summarize()の中 ceph/src/mgr/DaemonHealthMetricCollector.cc

着目している変数は誰の持ち物か 11 ・・・ ・・・ この処理は、SlowOpsクラスの_summarize()の中 valueはDaemonHealthMetricCollectorクラスのメンバ ・・・ n1・n2という 32ビット整数型を メンバに持つ ceph/src/mgr/DaemonHealthMetricCollector.cc ceph/src/mgr/DaemonHealthMetricCollector.h

読んでいる対象の名前を意識する 12 ・・・ 読み進める内に迷子にならないように、 今読んでいる部分の役割をクラスの名前等からできる限り推測する “DaemonHealthMetricCollector” という名前なので、 “DaemonHealthMetric”を 集めているのだろう ceph/src/mgr/DaemonHealthMetricCollector.h

value.n2に何を格納しているか 13 ・・・ 少し上の方にこのような実装がある value.n2へは、 DaemonHealthMetricクラスのget_n2()の値を格納している ceph/src/mgr/DaemonHealthMetricCollector.cc

get_n2()の実装を見る 14 ・・・ ・・・ DaemonHealthMetricクラスも daemon_metric_t valueをメンバに持っていて、 get_n2()はそのn2を返すだけ 誰がvalue.n2を設定しているのか？ ceph/src/mgr/DaemonHealthMetric.h

DaemonHealthMetricのvalueを設定 しているのは誰か 15 ・・・ ・・・ daemon_metric_t valueはprivate setterがある？ ceph/src/mgr/DaemonHealthMetric.h

16 ・・・ daemon_metric_t valueはprivate setterがある？ 無い コンストラクタで値を設定する ceph/src/mgr/DaemonHealthMetric.h DaemonHealthMetricのvalueを設定 しているのは誰か

17 ・・・ daemon_metric_t valueはprivate setterがある？ 無い コンストラクタで値を設定する 設定を行う箇所には このクラス名”DaemonHealthMetric”が 含まれる、と推測できる ceph/src/mgr/DaemonHealthMetric.h DaemonHealthMetricのvalueを設定 しているのは誰か

”DaemonHealthMetric”のキーワード で検索 18 $ grep -nrE 'DaemonHealthMetric[^a-zA-Z]' | grep -vw 'DaemonHealthMetric.h’ ・・・ src/osd/OSD.cc:7742:vector OSD::get_health_metrics() src/osd/OSD.cc:7744: vector metrics; src/osd/OSD.h:1951: std::vector get_health_metrics(); src/mon/Monitor.h:217: std::vector get_health_metrics(); src/mon/Monitor.cc:5871:vector Monitor::get_health_metrics() src/mon/Monitor.cc:5873: vector metrics; src/messages/MMgrReport.h:109: std::vector daemon_health_metrics; Binary file .git/index matches

”DaemonHealthMetric”のキーワード で検索 19 $ grep -nrE 'DaemonHealthMetric[^a-zA-Z]' | grep -vw 'DaemonHealthMetric.h’ ・・・ src/osd/OSD.cc:7742:vector OSD::get_health_metrics() src/osd/OSD.cc:7744: vector metrics; src/osd/OSD.h:1951: std::vector get_health_metrics(); src/mon/Monitor.h:217: std::vector get_health_metrics(); src/mon/Monitor.cc:5871:vector Monitor::get_health_metrics() src/mon/Monitor.cc:5873: vector metrics; src/messages/MMgrReport.h:109: std::vector daemon_health_metrics; Binary file .git/index matches OSDとMonitorにだけ それらしい関数がある 4 slow ops, oldest one blocked for 4628 sec, osd.7 has slow ops

あたりを付けた関数を見てみる 20 今回の肝になる関数 ceph/src/osd/OSD.cc

21 ceph/src/osd/OSD.cc slow opsの条件が分かる部分

22 「現在時刻 – osd_op_complaint_time設定値(*1)」 をtoo_old(時間が掛かり過ぎ)としている (*1): デフォルト30秒 → slow ops が出始めるのは30秒を超えた所から であると分かる ceph/src/osd/OSD.cc slow opsの条件が分かる部分

23 ・・・ ・・・ ・・・ 「count_slow_ops」 という関数を作成 ceph/src/osd/OSD.cc count_slow_ops

24 ・・・ ・・・ ・・・ too_oldより 古いものがあったら ceph/src/osd/OSD.cc count_slow_ops

25 ・・・ ・・・ ・・・ カウント用の変数を インクリメント ceph/src/osd/OSD.cc count_slow_ops

26 ・・・ ・・・ ・・・ 「最も古いオペレーション」 を更新する ceph/src/osd/OSD.cc count_slow_ops

27 ・・・ ・・・ ・・・ 実施中(in flight)のオペレーションを count_slow_opsを使ってチェック ceph/src/osd/OSD.cc 実施中のオペレーションチェック

28 metrics登録 ・・・ ・・・ ・・・ 該当するものがあったら metrics登録 ceph/src/osd/OSD.cc

29 ・・・ ・・・ ・・・ value.n1 value.n2 ceph/src/osd/OSD.cc metrics登録

30 ・・・ ・・・ ・・・ value.n1 value.n2 4 slow ops, oldest one blocked for 4628 sec, osd.7 has slow ops value.n1 value.n2 ceph/src/osd/OSD.cc metrics登録

オペレーションが処理される流れが デバッグログから分かっている 31 enqueue_op → dequeue_op → do_op → event: done と処理されていくよう debug 2022-02-01T07:53:38.191+0000 7fdb424de700 15 osd.8 3070 enqueue_op 0x55a51f7ed4a0 ... ... debug 2022-02-01T07:54:13.927+0000 7fdb231e9700 10 osd.8 3070 dequeue_op 0x55a51f7ed4a0 ... ... debug 2022-02-01T07:54:13.927+0000 7fdb231e9700 20 osd.8 ... do_op: op osd_op(... debug 2022-02-01T07:54:13.927+0000 7fdb231e9700 10 osd.8 ... do_op osd_op(... ... debug 2022-02-01T07:54:13.928+0000 7fdb231e9700 6 ... event: done, op: osd_op(... ログの一例 ※ ログレベルを上げて調査をした結果

ソース調査の結果分かったこと メッセージの意味と契機 ▌デーモンの個々の処理に所定の時間以上か かっている ⚫ メッセージの “oldest one blocked for XXX sec” の部分 ▌パラメタでメッセージが出るまでの時間を調 整可能 ⚫ https://docs.ceph.com/en/latest/rados/configuration/osd-config-ref/#confval- osd_op_complaint_time 32

その他にわかったこと ▌詳細情報は個々のdaemonのログに書いて ある ▌OSDの一例 ▌daemon再起動で解消することがある 33 debug 2022-02-01T04:12:02.513+0000 7fdb3da2d700 20 slow request osd_op(client.7787495.0:1023676 5.4 5:3f892d60:::.dir.1cb5bb3a-...) initiated ... currently delayed

感想 ▌コードを読むポイント ⚫的を絞って読み進める ⚫OSSの挙動を部分部分で理解していく事ができる ⚫100万行を超えるコード(現状のCephの場合)を全部読む必要 は無い ⚫今見ている対象を認識しながら読み進める ⚫「とりあえず呼び出し元を追っていく」ように何も考えずに 読み進めると迷子になる 34

感想 ▌(Cephは特に)コードを読むのが大変。まずはドキュメントを参 照すべき ⚫案外細かい所はドキュメントが無かったりもするが、コードを読んだ 挙句に「実はドキュメントがあった」というのは避けたい ⚫クラスとして様々なものが抽象化されており、コードを読み進める中 で自分が今何を見ているのかを見失わないようにするのが大変 ▌ただ、ドキュメントにあるパラメータが裏でどのように働いてい るのかなど、仕組みを理解できる ⚫読んでも無駄にはならない 35

今後考えられる展開 今のステータスとしては継続調査中 ▌オペレーションについて追加調査 ▌分からない点をupstreamへ質問 ▌upstreamへの還元 ⚫slow ops周りのドキュメント拡充 36

37 おわり