OSS分散ストレージの調査例 - 未知のエラーメッセージが出たときの対処 -/cnsm2-cybozu-oss-storage-survey-example

Cloud Native Storage Meetup #2
https://cndata.connpass.com/event/231308/

Transcript

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

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

   View Slide

7. 調査対象を確認
   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
   …
   

   View Slide

8. キーワードで検索
   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
   

   View Slide

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

   View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

18. ”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
    

    View Slide

19. ”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
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

30. 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登録
    

    View Slide

31. オペレーションが処理される流れが
    デバッグログから分かっている
    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(...
    ログの一例
    ※ ログレベルを上げて調査をした結果
    

    View Slide

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

    View Slide

33. その他にわかったこと
    ▌詳細情報は個々の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
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

37. 37
    おわり
    

    View Slide