djangoをプロファイリングする

Date Modified Tags python / django

作ってるWebサービスが条件によってえらい重くなるので、ボトルネックを探すためにプロファイラを動かしてみようと考えてやってみたらそこそこハマった。

先に結論：

Middleware使ってブラウザに表示させるのが楽だった

条件

  • cui環境なので、プロファイル結果は画像作るかブラウザ表示するかのどちらか
  • コードに埋めこまない形

まず参考にしたのは公式ページのProfilingDjango – Django。ざっくりとした結果が知りたかったのでrunprofileserverを試してみることにした。

開発サーバでやってみる（runprofileserver）

django-extensionの一機能で

$ pip install django-extensions

でインストールして、

# settings.py
INSTALLED_APP = (...
   'django_extensions',
)

で設定して

$ python manage.py runprofileserver

とすると、よしなに/tmpフォルダ内にプロファイル結果を吐き出してくれる開発用サーバだそうで、これは便利そうと思い、やってみた。

結果を画像にしようとしてハマる

プロファイル結果からgraphviz通して画像にしたらブラウザから確認出来るし楽なんじゃね？とか良く考えると不毛なことを考えたのが間違いのもと。普通にKCacheGrind使ってろって話なんだけど、やってみた

ツールとして使ったもの

  • gprof2dot、プロファイル結果をdotファイルに変換する
  • graphviz、dotファイルを画像に変換する

話にならなかったもの（良く考えるとこのケースで使えないの当たり前なのに使おうとして失敗したもの）

  • xdebugtoolkit、単純にxdebugの結果でないとそりゃ使えないよねと納得した

あまり良く分かってなかったので、KCacheGrind互換で出力しておけば、色んなソフト使ってよしなに出来るんじゃね？と思ってみた。んでKCacheGrind互換出力ってcallgrind形式ってことだよね！と勝手に思い込んでた

$ python manage.py runprofileserver --kcachegrind

おもむろにdotファイルに変換!

$ path/to/gprof2dot -o out.dot -f callgrind /tmp/xxx.prof
....
AssertionError

うまくいかない。何かの計算値がこうなるはずなのにならないよ！とか怒られてる。って良く考えたらKCacheGrind互換の出力がcallgrind形式って保証がどこにもない！

ってことで、あれこれドキュメント読んでたら、runprofileserverはhotshot使ってるとか何とか書いてあるから、何も指定しなかったらhotshotでの形式になる・・・ってことは全然説明されてないけど-fのオプションはpstatsで良いんじゃね？

と勝手に予想して

$ python manage.py runprofileserver

$ path/to/gprof2dot -o out.dot -f pstats /tmp/xxx.prof

とやるとout.dotが出来ましたとさ。あとは色んなとこに書いてある（例えばここ）ように、dotファイルを画像ファイルに変換すると、ちゃんと画像が出来上がった。

ただ・・・・、まだ設定分かってないからだと思うんだけど、出来上がった画像にはviewやmodelのメソッドが一切書かれておらず、この情報だけからボトルネック探すのかなりキツイんじゃね？ということだけが分かった。

同一ドメインのurlを内部で呼び出してハマる

何故かURLによってプロファイル作るのが途中で止まって、サーバもレスポンスを返してくれなくなった。問題箇所を調べると、どうも内部で同じrunprofileserverで管理しているurlにアクセスすると止まっちゃう模様。別サーバを立てて、そこにアクセスするようにすれば、問題無く動作した。

手間なのでMiddlewareでプロファイルすることにした

いちいち開発中の状態なのにサーバ2つ立てて面倒だったり、結局作った画像見ても良く分からなかったので、今度はMiddlewareに埋め込むタイプを試してみた。

取りあえず動かなくてハマる

Extendedって書いてあるしということでdjangosnippets: Extended Profiling Middlewareを試してみた。

手順は

  • ↑のページのファイルをダウンロード（コード右上にダウンロードボタンがある）
  • 適当な名前を付けてimport出来る適当な場所に配置。（オラはmodulesってとこにprofiler.pyという名前を付けて置いてみた）
  • settings.pyにmiddlewareを登録する
  • プロファイルしたいURLにprof=というパラメータを付けてブラウザでアクセスする

って感じ。settings.pyは

# settings.py
MIDDLEWARE_CLASSES = (
...
    'modules.profiler.ProfileMiddleware',
)

こんな感じ。で、上のようにブラウザでアクセスするとエラー・・・

AttributeError: 'WSGIRequest' object has no attribute 'has_key'

なので、コード上で

request.has_key

となっているところを

request.GET.has_key

と変更すると上手く動いた。ProfileMiddlewareのページ内コメントを見ると

'prof' in request.GET

と変更しても動くらしい。んで、プロファイルしたいurlにprof=をパラメータとして付けてアクセスすると、ブラウザ上に

47793 function calls (42681 primitive calls) in 0.907 seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3    0.608    0.203    0.608    0.203 /path/to/python/local/lib/python/site-packages/django/db/backends/utils.py:58(execute)
       30    0.112    0.004    0.112    0.004 /usr/lib/python/socket.py:406(readline)
       12    0.050    0.004    0.050    0.004 /usr/lib/python/socket.py:223(meth)
....

という形でプロファイルが表示出来た。もーこれでいーや。ということでやったのはここまで。まだまだだけど、取りあえずプロファイル結果を出すまでだけでハマったし、次回やっても同じようにハマりそうなのでメモしておく。