OSSへの貢献ノウハウ: ユーザサポート編 - Cybozu Inside Out

はじめに

こんにちは、Necoプロジェクトのsatです。本記事は先日公開した以下の記事の続編です。

blog.cybozu.io

上記の記事ではOSSプロジェクト全体を盛り上げる手段を次のように紹介しました。

プロジェクト全体を盛り上げるには例えば次のような方法があります。

自社に直接関係が無いissue/PR発行、レビュー

ユーザサポート

イベントでの発表

本記事では、このうちのOSSにおけるユーザサポートとはどのようなものかについて、Rookにおいて発生した実際の問題を例として書きます。この問題の根本原因はカーネルだったためにカーネルの用語がいくつか出てきますが、あまり気にせずにフィーリングで読んでいただければとおもいます。本記事で一番伝えたいのはカーネルの技術的な知識ではなくOSSにおけるユーザサポートのノウハウです。

Rook、およびRookが管理するCephについては過去記事をごらんください。

blog.cybozu.io

きっかけ

筆者がKubeCon North America 2019に参加していたときに、Rookのgithubにおいて気になるissueを見つけました。

github.com

まずはこのissueがどういう問題かについて書きます。前提知識として、Rookが管理するCephクラスタは、多くのノード上にCeph用のサービスを動かしています。このうちのOSDというサービスが動いているノードが、特定の条件を満たすとCPU使用率が100%になり、かつ、その後にノード全体が無反応になるというのがこの問題です。

業務システムでこのような問題が発生した場合は大きな問題になりますし、かつ、同じ問題に遭遇した人は数人いたため、極めてレアなケースというわけでもないことがわかりました。

さらにissueを読み進めると、問題発生時には次のコメント内の画像のようなLinuxカーネル(以下カーネルと記載)のログが出力されることがわかりました。

github.com

ここで重要なのは次のメッセージです。

... task XX blocked for more than 120 seconds.

筆者はかつてカーネルの開発をしていたこともあり、このメッセージはユーザプロセスではなくカーネルの問題が起きた場合に出ることを知っていました。もう少し詳しく言うと、カーネル内の排他制御の問題で、特定のプロセスが長時間、あるいは永久に動けない状況になっていたことを示しています。

しかしながら上記のコメントの後の流れを見たところ、Cephを含めたユーザプロセスの問題について色々と議論しているものの、カーネルの話はまったく出てきていませんでした。このことから、このissueの関係者にはカーネルに詳しい人がいないのだろうということがわかりました。

ここまでわかった段階で、以下のような理由によって筆者はこのissueの解決に協力することを決めました。

Rookを使っているからにはプロジェクトに貢献して盛り上げたい*1
自分の知見を活かせる、かつ、自分が協力しないと恐らく先に進まない
現在Necoではこの問題に遭遇していないが、いずれ遭遇するかもしれない。その場合の影響が大きい

どのような貢献をするか

問題の解決に協力するとして、具体的にどのようなことをするかも考えなければいけません。このようなときに陥りがちな罠は、とにかく何でもかんでも貢献しようと勇み足になって全てを自分でやろうとしてしまうあまり、本業をおろそかにしてしまうことです。

筆者はこの罠に陥らないように、自分のやることを以下のように定めました。

問題に遭遇した人から必要な情報を収集する
上記の情報を使ってカーネル開発者とやりとりする
得られた情報をissueにフィードバックする
問題を回避できればそこまでで終了とする
カーネル修正が必要になった場合は積極的には手を出さない、あるいは自分の環境で遭遇するまでは低優先度で取り組む

企業の製品サポートでいえば製品内の不具合の直接調査する役割ではなく、関係者を巻き込んで問題解決を推進する取りまとめ役といえるでしょう。

調査の流れ

情報収集

