太陽曰く、Python cProfileでボトルネックとなっている関数を特定せよ!
5 min read
我々!
うー!
寄れ依れ!
にゃー!
こんにちは、無能です。
最近PCいじりながらラジオ感覚で聞いている元ハル研究所出身の桜井政博さんのチャンネルを裏で流しているとすごく楽しいです。
というか、3DSをいじっていた記憶も蘇り当時見ていた岩田社長のニンテンドーダイレクトはいつも楽しかった。改めてみていると、他で言えば富士通の池田敏雄だとか、ドキュメンタリーを見ると熱量があり、この当時で米国に何度も渡るなんて信じられないような世界です。当時ベトナム戦争もあり、第二次世界大戦後の戦後の影はあったはずなのに一体そのエネルギーはどこから湧いてきたのか。
はじめに
あまりスクリプト言語に対しての実行速度に対してあまり意識していなかったのだが自分が作っているcuckoogetを実行していると、ついつい気になってしまった。
一部はRustで書いたコードをPyO3/maturinでインタプリタの中でRustコードを実行できます。
もっとかんたんに言えば、Rustで書いた関数をPythonのライブラリ化し実行されるのはRustで書いたコードをコンパイルしたバイナリファイルを介し実行が行われます。CPU演算するような処理に関してはこのバイナリファイルで実行させた方が早くなりそうだからというシンプルな理由です。結果的には早くなりましたがこれには大きな間違いがあります。
まずは測定をそもそもOnly Pythonなコードでベンチマークテストを行わずに行っていたということ。
Goの父とも呼ばれるロブ・パイクが書いた「Cプログラミングに関する覚え書き」にも
ルール1: プログラムがどこで時間を消費することになるか知ることはできない。ボトルネックは驚くべき箇所で起こるものである。したがって、どこがボトルネックなのかをはっきりさせるまでは、推測を行ったり、スピードハックをしてはならない。
とあるならば、測定はするべきです。 低レイヤー層のC言語における原則がこうであるなら、それよりも上に属するレイヤー層には適応しないなんてことはありえないでしょう。
時々こういうことを忘れてしまうので、定期的に確認をするUNIX思想のようなものは自分を律するものとして必要だとつくづく感じます。
と、書きましたが人間なのでわかってはいつつ、ついつい外れ値を引きがちな自分です・・・。
cProfileでの計測
最初はimport time
から、start_time = time.time()
と関数の実行終了のend_time = time.time()
後にprint(f"exec time {start_time - end_time}")
と原始的な方法をやってましたがわざわざコンピュータを使っているのにこんな非効率的な!と、何かしら関数ごとに実行時間を表示してくれるものを探してみました。
標準ライブラリとしてcProfile
なるものがあるらしい。 以下のサイトがわかりやすいです。
Python cProfile でコードのパフォーマンスを解析する
私の場合以下で確認。
python3 -m cProfile -o profile.pstats ./main.py https://soulminingrig.com/ site
これによって、./main.py
で実行されている関数による実行時間はprofile.pstats
というバイナリファイルに格納されます。
関数実行結果を確認
先程のサイトではPythonの実行ファイルを使い行っていましたが、もっとお手軽にpstats
のコマンドラインモードに入り確認します。
python3 -m pstats profile.pstats
これでpstats
のコマンドラインモードに入り、以下で出力結果を確認します。
profile.pstats% stats 5
Thu Nov 7 20:24:10 2024 profile.pstats
48488696 function calls (47625490 primitive calls) in 51.151 seconds
Random listing order was used
List reduced from 3017 to 5 due to restriction <5>
ncalls tottime percall cumtime percall filename:lineno(function)
1586 0.001 0.000 0.001 0.000 /home/haturatu/.local/lib/python3.12/site-packages/aiohttp/client_reqrep.py:909(__del__)
80 0.000 0.000 0.001 0.000 /usr/lib/python3.12/copy.py:247(_reconstruct)
4 0.000 0.000 0.005 0.001 /usr/lib/python3.12/encodings/__init__.py:71(search_function)
3 0.000 0.000 98.745 32.915 /usr/lib/python3.12/asyncio/base_events.py:651(run_until_complete)
1103 0.001 0.000 0.003 0.000 /usr/lib/python3.12/re/_parser.py:312(_class_escape)
help
で他のコマンドを確認できます。
profile.pstats% help
Documented commands (type help <topic>):
========================================
EOF add callees callers help quit read reverse sort stats strip
私の場合、stats 100
として出力し別で開いてるターミナルからvim
でテキトウに開いてコピペしてquit
しました。
このvim
にペーストして保存したテキストファイルに対して、awk
とsort
でそれぞれ見ていきます。
tottimeの場合
$ awk '{ print $2","$6 }' bench | sort | column -t -s "," | tail
0.009 /usr/lib/python3.12/re/_compiler.py:243(_optimize_charset)
0.010 /usr/lib/python3.12/concurrent/futures/_base.py:428(result)
0.012 /usr/lib/python3.12/asyncio/base_events.py:627(run_forever)
0.013 /usr/lib/python3.12/re/__init__.py:280(_compile)
0.018 /usr/lib/python3.12/re/_compiler.py:37(_compile)
0.022 /usr/lib/python3.12/concurrent/futures/_base.py:497(set_running_or_notify_cancel)
0.030 /home/haturatu/git/devgit/async_web_mirror.py:186(download_and_save_image)
0.031 /usr/lib/python3.12/re/_parser.py:512(_parse)
0.061 /usr/lib/python3.12/concurrent/futures/_base.py:537(set_result)
tottime filename:lineno(function)
なんとなーく、tottime
だけで一旦関数ごとのベンチ的なものは情報としては十分なような感じがします。
Beatiful soup4のボトルネックは気の所せい?
他環境から出てきた遅かったのがbs4
から呼び出されているelement.py
のsearch_tag
が足引っ張っているようだった。
気になったのはここ
if ((not self.name)
or call_function_with_tag_data
or (markup and self._matches(markup, self.name))
or (not markup and self._matches(markup_name, self.name))):
or
演算でボトルネックになっているとは信じがたいが・・・。
ただ、このelement.py
のなかでor
で評価している箇所は7箇所しかなく、そのうちの3つがここで使われていることになっている。
なんかここ、臭いんだよなあ。
という訳で、なんか話題がbs4
の話になってきたのでここまで。
またよろしくお願いします。