クローズ忘れをvalgrindで検出

製品の連続稼働検証をしばらく行っているのですが、どうもアクティブなinode数がじわじわ増え続けているのが気になり、今日は会社でじっくりと調査しました。平日はなかなかじっくりと取り組む時間が取りにくいので、休みの日の方がこういうことは捗るものですし。。

まず、前にも説明したvalgrindを製品環境に無理矢理インストールしました。yumで簡単にインストールと思ったのですが、アプライアンスはいろいろと削っているので、ソースからビルドしてインストールしました。

valgrindはメモリーリークやメモリーの不正アクセスの発見に便利なのですが、オープンしたままのディスクリプタのチェック機能もあります。「--track-fds=yes」というオプションをつけるとメモリーリークと同様に、プログラム終了時にクローズしていないディスクリプタを報告してくれます。

ここまではそれほど時間もかからずに、確かに希にディスクリプタ開放がされていないことが確認できました。クライアントソケットだということまでは分かったのですが、ここからが問題です。1セッション1スレッドという感じの構成なら、ソケットの生成からクローズまで流れがすぐに追えるのですが、コネクトも送受信も、さらに他の処理も全部イベント駆動で構成したので、追うのがとても大変なのです。valgrindは、ここでオープンしたものが開放されていない、というレポートを出してくれますが、どこで開放されるべきだったかは、当たり前ですが実行結果からは分かりません。

仕方ないので、コネクトとクローズのログを出すようにしてみます。しかし、かなり負荷をかけないと再現しないので、ログを解析するだけでも大変です。最初はエディタで編集しながら見ていたのですが、とても無理なので、ログ解析プログラムを作りました。その結果、確かにコネクトしているのにクローズされないことが希に起きていました。

そこで、コネクトとクローズの間に行っている処理を絞り込んでいけるようにログを追加し、｛再現テスト・ログ解析｝をひたすら繰り返しました。

結局6時間くらいかかって、ようやく問題の場所が分かりました。このプログラムは、普通のソケットプログラムと比べてコネクト関連処理が実に複雑で、一度多スレッド型からイベント型に書き換えた際に、やらなくても良い判定を行っていたせいで、エラー処理のつじつまが合わなくなっている部分があったという感じです。

原因が分かれば修正は数秒です。

せっかくなので、ついでにvalgrindの警告を潰しておこうと、動作検証をしながらいろいろなパターンの確認をし、調整できるところは改良しておきました。

結局朝の9時半から夜の9時半までかかってしまいました。。