問題がカーネルにあるとわかったものの、カーネルの中のどこに問題がありそうかを明らかにするために、もうすこし深掘りをすることにしました。具合的には、次のコメントにおいて、問題はカーネルにあることを述べた上で、問題に遭遇した人々に情報収集を依頼しました。

github.com

各情報の採取意図については本記事の範囲を超えますので、必要であれば上記コメントを読んでください。

幸いにも上記の依頼に対していくつかの反応がありました。そのうち最も有用だったのは以下のコメントです。

github.com

このコメントによって、問題発生時のカーネルのバックトレースの情報が得られました。

[51717.039319] INFO: task kworker/2:1:5938 blocked for more than 120 seconds.
[51717.039361]       Not tainted 4.15.0-72-generic #81-Ubuntu
[51717.039388] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[51717.039426] kworker/2:1     D    0  5938      2 0x80000000
[51717.039471] Workqueue: xfs-sync/rbd0 xfs_log_worker [xfs]
[51717.039472] Call Trace:
[51717.039478]  __schedule+0x24e/0x880
[51717.039504]  ? xlog_sync+0x2d5/0x3c0 [xfs]
[51717.039506]  schedule+0x2c/0x80
[51717.039530]  _xfs_log_force_lsn+0x20e/0x350 [xfs]
[51717.039533]  ? wake_up_q+0x80/0x80
[51717.039556]  __xfs_trans_commit+0x20b/0x280 [xfs]
[51717.039577]  xfs_trans_commit+0x10/0x20 [xfs]
[51717.039600]  xfs_sync_sb+0x6d/0x80 [xfs]
[51717.039623]  xfs_log_worker+0xe7/0x100 [xfs]
[51717.039626]  process_one_work+0x1de/0x420
[51717.039627]  worker_thread+0x32/0x410
[51717.039628]  kthread+0x121/0x140
[51717.039630]  ? process_one_work+0x420/0x420
[51717.039631]  ? kthread_create_worker_on_cpu+0x70/0x70
[51717.039633]  ret_from_fork+0x35/0x40

どうやらXFSファイルシステムが関係していそうだということがわかりました。さらに、この問題はこれまでにXFSでしか発生実績がなかったことより、筆者はXFSが有力な容疑者の一人だとみなしました。

カーネル開発者への相談

ここからやるべきことは既存障害調査、およびXFS開発者への相談です。前者は自分だけでもできるので、まずはこちらからやりました。具体的には次のようなことをしました。

XFS開発メーリングリストの過去ログを上記トレース内の特徴的な単語を使って検索した
カーネルのコミットログを上記と同様に検索した

しかし、この問題に関係ありそうな議論、あるいは修正は見つかりませんでした。

github.com

続いてXFS開発メーリングリストでXFSの開発者達に相談してみることにしました。

ここで問題になるのが、報告するときに提供すれば好ましい情報がいくつか足りていないことでした。たとえば再現手順や最新カーネルにおける再現確認などです。ただし、次の事情によって、これらの情報を得るのは短期的には難しいと判断しました。

OSSのissueにおける情報収集依頼は商用製品のサポートに比べて要求した情報が得られる確率が低い。報告した後に無反応になる人も多い
誰も再現方法を見つけられていない。ゆえに筆者の環境において最新カーネルでの再現も難しい

この手の情報が足りないと報告そのものが無視されがちなのですが、やむをえず、できる限りの情報を添えて、XFS開発メーリングリストに相談しました。幸いにもこの後すぐにXFSの元メンテナであるDave ChinnerさんがCephによってブロックデバイスを提供するkrbdドライバが怪しいということを教えてくれました。

この後はすぐにDaveさんのコメントを反映してCephのカーネル部分の開発者メーリングリストに相談しました。幸いにも、こちらの相談もCephカーネル機能のメンテナの一人であるIlya Dryomovさんからすぐに回答がありました。彼にはこの問題がkrbdとXFSの相互作用によって発生すること、既知のものであること、修正見込みであること、および回避策があることを教えていただきました。