Python 程式的 Profiling 2 - cProfile Má-tsìo (Module)

cProfile Má-tsìo (Module)

cProfile 是共規个程式來分析, 程式內面个函式, 予人呼幾遍? 逐遍開偌濟時間? 予你真簡單就會使了解程式个關頭佇佗位? 紲落來个例, 有一寡是直接 uì 伊的官網提過來.

上完整个了解 cProfile, 當然是參考伊的官網.  佇遮, 我有閣參考這篇: Python 用 cProfile 測量程式效能瓶頸與 gprof2dot 視覺化分析教學 , 有興趣會使揤入去看.

簡單例

佮 timeit 相siâng, 伊會使用佇命令列直接用抑是 Python 內底用 Má-tsìo 方式共伊 import 入來使用 。咱先介紹命令列, 用法是:

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)

-s  : 是排序(pâi-sū) 个根據, 較捷捷用个有:

• 'calls'            :予人呼个數目. 這是預設值
• 'cumtine'      :粒積个時間

咱來起行 train_neuralnet.py 做一个例較清楚: (注意: 這个咧愛uì https://gitlab.com/Iunn/deep-learning-from-scratch/tree/master 全部搝落來才會振動)

$ python3 -m cProfile train_neuralnet.py
train acc, test acc | 0.09915, 0.1009
...
train acc, test acc | 0.9449333333333333, 0.9429
train acc, test acc | 0.9467, 0.9431
         887729 function calls (881058 primitive calls) in 237.808 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      571    0.001    0.000    0.001    0.000 :103(release)
      360    0.000    0.000    0.000    0.000 :143(__init__)
      360    0.000    0.000    0.004    0.000 :147(__enter__)
      360    0.000    0.000    0.001    0.000 :151(__exit__)
      571    0.002    0.000    0.003    0.000 :157(_get_module_lock)
      359    0.001    0.000    0.001    0.000 :176(cb)
      211    0.000    0.000    0.001    0.000 :194(_lock_unlock_module)
    479/7    0.000    0.000    0.403    0.058 :211(_call_with_frames_removed)
     3475    0.001    0.000    0.001    0.000 :222(_verbose_message)
        5    0.000    0.000    0.000    0.000 :232(_requires_builtin_wrapper)
....

伊會自動共上定定用个囥頭一个, 才那來若細排--落來. 欄位(nuâ-uī) 个意義是按呢:

• ncalls        :予人呼幾擺
• tottime      : 佇這个函式來底, 無共囝函式 (subroutine) 算在內, 開偌濟時間
• percall      : tottime/ncall, 也就是一个 call 个時間。
• cumtime   : 粒積个時間, 共囝函式个時間攏算入來
• percall      :第二个 percall是 cumtime/ncalls
• filename:lineno :函式名和第幾行

咱若是用 -s cumulative 來行, 伊就是按呢生:

$ python3 -m cProfile -s cumulative train_neuralnet.py
train acc, test acc | 0.09751666666666667, 0.0974
。。。。

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    318/1    0.009    0.000   36.585   36.585 {built-in method builtins.exec}
        1    2.237    2.237   36.585   36.585 train_neuralnet.py:2()
    70371   17.960    0.000   17.960    0.000 {built-in method numpy.core.multiarray.dot}
    10000    0.667    0.000   14.686    0.001 two_layer_net.py:55(gradient)
    10034    0.619    0.000   14.124    0.001 two_layer_net.py:18(predict)
    10000    0.035    0.000    7.642    0.001 two_layer_net.py:30(loss)
       34    0.043    0.001    7.193    0.212 two_layer_net.py:35(accuracy)
    40034    6.362    0.000    6.362    0.000 functions.py:13(sigmoid)

前兩個就差不多是規个 Má-tsìo, uì 第三个開始是咱的函式名. -s 个完整參數佇官網有. 你嘛會使看輸出个欄位名.

共輸出儉入去檔案

頂懸个命令, 干焦共結果 uì 標準輸出 (stdout)。咱嘛會使先共結果儉--起來，事後才閣用另一个Má-tsìo來分析. 按呢咱就會使用無仝个排序來斟酌分析結果, 毋免行幾落變程式。
若是欲共輸出儉佇檔案, 愛添 -o:
.

$ python3 -m cProfile -o train_neuralnet.pstats train_neuralnet.py

綴佇後壁  train_neuralnet.pstats 是檔案名.
徙落來, 咱會使用 -m pstats 來分析這个檔案:

$ python3 -m pstats -o train_neuralnet.pstats

你揤 ENTER 了後, 就入去一咧殼 (Shell), 這个殼裡, 是 pstats 的世界, 你會當落 pstats 个命令:

train_neuralnet.pstats % sort cumtime       # 用 cumtime 排序
train_neuralnet.pstats % stats              # 共伊印出來
Mon Jul 23 20:51:48 2018    ./out.pstate

         898211 function calls (891473 primitive calls) in 32.642 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    318/1    0.010    0.000   32.642   32.642 {built-in method builtins.exec}
        1    1.784    1.784   32.642   32.642 train_neuralnet.py:2()
    70612   14.804    0.000   14.804    0.000 {built-in method numpy.core.multiarray.dot}
    10000    0.541    0.000   12.327    0.001 /home/black/data/myRoadMap/myGit/my_python/my-deep-learning/deep-learning-from-scratch/ch04/two_layer_net.py:55(gradient)
    10034    0.476    0.000   11.870    0.001 /home/black/data/myRoadMap/myGit/my_python/my-deep-learning/deep-learning-from-scratch/ch04/two_layer_net.py:18(predict)
    10000    0.027    0.000    6.370    0.001 /home/black/data/myRoadMap/myGit/my_python/my-deep-learning/deep-learning-from-scratch/ch04/two_layer_net.py:30(loss)
       34    0.019    0.001    6.070    0.179 /home/black/data/myRoadMap/myGit/my_python/my-deep-learning/deep-learning-from-scratch/ch04/two_layer_net.py:35(accuracy)
    40034    5.631    0.000    5.631    0.000 ../common/functions.py:13(sigmoid)
.....
train_neuralnet.pstats % sort ncalls          # 用 ncalls 排序
train_neuralnet.pstats % stats 10             # 共伊印出來, 干焦印十行
Mon Jul 23 20:51:48 2018    ./out.pstate

         898211 function calls (891473 primitive calls) in 32.642 seconds

   Ordered by: call count
   List reduced from 3637 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    80644    1.161    0.000    1.161    0.000 {method 'reduce' of 'numpy.ufunc' objects}
74790/74786    0.038    0.000    0.042    0.000 {built-in method builtins.isinstance}
    70612   14.804    0.000   14.804    0.000 {built-in method numpy.core.multiarray.dot}
    50072    0.022    0.000    0.542    0.000 _methods.py:31(_sum)
    50068    0.146    0.000    0.720    0.000 fromnumeric.py:1778(sum)
    40034    5.631    0.000    5.631    0.000 functions.py:13(sigmoid)
    26000    0.005    0.000    0.005    0.000 {method 'append' of 'list' objects}
    20514    0.003    0.000    0.003    0.000 {method 'startswith' of 'str' objects}
    20167    0.013    0.000    0.540    0.000 _methods.py:25(_amax)
    20109    0.079    0.000    0.619    0.000 fromnumeric.py:2222(amax)

uì頂仔个例, 咱會使隨時換捌種排序个方式, 免閣重行規个程式. 咱嘛會寫落 help 來看命令ê用法.

train_neuralnet.pstats% help

Documented commands (type help ):
========================================
EOF  add  callees  callers  help  quit  read  reverse  sort  stats  strip

train_neuralnet.pstats% help sort
Sort profile data according to specified keys.
(Typing `sort' without arguments lists valid keys.)
train_neuralnet.pstats% sort
Valid sort keys (unique prefixes are accepted):
calls -- call count
ncalls -- call count
cumtime -- cumulative time
cumulative -- cumulative time
file -- file name
filename -- file name
line -- line number
module -- file name
name -- function name
nfl -- name/file/line
pcalls -- primitive call count
stdname -- standard name
time -- internal time
tottime -- internal time
train_neuralnet.pstats% 

Má-tsìo 方式 (Module)

就是用 import 共伊搝入來, 使用伊的 run() 方法:

import cProfile
import re
cProfile.run('re.compile("foo|bar")', 'restats')

佇頂仔个例, 咱對  re.compile("foo|bar") (re 是 regular expression)做 profile, 共結果儉入去restats  這个檔案中方.

咱會當用 pstats Má-tsìo 來共 restats 轉做人看有个型式:

import pstats

p = pstats.Stats('restats')
p.strip_dirs().sort_stats(-1).print_stats()

佇我的電腦 (Ubuntu 18.04, Python 3.6.5), 輸出:

Wed Jul 18 21:01:07 2018    restats

         199 function calls (194 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 :1()
        4    0.000    0.000    0.000    0.000 enum.py:265(__call__)
        4    0.000    0.000    0.000    0.000 enum.py:515(__new__)
        2    0.000    0.000    0.000    0.000 enum.py:801(__and__)
        1    0.000    0.000    0.001    0.001 re.py:231(compile)
....

咱會使看著: 伊是用名个順序來排先後.

排序个根據

若是欲改變排序个根據, 佇咧 sort_stats() 內底囥無仝个參數, 親像 'time', 'cumtime', 就會使.

>>> help(p.sort_stats)

>>> p.sort_stats('cumtime')

>>> p.print_stats()
Wed Jul 18 21:12:10 2018    restats

         199 function calls (194 primitive calls) in 0.001 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}
        1    0.000    0.000    0.001    0.001 :1()
        1    0.000    0.000    0.001    0.001 re.py:231(compile)
        1    0.000    0.000    0.001    0.001 re.py:286(_compile)

NOTE: 我是佇 Python 3.6.x 版,  猶原是用字串, 若是 3.7 版, 就愛 import  SortKey, 用伊的定義好个符號:

from pstats import SortKey
p.sort_stats(SortKey.NAME)

減省輸出

有當時, 咱干焦想欲看較重要个代誌, 無想欲全部个資訊攏摒摒--出來, 咱看甲目睭花, 咱會使佇 print_stats() 个參數添數字, 比如講 5 就是咱干焦想欲看上懸个五个函式:

>>> p.sort_stats('time').print_stats(5)
Wed Jul 18 21:12:10 2018    restats

         199 function calls (194 primitive calls) in 0.001 seconds

   Ordered by: internal time
   List reduced from 42 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}
      3/1    0.000    0.000    0.000    0.000 sre_parse.py:173(getwidth)
        1    0.000    0.000    0.001    0.001 re.py:286(_compile)
      3/1    0.000    0.000    0.000    0.000 sre_compile.py:64(_compile)
        2    0.000    0.000    0.000    0.000 sre_parse.py:470(_parse)

你嘛會使干焦看指定ê函式名:

>>> p.sort_stats('time').print_stats('__init__')

抑是看啥人呼伊? 抑是予人呼?

>>> p.print_callers(,'init')
...
>>> p.print_callees()

命令列用法和 Má-tsìo 用法 ê 討論

命令列用法 -m cProfile 是方便, 毋過, 伊是 uì 程式外爿開始做, 所以戲文本身嘛會算入來. 親像頂仔个例:

$ python3 -m cProfile -s cumulative train_neuralnet.py
...
...
        1    2.237    2.237   36.585   36.585 train_neuralnet.py:2()

若是用 Module 用法, 伊就是真正是戲文內面使用著个物件. 而且, 伊會使佇你干焦想欲 profiling 个所在做就好:

import cProfile

pr = cProfile.Profile()
pr.enable()
....                           # 想欲 profiling 个所在
pr.disable()
pr.print_stats(sort='time')

若是欲趕時間, 就是用命令列, 若是欲做較幼路个,  就是使用 Má-tsìo 用法.

用  gprof2dot 來生圖形

親像頂懸介紹个輸出, 是一逝一逝个表。雖罔有排序, 毋過對咱人來講, 也是較食力看. 若是會使用圖形, 較直接.

若是欲按呢做, 愛用著另外兩種工具, 一个是 pyhton 个 Má-tsìo (Module), 另一个是 Linux 頂懸个包袱仔 (package).

咱這馬來安 gprof2dot Má-tsìo:

sudo pip3 install gprof2dot

另外閣安 graphviz:
佇 Ubuntu/Debian Linux:

sudo apt-get install graphviz

佇 Fedora Linux:

sudo yum install graphviz

若是你的 sudo 袂喈, 你就愛成做 root 使用者.

咱用進前个 train_neuralnet.py 來生出 train_neuralnet.pstats

python3 -m cProfile -o train_neuralnet.pstats train_neuralnet.py

閣來才利用 pstats 來生出 png 圖檔:

python3 -m gprof2dot -f pstats train_neuralnet.pstats |dot -T png -o train_neuralnet-profile.png

頂懸个命令你先共伊看做公式, 除了輸入 train_neuralnet.pstats 佮輸出 train_neuralnet-profile.png 你會當家己指定, 賰咧攏固定. 你若是有興趣欲了解閣較濟, 會用个參考 Graphviz 官網. 這是伊的輸出:

若是欲放大, 點遮.
咱佇圖裡, 真簡單就會當看出來: gradient 39% 佔上濟, predict 38%. 毋過佇較低層內面, numpy 个 dot 佔欲 48%.