太陽曰く、Python cProfileでボトルネックとなっている関数を特定せよ！

我々！
うー！
寄れ依れ！
にゃー！

こんにちは、無能です。
最近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の話になってきたのでここまで。
またよろしくお願いします。