實戰 Python 效能分析 - 從 cProfile 到 py-spy

Posted on  Dec 9, 2021  in  Python 程式設計 - 高階  by  Amo Chen  ‐ 5 min read

Python 應用(application)相較於 Go, C 這類語言所寫的應用,前者執行效率較慢是公認問題,不過 Python 的易用性也相對地提升開發速度,甚至其 batteries included 的哲學以及豐富的生態系也能夠減少重複造輪的情況,大幅縮短從概念到產品的實現路徑。

至於執行效率的問題,其實可以透過多種手段進行改善,譬如進行分散式、多執行緒(multithreading)、多行程(multiprocessing)、改善演算法,或以其他較高效率的語言為 Python 進行擴充(例如 ctypes 模組),雖然無法保證一定能夠像 Go, C 這類語言同樣高效,但也能夠將效率提升到可接受的程度以上。

但在處理真正的效率問題之前,絕大多數可能是我們沒有以正確有效率的方式撰寫 Python 應用,而導致其執行效率較差,並且將問題怪罪於 Python 本身。

因此如何剖析 Python 程式,並且找到隱藏在其中的效率問題,是一門相當重要的課題,本文將從介紹 cProfile 模組開始,並以實際範例找出 Python 程式中的問題點,並使用 py-spy 工具更近一步精準定位問題所在,以提高找出問題的效率。

本文環境

$ pip install pandas==1.0.3 snakeviz py-spy

資料集

本文需要使用以下資料集作為範例程式所需要的資料集:

Daily Financial News for 6000+ Stocks

範例程式

以下是本文的範例程式,該程式會載入資料集中的 raw_partner_headlines.csv 檔,統計該資料集中 headline 欄位中含有 To New High 的美股代號以及出現該美股代號出現次數,並在最後由高至低將超過 5 次以上的美股代號依序列印。

import re
import pandas as pd

from collections import Counter


def load_data():
    return pd.read_csv(
        '<path to>/raw_partner_headlines.csv',
        chunksize=100
    )


def main():
    counter = Counter()
    for df in load_data():
        for r in df.itertuples():
            if re.search(r'To New High', r.headline):
                counter[r.stock] += 1

    for stock, count in sorted(
        counter.items(),
        key=lambda x: x[1],
        reverse=True
    ):
        if count >= 5:
            print(stock, count)


main()

上述範例執行結果如下,該範例大約會耗時 1 分鐘以上的時間執行:

$ time python test.py
ULTA 9
ALK 5
YY 5
python test.py  70.01s user 7.17s system 100% cpu 1:17.00 total

cProfile 模組

cProfile 是 Python 內建的效能分析模組,該模組提供 2 種方式讓開發者可以對 Python 程式進行效能分析:

  1. cProfile
  2. profile

上述 2 種方法差別在於實作方式, cProfile 是以 C 語言實作的 Python 擴充(extension), 適合用來剖析長時間執行的 Python 程式,不僅效能較好,也是 Python 官方推薦的方式;而 profile 則是由 Python 實作的模組,效能較差,一般不推薦使用 profile 對 Python 程式進行分析。

使用 cProfile 模組的方式相當簡單,只要在執行 Python 指令時加上 -m cProfile 即可。

以下為對前文範例程式進行剖析(profiling)的指令:

$ python -m cProfile test.py

上述指令執行到最後會列印效能分析的結果,如下所示:

...
         126019093 function calls (124921197 primitive calls) in 111.419 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <__array_function__ internals>:2(<module>)
   110737    0.102    0.000    0.380    0.000 <__array_function__ internals>:2(concatenate)

上述報表主要有 6 個重點:

  1. 執行時間 111.419
  2. 排序依據為 standard name, 也就是 filename:lineno(function) 欄位
  3. 每個 function 呼叫了幾次,也就是 ncalls 的值
  4. 每個 function 總計花費多少時間,但不包括該 function 所呼叫其他 function 的時間,也就是 tottime 的值
  5. 每個 function 總計花費多少時間,包括該 function 所呼叫其他 function 的時間,也就是 cumtime 的值
  6. 2 個 percall 則分別是 tottime 以及 cumtime 各自除以 ncalls 的值,也就是平均每次呼叫會花費的時間

預設的排序方式通常很難一眼看出問題,因此我們會更改排序方式,將按照 cumtime 的時間排序,通常時間花費最久的 function 就是問題點,值得我們 追查:

$ python -m cProfile -s cumulative test.py | less

上述指令多了 -s cumulative 代表以 cumtime 遞減排序(更多排序選項詳見官方文件):

...
         126019099 function calls (124921203 primitive calls) in 112.626 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  19157/1    7.448    0.000  113.576  113.576 {built-in method builtins.exec}
        1    0.000    0.000  113.576  113.576 test.py:1(<module>)
        1    2.707    2.707  113.179  113.179 test.py:14(main)
    18457    0.022    0.000   82.398    0.004 parsers.py:1105(__next__)
    18457    0.089    0.000   82.376    0.004 parsers.py:1160(get_chunk)
    18457    0.217    0.000   82.287    0.004 parsers.py:1131(read)
    18456    0.141    0.000   44.636    0.002 frame.py:414(__init__)
    18456    0.181    0.000   44.408    0.002 construction.py:213(init_dict)
    18457    0.259    0.000   36.784    0.002 parsers.py:2035(read)
    18457   28.631    0.002   35.912    0.002 {method 'read' of 'pandas._libs.parsers.TextReader' objects}

