blog.fuktommy.com

Pythonでメモリリークを追っ掛けた話

Pythonで書かれた掲示板デーモン「朔」http://shingetsu.info/sakuex/
のメモリリークを追っていて、つい熱くなって徹夜してしまったという…

●基本はやっぱりコレ
http://www.python.jp/doc/release/library/gc.html
ただ gc.get_objects() すると何もしてなくても4000とか返ってくるので追いきれない。

●そこでこんな感じのツールで
http://fuktommy.com/script/gcdebug.py
それぞれの型ごとに、いくつ増えたか減ったかを出力するわけですね。
ほとんどの場合は辞書とか配列とかタプルとかが増えてて、型だけではちょっとわからない。
オブジェクトの中身も表示できることはできるのだけど、ノイズが多くてやっかいでした。

●進め方: 対デーモンとして
まずやったのは、デーモンが相手だったので、
1分ごとに出力するようにして、どのあたりが原因なのか当たりをつける方法でした。
あんまり効率はよくないし、オススメでもないのだけど、仕方ない。
まず目をつけたのは、辞書が増えていること。
その中身を見たら、あるクラスのメンバー名が入ってる。
おそらくPythonのオブジェクト(旧形式の)はメンバーを辞書で管理しているのではと推測して、
コードを読んでみたら、自前のキャッシュ機構にゴミが残っているということがわかりました。
ゴミを積んでしまうのはバグだし、掃除をしないのはそれはそれで問題なので、それぞれ修正。
熱くなって徹夜までしたけど、このあたりで限界。

●進め方: 関数1つずつ
で、さすがに動いているデーモン相手にいろいろやっても苦しいだろうと思って、
このアクセスのときにゴミが残るなというところだけ当たりをつけておいて、
1つずつ関数を実行するとか、関数の一部をコメントアウトして実行するとかを進めていきました。
それでオブジェクトの中身をみてみると、
タプルにunixtimeっぽいのとファイル名っぽいのが入っていたので、
dircache のキャッシュだとわかりました。
そういえばそんなの使ってたなあ、ということで、dircache.reset() で対応。

●進め方: ローカルでデーモンを動かす
次は関数が実際のアクセスからでないと動きにくいものなので、1つずつ実行だときつい。
さらにCheetahのオブジェクトを始めとして、生成されてキャッシュされているのは普通のことなので、
10秒ごとにデバッグ出力が出るように設定して、
2回アクセスした後、オブジェクトの数が変わらなくなるまで待って、
数回アクセスして差分をみるという方法で。
ただ、これはノイズも多くてよくわからんかった。
そこでさらに各所をコメントアウトしてどこの箇所かを探っていったところ、
re.sub() を使ってるところでモジュール内にキャッシュされているということわかり、
re.purge() で対応。

●まとめ
デーモンなどのように長時間動くプログラムはキャッシュ機構に注意。
特に標準モジュールが自動でやってくれるものは気をつけること。
今回の変更点は↓だけ。
http://shingetsu.info/trac/changeset/1651
それでも場所をみつけるのにこんなに時間がかるとはなあ。
printfデバッグは前提となるあれこれの知識がないと辛いね。