tech
エンジニア・光成 滋生の「バグを突き止める技術」
サイボウズ・ラボの西尾 泰和さんが「エンジニアの学び方」について探求していく連載の第18回（これまでの連載一覧）。サイボウズ・ラボの光成 滋生さんにお話を伺うシリーズ（1）です。
本連載は、「WEB+DB PRESS Vol.80」（2014年4月24日発売）に掲載された「エンジニアの学び方──効率的に知識を得て，成果に結び付ける」の続編です。（編集部）
この連載では「エンジニアの学び方」をテーマにインタビューを行い、どういう「学び方」をしているのか探求していきたいと思っています。第2弾は、サイボウズ・ラボのエンジニアとして、楕円曲線などの難しい数学を使った暗号の論文を読んで実装したり、サイボウズが遭遇した問題の原因を掘り下げていって最終的にLinuxのバグを修正したり、と幅広い活動をされている光成滋生さんです。
光成さんが、どういうプロセスで問題の原因を究明するのかや、どういうプロセスで数学を理解するのかは、きっと「エンジニアの学び方」の参考になるはずです。
Linuxカーネルのバグを直す
まず光成さんがLinuxカーネルのバグを見つけてパッチを送った際の話を聞いていきます。詳しいいきさつや問題解決の流れは社内勉強会の発表資料を見るほうが正確とのことなので、インタビュー内容と資料の内容とを合わせて簡単に説明します。
事の発端はLinuxマシンのディスク容量拡張後にページキャッシュが約15分おきに破棄されるという未知の現象が発生したこと。多くのウェブサービスはハードディスク上に置かれているデータベースが、徐々にメモリ上にキャッシュされてアクセスが速くなる設計になっているが、このキャッシュが何故か約15分に1回クリアされてしまう。そうするとユーザーにとってはサービスのレスポンスが遅くなってしまうわけです。
問題を解決するためには、まず問題を再現させないといけない。これが一番大変だったそうです。なぜなら15分という値が固定なのか、何らかのパラメータによって変わるのかすらも分からないから。再現しそうな環境を作り、1時間くらい待ってみて再現するかしないかを観察する。これを2、3日繰り返して、ようやく再現する環境を作ることができたそうです。
次の問題は、犯人がどこにいるのかです。最初は自分たちのアプリケーションが悪いのか、そうでないもかも分からない。MySQLか、ext3ファイルシステムか、ソフトウェアRAID（mdadm）か、論理ボリューム管理（LVM）か、カーネルデバイスドライバか……。でも、少なくともキャッシュクリアが起こるということは、Linuxカーネルはページキャッシュを破棄する関数を呼ぶはずです。そこで破棄しそうな関数をリストアップし、かたっぱしからftraceでその関数を呼ぶものを探したとのことです。
その結果、mdadmのデーモンがその手の関数を呼んでいることが判明しました。これはユーザ空間なのでgdbでアタッチできる。そのデーモンが1000秒に1回何かをしていることが分かった。1000秒は16分40秒だ。試しにmdadmのソースの1000を30に書き換えてみたら、30秒で再現するようになった。これで調査効率が格段に上がりました。
じゃあこのデーモンが犯人か？ しかしこのデーモンは現在の状態をモニタリングするだけのデーモンで、キャッシュをクリアしそうには思えなかった。どのタイミングでキャッシュがクリアされるのかをgdbで追ってみたところ、なんと「/dev/md」をopenするだけでキャッシュクリアが起きることが判明。では犯人はmdのデバイスドライバか？ いえ、それも違いました。
結局、犯人は「kernel/fs」の中にいました。デバイスのサイズが変更された際には「キャッシュは無効、クリアされるべき」というフラグが立ちます。しかし、ある実行パスでそのフラグを0に戻し忘れているというバグがあったのです。その結果、フラグが立ちっぱなしになり、openするたびに「キャッシュ無効だからクリアしてから開こう……」という処理が走っていたわけです。
どれくらい詳しかった？
これをやったときカーネルのソースコードに対してはどれくらい詳しかったんですか？
やったことがあるのが何かっていうと、特殊なプロセッサが搭載されたネットワークカードを操作するデバイスドライバをいじったりとか、それ用のデーモン書いたりとか、そのためにカーネルに近い部分をちょっとだけ触ったりとか。そんなに詳しくはない。
じゃあ、今回の依頼は、ファイルシステムのキャッシュがクリアされてしまうという問題だったわけですけど、ファイルシステムの中に触るのは初めてだったということですか？
そうですね。
使うツールに対しての知識はある程度あった？
いや、すぐ廃れるんです。私が昔やっていたときの知識は全然使えない。バージョン変わったらすぐ変わっちゃうんで、常時キャッチアップしてないとすぐ廃れる。
じゃあ、今回問題解決の依頼を受けてから、最新のツールは何だろうとキャッチアップを始めたということですか。
そうですね、まあ小崎さんの記事とかで「こんなんが使えるようになったのか。どんどん便利になってるな」っていうのは見てましたけど、真面目に自分で触る機会はなかったですね。
再利用できる知識は？
今後また同じようにLinuxカーネルをいじらないといけない状況が起きたとしましょう。ツールの知識はその頃には陳腐化してるわけですが、何が再利用できる知識だと思いますか？
うーん、再利用できる知識……、難しいな。いろいろ「これどうなってんの」とか調べるプロセスって、大概ケースバイケースです。毎回手法も違う。
例えば光成さんが、これと同じような仕事ができるように新入社員を鍛えないといけないとしたら、何を教えます？
それは難しいんじゃないですか。
難しいのは重々承知なんですけれども、どれだけ時間をかけてもよいから教えろとなったら、どういう方向性で教えていくのがよいでしょうか？
何かひっかかることがあったときに、その原因が何かを2、3日で諦めないで探す粘り強さは要るんじゃないかと思いますね。
２、３日やっていて答えが見つからないと心折れそうになると思うんですけど、これをやってる間って心折れそうにならなかったですか？
最初はやっぱ辛いですね。
そこで心折れて「やめたい」にならないで、続けられた理由というのは一体なんなんでしょう？
いや、仕事だし。
仕事でも「これは原因は分かりません」とつきかえすこともできたのでは？
別の場面で「これ再現性が低いし、重要度も低いから、放置していいだろう」って返答した事柄もあります。でも、今回のは重要度が高かったわけです。「重要だから」っていうのは大きいですね。あと「全員怪しいけど、誰が犯人なんだ」という、犯人探しは面白かったですね。
なるほど、個人的にも答えを知りたかったからということなんですね。
犯人探しは好き
そうそう。そういうのは割と探すほうかもしれないですね。最初の会社で出会ったのは、ユーザーランドのプログラムでWindowsがリブートするっていう現象。それも「誰だ犯人は」って探すのは、すごく面白かったですね。
それって誰が犯人だったんですか？
それはWindowsのバグだったんです。当時、2000とかXPとか、NT系カーネルで発生していました。しかもですね、発生するコードと発生しないコードで、スペースとかインデント以外の差分がなかったんです。ブランク以外の差分がないのに発生するんだから、犯人はブランクだろう、って冗談を言っていたら、マジで原因はブランクだったんです。
ええっ、ほんとうにブランクが原因なんですか。
そうそう、どんどんコードを削っていったら最終的には「printf(“\t\b\b”)」1行で、ターミナルにタブを出したあとバックスペースを2個出すと、Windowsがリブートするということが分かりました（※1）。
それを見つける過程では「ソースコードをどこまで削ったら再現するのか」と、どんどん小さな問題に還元していったわけですか？ そうすると予想外にprintfで発生することが分かった、と？
デバッグ対象実行前にgdbが死ぬ
うん、そうですね。この間あった別のやつは、あるexeファイルをgdbでデバッグしようとするとrunする前にgdbが死ぬ、ヘッダ表示して死んでいるんです。コンパイルオプションを変えたら落ちないんで、このexeを読むとだめだと分かる。で、数万行のソースの中から犯人を探すわけです。しかし二分法も難しいのでいろいろやってったら……。
具体的にどういうことをやるんですかね。
ちょっと削ってみて落ちるか落ちないかっていうのをひたすらやるんです。最初は二分法ができないんです。犯人が全然分からないからちょっとずつしか削れない。ソースコードって複雑に絡んでるから、ガバッと半分削るなんてことは難しいわけです。頑張ってちょっとずつ減らしていったら、C++11で使えるラムダ関数をある形で呼ぶと、すごいへんちくりんなシンボルができて、gdbがそのパースに失敗して死亡していることが分かった。
再利用できる知識
さっきの「再利用できる知識」という点では「こんなパターンがありえるんだ」っていう知識は1回経験するごとに増えてはいきますよね。普通プログラムがバグったら「自分のプログラムをまず疑え」というのが一番ですけど、例えばコンパイラがバグってることもあったし、gdbとかデバッガがバグってることもあったし、OSやハードウェアがバグってるときもあった。
そういう経験は積み上がっていくものなのですね。
そう。やり方としては絶対確実なものをまず見つけることが大事ですね。「ここは絶対信用できる」というところをまず明らかにする。
絶対信用できる部分って例えばどういうところですか。
例えば、まあ、空の「int main」だけのコードがまず動くのか確認する。
それはまあ動きますよね。
ところがこれが動かないケースもあった。
えっ、そうなんですか。
そう。ハードウェアやコンパイラの問題だと起こりえる。なので「ここは信用できる」と思っているところを、まず本当に信用できるのか確認する必要がある。
なるほど、大きなプログラム書いていて何か問題が発覚したときって、大前提として「このプログラムに問題があるだろう」と考えてちょっとずつ小さくしていくものだと考えていました。
その大前提はもちろん一番大事です。ただ、その犯人当てのときに、常に「これはないだろう」というやつも候補に入れながらやる。「まさか空の『int main』が動かないわけないよな」と思っても、きちんと確認する。思い込みが間違っていた場合にかかるコストに比べたら、それを確認するコストは高くない。
なるほど、どこに原因があるかを探す際に、ついつい「ここにはないだろう」という先入観を持ってしまいがちです。でも、それでは「意外な原因」に気づくことはできないわけです。確認したこととしていないことを明確に区別すること。きちんと確認すること。確認せずに思い込んだりしないこと。これが意外な原因に気づくためには大事だとのことでした。この方法論は普遍的に有用なものだと思います。
さて、次回からは光成さんの数学に対する学び方について掘り下げていきたいと思います。（つづく）
※1 参考情報：
◎「Windows 2000がハングアップするバグについて」（fj.os.ms-windows.programming）
◎「Bug which crash Windows 2000 and XP」（comp.os.ms-windows.programmer.win32）
本連載は、これまで「毎週火曜日に掲載、火曜日がお休みの場合は翌日」としてきましたが、今回以降は、不定期での掲載となります。
「これを知りたい！」や「これはどう思うか？」などのご質問、ご相談を受け付けています。筆者、または担当編集の風穴まで、お気軽にお寄せください。（編集部）
謝辞：
◎Web+DB Press編集部（技術評論社）のご厚意により、本連載のタイトルを「続・エンジニアの学び方」とさせていただきました。ありがとうございました。
変更履歴：
2014年12月02日：「15分起きに」のtypoがありました。編集部のチェック漏れです。申し訳ありませんでした。またこれに関連して「15分起きにクリアされて」を「約15分に1回クリアされて」に修正しました。
SNSシェア
