IMG_20190122_173812

ロギングはバグを特定するための古典的な手法である．ログとして記録してお
くイベントの品質が，そのままデバッグの効率に直結する．それにもかかわら
ず，従来のロギングでは開発者の経験と勘に基づいて
1) ログを出力するコード上の場所(where to log) と
2) 記録しておくべき情報 (what to log)
をアドホックに決定している．そのため，デバッグ時に必要十分な情報が得ら
れるとは限らず，デバッグを困難なものとする一因となっている．
本発表では，ログの品質を改善する「ロギングコード自動挿入」に関する最近
の研究成果を紹介する．ログの自動挿入はここ数年にわたって活発に研究され
ており，システムソフトウェア研究のトピックのひとつとなっている．既存研
究を概観したのち，発表者等が研究・開発を進めているロギング・ツールK9
について紹介する．K9 はマルチスレッド環境におけるエラー伝播を対象とし
ており，共有データを介したスレッド間でのエラー伝播の追跡を可能とする．
共有データを介したエラー伝播が発生すると，障害を起こしたスレッドのコン
トロールフローを遡っても，障害の原因となったバグにたどり着けるとは限ら
ない．K9 ではそのようなエラー伝播の追跡を支援する．実際に，K9 をLinux
カーネルに適用し，既知のカーネル・バグ 3 種の追跡が可能であることを確
認した．さらに，Linux のファイルシステム保守中に遭遇した未知の障害にも
適用し，バグの特定に有益であることを確認した．

IMG_20190122_174848IMG_20190122_175121

[2019-01-22 18:00]

  • 障害が発生したら(教科書的には): 再現→調査→対策
  • しかし:
    • そもそも再現がむつかしい。
    • 同じ実行環境が手にはいらない。
    • プライバシの観点からデータが手に入らない。
  • かわりのログを送ってもらいログを調査する。
  • しかし:
    • ログが膨大すぎて解析できない。
    • 肝心の手掛かりとなる情報がログにない。
  • 経験と勘に基づいたロギングが原因。
    • システムコールのエラー。
    • 例外的な処理。
    • 気分で入れてるだけ。
    • windows SOSP 2009
    • printf, log4j, syslog event tracing for windows (ETW)
  • 適切なログイングは難しい。
  • 専門用語:
    • logging too little: ログが少なすぎる
    • logging too much (redundant&trivial): 冗長だったり、あたりまえの内容だったり。オーバヘッド・ストレージ使用量が問題になる。
  • ロギングが研究テーマになったのは数年前から
    • 手動から自動へ
    • where to log?: どこに入れるか?
    • what to log?: どんな値を記録すればよいか?
    • what happend?: ログから障害発生の様子を自動抽出して障害の実行パスを類推する。
  • Errlog [Yuan+ OSDI'12]
    • どこでログを入れるか、入れわすれたところに自動でログを入れる。
    • 例外処理:
      • 実際にはログを取り忘れるケースが多い。250件の障害事例を調査。
    • error()を呼んでたらエラー処理というような判定をする。error()を呼ぶ条件式を集めて、ログを入れ忘れているところに追加する。プログラマは無能ではない前提。
  • SherLog [ASPLOS'10]
    • what happend? ログから実行パスを類推する。Sharはシャーロックホームズから。
  • LogEnhancer[ASPLOS'11]
    • 実行パスが類推できるように変数の値をロギングする。
  • K9ではLinuxをターゲットにした。
    • Linux as Infrastructure
    • Linuxは実用的・巨大・複雑なので、Linuxでつかえれば他のソフトでも使える。
  • 用語:
    • fault: =bug 誤りのこと バグがあっても踏まないと発症しない
    • error: バグをふんでおかしくなった状態
    • error propagation: おかしな状態は伝搬する
    • failure: 障害発生(クラッシュ・ハングアップ)
  • Palix:
    • Null: nullチェックもれ
    • Inull(Inconsistent null check): ポインタ参照(deref)したあとにnullチェック(意味がない)
    • Block: ブロックしてはいけないコンテキストでブロックする関数をよぶ
  • linuxにはだいたいいつでも700個くらいバグが残っている。
    • バグをつぶしても同じくらいバグが入ってくる。
    • 1行あたりのバグは減っている。
  • 簡単なバグだけではない
    • 関数にまたいだ問題
    • 割り込み(非同期)
  • Inter-thread error propagation
    • 例
      • Btrfsでworker threadが例外時にdirtyフラグを落すのを忘れて
      • sync threadがBUG()を踏む
    • direct propagation: スレッド1が共有データを更新して、スレッド2が読む。
    • indirect propagation: スレッド1が共有データを更新して、スレッド2が読んで別の共有データを更新して、スレッド3が読む。
  • K9ではエラー伝搬を解析できるようにログを入れるが、linux規模のソフトでは正攻法は無理。
    • オーバヘッドを押える
    • 静的解析はしない
    • ポインタ解析はしない (やっても正確には分からないことが証明されている)
    • coding traditionを仮定して共有データをさがす。
      • 共有データはヒープに置かれる。
      • 共有データは構造体になっている。
        • そのなかのポインタ配列やリスト構造をみる。
        • リンクリストなどのデータ構造用のライブラリにも対応(対応しないとデータ構造を操作するだけの関数がログに出て呼び出し元が分からない)
    • indirect propagationはデータフローは追い掛けずに型レベルで推測する。
  • ファイルシステムにはバグが多いという論文がある and Btrfsは新しいファイルシステムなのでバグが多く残っているのでは? and 研究室の学生がBtrfsのメンテナ
  • Btrfsで未知のバグをK9で追い掛けた原因をつきとめられた (実証)
  • K9のオーバヘッドは、スループットで1.83%(平均)、CPU利用率で0.32%(平均)。
  • たまにスループットのオーバヘッドが少ないという論文があってもCPU使用率が高いケースがある。その場合はCPUに余裕がないとスループットが悪くなる。

[2019-01-22 19:16]

QA

  • Q: ログを入れたのはファイルシステムだけ?
  • A: yes。だがファイルシステムのコードから呼ばれている関数にもログが入っている。スケジューラとかメモリ管理とか。これら(sched,mem)にはバグが少ないという研究報告がある。クリティカルセクション内でログを吐かないようにすることで、よりオーバヘッドを減らせる余地がある。
  • Q: ロックには注目しないのか?
  • A: ロックの範囲を調べるのが簡単ではないのと、ロックが保護している変数を見つけるのも難しい。ロックもれがあった場合に困る。やってみたが良くなかった。
  • Q: K9の論文は公開されているか?
  • A: 投稿中。
  • Q: オープンソースにするのか? それとも企業に買収されるのを期待しているのか?
  • A: 日立との共同研究なので日立が買う可能性はあるが、オープンソースにする予定になっている。
  • Q: C以外の言語でもつかえるか?
  • A: LLVMの中間言語で解析しているので、言語に特化したものでなければいけるはず。

[2019-01-22 19:24]

IMG_20190122_194128

関連資料?
タグ ：
#iijlab