太陽說，用 Python cProfile 找出瓶頸函數！

5 min

python
language: ja bn en es hi pt ru zh-cn zh-tw

我們！
嗚！
靠過來！
喵！

大家好，我是無能。
最近一邊玩電腦一邊像聽廣播一樣聽著前 HAL 研究所出身的櫻井政博先生的頻道，感覺非常愉快。
話說回來，玩 3DS 的記憶也復甦了，當時看的岩田社長的任天堂直面會總是那麼有趣。重新審視，如果說到其他人，像是富士通的池田敏雄，看紀錄片時會感受到他們的熱情，在那個時代多次前往美國，真是令人難以置信的世界。當時還有越南戰爭，二戰後的陰影應該還存在，但那股能量究竟是從何而來的呢？

前言

我以前不太在意腳本語言的執行速度，但當我執行自己開發的cuckooget時，卻忍不住開始在意了。
部分程式碼是用 Rust 編寫的，可以透過 PyO3/maturin 在解釋器中執行 Rust 程式碼。
更簡單地說，將用 Rust 編寫的函數包裝成 Python 函式庫，執行時會透過編譯後的 Rust 程式碼的二進位檔案來執行。對於 CPU 運算密集型的處理，這樣做的簡單理由是透過這個二進位檔案執行可能會更快。結果確實變快了，但這其中有一個很大的錯誤。
首先，我根本沒有對純 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來進行每個函數的基準測試，資訊量似乎已經足夠了。

Beautiful Soup 4 的瓶頸是我的錯覺嗎？

從其他環境發現，拖慢速度的是從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了，所以就到這裡。
之後也請多多指教。

Related Posts