2011/08/28
因果律を否定するバグ
変更が全く予想外なところに影響を及ぼした例。
金曜の朝に、﹁shiroのパッチを入れたらHudsonでのテストがこけたんで見てくれ﹂
とメールが届いた。パッチそのものはごくtrivialなもので、バグフィクスは
実質1行、それをテストするためのコードが80行くらい。ところがこけてるテストは
私のパッチのテストより前に実行されるテストで、メモリを喰い潰して落ちている。
そこでテストしてる部分は私のfixとも一見無関係。
まあ普通は最初にバグフィックスの1行の変更を疑うよなあ。
で、私のパッチを外すと確かに再現しない。
パッチを入れて、問題のテスト単独で実行しても再現しない。
パッチを入れて、かつフルテスト(3時間くらいかかる)を実行した場合に限り
再現するのだが、再現しない時もある。ただし再現する時にこけるテストはいつも同じだ。
コードを論理的に追う限りではおかしいところは思い当たらないので、
まずは確実に再現させる条件を追っかけた。結果、
﹁make cleanしてスクラッチからビルドした後にフルテストを流すと再現する﹂ことが
わかった。(複雑ではあるが再現条件があるという点で、これはボーアバグであると言える)。
論理的に無関係な箇所に影響を及ぼすという点ではメモリ破壊かスレッド関係を真っ先に
疑うのだが、そっちの線で追っかけてもどうもわからない。試しに、バグフィクスの1行
だけをrevertしてみた。つまり本体のコードはパッチ適用前と同一で、テストコードだけ余分だ。そしたらそれでもこけるではないか。
すなわち、他の条件が同一で、私のテストコードがソースに存在する場合に限り、
そのテストコードが実行される前に 別のテストがこけるということだ。
将来実行されるであろう私のテストコードが悪さをして、
その影響が時間を遡って別のテストをこけさせているのだろうか。
だがそこでテストがこけるために、私のテストコードは結局実行されないのである。
タイムパラドックスだ。私は開けてはいけない扉を開けてしまったのだろうか。
恐ろしい可能性におののきつつ、落ちるテストで何が起きているのかを
注意深く観察してみた。そのテストは16通りの条件でデータの検索と追加を
行っている。n=0から15までループするのだが、それまでに追加した
データに依存して新たにデータが追加され、総データ量はだいたいO(2^n)になっている。
n=0で1個追加されたデータが、正常時にはn=15の時点でだいたい数万個のオーダーになるということ。
ところが異常時にはn=12くらいからデータ量が若干上方向にぶれ始めて、n=15の開始時には90万レコードとなり、n=15のサイクルでデータ追加が終わらないという事態になっている。
追加されるデータの一部は(random 1000)を使って疑似乱数で生成されている。
テストではrandom seedには触っていない。
そこで、正常時と異常時で生成される乱数系列をダンプしてみた。
正常時: 955, 600, 330, 372, 760, 459, 241, 145, 423, 680, ...
異常時: 330, 372, 760, 459, 241, 145, 423, 680, 496, 401, ...
むむ。
そう、異常時、すなわち、私の実行されないはずのテストコードが存在する時には、
乱数系列が二つ先に進んでいる。おそらく、
私のテストコードをコンパイル&ロードする際に処理系内部で
乱数をふたつ消費しているのだろう。
(Lispシステムでは、テストコードがコンパイルされていない場合、まず
テストコードを全てコンパイルしてから同じプロセスが順にテストを実行
してゆくようになっていたので、たとえ私のテストコードが実行されずとも
影響はゼロでは無かったというわけだ。)
試しに、正常時のコードにダミーのrandomの呼び出しを二つ加えて同じ系列を
使うようにしたら、メモリを喰い潰して落ちた。
逆に異常時のコードにダミーのrandomを入れて系列をずらすと、通る。
すなわち、元々このテストは、特定の乱数系列によってデータ量が爆発するという
潜在的な問題を抱えていて、私のテストコードの追加が偶然にもその
系列を発生させてしまっていた、ということだったのだ。
本来的に指数増加するアルゴリズムなので、初期条件のわずかな違いが
指数増加によって極端に増幅されたとも考えられる。
なお、スクラッチビルドでない場合に再現しなかったのは、
テストコードは最初のフルテスト実行時にコンパイルされfaslになっていたため、2回目以降は使われる乱数系列がずれるからであった。
これにて一件落着。因果律は破られず、宇宙の秩序は保たれた。奇妙なことに私の週末だけがどこかに消えてしまったのだが、宇宙の秩序にくらべれば些細なことである。
それにしても、random seedをrandomizeしていたら、これはボーアバグではなく
ハイゼンバグになって、解決ははるかに困難になっていただろう。
教訓: テストは常に再現可能なデータを使うべし。
テストコードの追加によって乱数系列がずれるのもまずいので、
疑似乱数を使うにしてもテストの直前でseedを特定の値にリセットすべきかもしれない。
あと O(2^n) は怖いよね、気をつけようね、ということかな。
(追記2011/08/31 04:29:49 UTC):続きみたいなもの: テストの話
Tags: Programming, Bug
|
さとお (2011/08/30 17:09:32):
宇宙の秩序を保っていただき、ありがとうございます:-) 多用な入力に対するテストは、いったんデータ列をファイル化して読み込ませてます。shiro (2011/08/30 17:48:48):
長くなるから省略したのですが、実はコンパイラのマイナーバージョンを木曜に切り替えていて、そっちを疑ったりしてさらに時間を喰ったという (実行されてないコードの存在が影響を与える→リンカによるコード配置の問題?とか)。 テストコードがプロセスにロードされる際にon-the-flyでコンパイルされてfaslにキャッシュされるんですが、そのコンパイル時に乱数が消費されるというのは盲点でした。uuidでも生成してるのか、テストフレームワークのマクロ展開が何かしてるのか、そこまで追っかけてませんが。okuji (2011/08/30 22:48:30):
昔自分はこういう記事を書いたことがありますが、 http://enbug.tdiary.net/20061218.html#p01 再現性のないテストを書く人が悪いと思いますよ。それじゃテストの意味がありませんから。すごーく厳密な話をすると、乱数発生の関数もシステムのデフォルトを使うと、デフォルトが将来変更された時に再現性が保証できなくなるので、乱数のアルゴリズム自体、テスト中にコーディングすべきとさえ言えると思います。shiro (2011/08/31 00:18:02):
ですよねー> okuji 。今回の件については、処理系の開発とアプリの開発がほぼ同じチームなのでPRNGが予告無く入れ替わることは多分無いんですが、それでもseedをリセットするくらいは必要だと思う。 ただ、今回問題になったテストは﹁返されるべきではないデータが返されないことを確かめる﹂という補集合のロジックを確認するもので、これは﹁返されるべきデータが返されることを確かめる﹂というテストに比べるとテストデータセットを極めて作りにくいものではありました。静的検証ができるといいんでしょうけど、多分このアプリの規模だと実用的な時間での検証は無理っぽいですし。shiro (2011/08/31 01:26:03):
今回、話としては﹁乱数でした﹂でオチに見えるけど、本当に重要なのは﹁ヒープ量が爆発する﹂という症状が見えてる時に、それがコンパイラやGCのバグではないという確証を得ることで、その意味では﹁この乱数系列を使うと、アルゴリズム的に確かに爆発するのだ﹂という具体的な系列が確認できたことが結論なんですね。だからコンパイラやGCのバグでないことがわかったと。長くなるので省いちゃいましたが。horiguchi (2011/09/01 15:55:00):
おもしろい！！ 再現性の薄いバグには慢性的に悩まされています。 ︵私のコードじゃないよ (笑)︶horiguchi (2011/09/01 15:58:24):
今となっては昔の話ですが、昔のCのコードは printf で間違ったスタックの積み違いが、別の printf で治ってしまう場合があって、debug 用の printf を抜くと落ちるというのがありましたねぇ。原因のレベルが違いますが、そんなことを思い出しました～shiro (2011/09/01 19:43:52):
printfはハイゼンバグの代表的な原因でしたね。確かに最近あまり当たらないような気がするけど、x86_64でABIが変わったからとかそういう影響もあるのかな?