上述文字形式的分析報表通常會過於冗長,不便於閱讀,推薦使用 SNAKEVIZ 以視覺化的方式閱讀該報表,因此我們需要透過指令將文字報表輸出成檔案,以下指令用 -o 參數將報表輸出至 test.prof 檔案中:

$ python -m cProfile -o test.prof test.py

接著,使用 snakeviz 讀取該報表:

$ snakeviz test.prof

上述指令將會以瀏覽器(browser)打開圖表:

上圖可以看到 parsers.py:1105(__next__) 花費約 83.6 秒,佔整個 main() 執行時間 115 秒的 72% 左右,而 __next__ 為 Python 迴圈可能呼叫的方法,該方法又進一步呼叫 get_chunk ,所以可以看到 get_chunk 的 cumtime 與 __next__ 的 cumtime 幾乎一模一樣。

從這些線索就可以推測應該是程式碼 for 迴圈的部分相當花時間,如果進一步查詢 get_chunk 的資訊(如下圖所示),可以發現其 ncalls 值為 18457, 雖然 percall 只有 0.004 秒,但因為呼叫次數相當多,最終還是對執行時間產生影響,如果能夠降低 ncalls 就能有效縮短執行時間。

搭配 get_chunk 的線索,幾乎可以確定是範例程式中 chunksize=100 設定太小的緣故,可以試著將 chunksize 調到 1000 試試:

import re
import pandas as pd

from collections import Counter


def load_data():
    return pd.read_csv(
        '<path to>/raw_partner_headlines.csv',
        chunksize=1000
    )


def main():
    counter = Counter()
    for df in load_data():
        for r in df.itertuples():
            if re.search(r'To New High', r.headline):
                counter[r.stock] += 1

    for stock, count in sorted(
        counter.items(),
        key=lambda x: x[1],
        reverse=True
    ):
        if count >= 5:
            print(stock, count)


main()

接著再重複一次 profiling 的過程,並且查看執行時間是否下降:

從上述結果顯示將 chunksize 調整為 1000 之後,執行時間就降到 22.6 秒,而且 for 迴圈的部分也縮短為 13.9 秒,如果進一步查詢 ncalls, 也可發現呼叫次數縮短到 1847 次,如下圖所示:

行文至此,可以發現 cProfile 最多只能幫助我們追查到 function level 的效率問題,具體是 function 內的哪一行有問題,還是需要一些經驗進行推敲,如果能夠更具體定位到哪一行,將會更加有效率,這時可以使用類似 py-spy 等能夠逐行(line by line)分析的 profiler 幫忙。

py-spy

py-spy 是一套相當成熟的 sampling profiler, 預設每秒會對程式取樣 100 次,其運作原理是取樣讀取 Python 的記憶體,藉此了解 Python 當時正在執行什麼工作(從 call stack 能夠得知),所以執行時間越久的部分,越容易被取樣到,藉此達成分析的功能。

py-spy 除了支援 thread 的 profiling 之外, 也支援 multiprocessing 的 profiling, 也能夠針對執行中的 Python process 進行 profiling, 是相當值得學習如何使用的效能分析工具,更多 py-spy 介紹詳見官方文件

以下指令用 py-spy 對範例程式進行效能分析,並將結果輸出至 profile.svg :

$ sudo py-spy record -o profile.svg -- python test.py
Password:
py-spy> Sampling process 100 times a second. Press Control-C to exit.
...

p.s. macOS 需要使用 sudo 才能執行

上述指令完成之後會同樣會打開瀏覽器,並以火焰圖(flame graph)形式呈現分析結果,如下圖所示,從圖中藍色箭頭所指可以看到 py-spy 清楚地顯示出 test.py 第 16 行的部分佔了絕大多數的執行時間,而 16 行剛好就是 for 迴圈的部分,相較於 cProfile 的分析結果而言又更加明確。

總結

雖然 cProfile 有其不便的地方,但卻是 Python 內建提供的模組,不需額外安裝其它套件,同時該模組也是學習 Python 效能分析很好的開始,是相當值得閱讀學習的模組,在了解其原理之後,對於其他工具也會相當好上手。

另外,實務上效能分析與改善的過程通常會較為複雜一點,本文所提供的範例只是為了簡化過程而設計,本文僅是扮演一個引路的角色,基本上還是需要仰賴多次的練習才能夠提升效能分析與改善的技能。

以上!

Happy coding!

References

https://docs.python.org/3/library/profile.html

https://github.com/benfred/py-spy

對抗久坐職業傷害

研究指出每天增加 2 小時坐著的時間,會增加大腸癌、心臟疾病、肺癌的風險,也造成肩頸、腰背疼痛等常見問題。

然而對抗這些問題,卻只需要工作時定期休息跟伸展身體即可!

你想輕鬆改變現狀嗎?試試看我們的 PomodoRoll 番茄鐘吧! PomodoRoll 番茄鐘會根據你所設定的專注時間,定期建議你 1 項辦公族適用的伸展運動,幫助你打敗久坐所帶來的傷害!

贊助我們的創作

看完這篇文章了嗎? 休息一下,喝杯咖啡吧!

如果你覺得 MyApollo 有讓你獲得實用的資訊,希望能看到更多的技術分享,邀請你贊助我們一杯咖啡,讓我們有更多的動力與精力繼續提供高品質的文章,感謝你的支持!