[Python] Easy python profiling

話說, 常常寫 python 會碰到一些 performance issue

因為 python 太多好用的 function, 很容易就不小心用很直覺得方式去撰寫 code

而導致有些寫法其實會無意間增加很多的執行時間

一般情況下一般人在 Linux 會使用 time 來簡易的衡量程式跑得時間

可是問題是這並沒有辦法知道你寫的 function 中哪一行花費了最多的時間, or 耗費的記憶體

首先針對執行時間, 有個 python module 可以幫你改善這件事情

line profiler: http://pythonhosted.org/line_profiler/

1. 安裝很容易, 只要輸入下面指令即可

sudo pip install line_profiler

2. 假設我程式碼如下

import random

def uniq1(a):
    b = []
    for i in a:
        if not b.count(i):
            b.append(i)
    return b

def main():
    a = [random.randint(1, 100) for i in range(100)]
    uni = uniq1(a)

if __name__=='__main__':
    main()

這只是一個很簡單的程式, 首先我先隨機產生一個 list a 100筆

那當然 a list 會有很多重複的值, 所以我要取一個 uniq 的結果

所以我寫了一個很單純的方法, 就是宣告一個 b, 然後用 count 的方法去檢查

如果沒出現在 b, 就新增到 b, 有的話就不理會, 最後回傳 b

執行結果速度好像還滿快的, 可是如果今天我要產生的是 10000 筆, 程式速度馬上大幅下降

首先先不管 random 其實有個 sample method 可以讓產生出來的東西是 uniq, 這不是我要談的主題

再來, 我想要知道上述 function 哪裡是最慢的主因, 要怎麼看?(後面範例都是用10000筆)

可以在 function 上面加上 decorate @profile

ex:

@profile
def uniq1(a):
    b = []
    for i in a:
        if not b.count(i):
            b.append(i)
    return b

然後執行程式的時候輸入(假設我的檔案叫做 lazy.py)

kernprof.py -l -v lazy.py

除了他會執行程式之外, 他還會印出有執行到有加 @profile 的 function 結果

hhtu@hhtu:~$ kernprof.py -l -v lazy.py 
Wrote profile results to lazy.py.lprof
Timer unit: 1e-06 s

File: lazy.py
Function: uniq1 at line 3
Total time: 0.683704 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     3                                           @profile
     4                                           def uniq1(a):
     5         1            6      6.0      0.0      b = []
     6     10001         9519      1.0      1.4      for i in a:
     7     10000       667081     66.7     97.6          if not b.count(i):
     8      6328         7096      1.1      1.0              b.append(i)
     9         1            2      2.0      0.0      return b

稍微解釋一下每個項目

Total time: 總執行時間
--------
Line #: 程式碼的第幾行
Hits: 這行被執行幾次
Time: 這行執行總共花了多少時間, 單位在上面的 timer unit
Per Hit: 平均每次花多少時間
% Time: 以整個執行時間來講, 這行佔了多少時間比例
Line Contents: Source code

很明顯可以看得出來, 居然花了 0.6秒, 而且大多是在判斷 b.count那邊花費太多時間

那個 -v option 指的是結果印在 console 上, 不要存成檔案

所以如果你不加 -v, 他會存成 lazy.py.lprof, 這是 binary file

要檢視的話要輸入

python -m line_profiler lazy.py.lprof

就會印出跟直接顯示在 console 一樣的結果

那這邊我再寫個 function, 用 dict 試試看

@profile
def uniq2(a):
    b = {}
    for i in a:
        if i not in b:
            b[i] = 1 
    return b.keys()

測試結果

hhtu@hhtu:~$ kernprof.py -l -v lazy.py 
Wrote profile results to lazy.py.lprof
Timer unit: 1e-06 s

File: lazy.py
Function: uniq2 at line 11
Total time: 0.025542 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    11                                           @profile
    12                                           def uniq2(a):
    13         1            1      1.0      0.0      b = {}
    14     10001         9021      0.9     35.3      for i in a:
    15     10000         9767      1.0     38.2          if i not in b:
    16      6328         6678      1.1     26.1              b[i] = 1
    17         1           75     75.0      0.3      return b.keys()

會發現已經大幅下降比對的時間, 總共只花 0.02秒, 用此 profile 就可以很明顯看出差異

不過其實假如不在意 list 的 order 結果的話, 我大多是用 set

@profile
def uniq3(a):
    return set(a)

很單純, 就只是把傳進入的 list 轉成 set, 然後傳出去, 就做完了

hhtu@hhtu:~$ kernprof.py -l -v lazy.py 
Wrote profile results to lazy.py.lprof
Timer unit: 1e-06 s

File: lazy.py
Function: uniq3 at line 19
Total time: 0.00061 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    19                                           @profile
    20                                           def uniq3(a):
    21         1          610    610.0    100.0      return set(a)

這就更扯了, 只花了 0.0006秒, 不過缺點就是他的 order 並非原本的 list order

當然還有很多方法可以做到 uniq list, 這邊只是舉例怎麼使用 line profile

對於讀寫資料的人, 或許是個很適合的 profiler

至少可以觀察出哪邊的 I/O 太多, 或者是可改善的空間可能是哪邊

當然怎麼改善要看個人經驗, 或者多上網 google 查看看

另外, 如果想要偵測的是 memory usage, 也有 tool 可以達到

sudo pip install -U memory_profiler

本來我只安裝了, memory_profiler, 結果執行的時候會出現 warnings.warn("psutil module not found. memory_profiler will be slow")

那我就乖乖聽他的話也順便裝了 psutil

sudo pip install psutil

然後使用方法相當令人高興, 如果是從上面 line profile 用下來, 程式碼都不用改

因為他也是一樣加個 @profile decorate 在 function 之前, 所以只是差異在執行方法

python -m memory_profiler lazy.py

馬上就列出了我剛剛三個方法所使用的記憶體空間

hhtu@hhtu:~$ python -m memory_profiler lazy.py
Filename: lazy.py

Line #    Mem usage    Increment   Line Contents
================================================
    11                             @profile
    12     7.922 MB     0.000 MB   def uniq2(a):
    13     7.922 MB     0.000 MB       b = {}
    14     8.879 MB     0.957 MB       for i in a:
    15     8.879 MB     0.000 MB           if i not in b:
    16     8.879 MB     0.000 MB               b[i] = 1
    17     8.879 MB     0.000 MB       return b.keys()


Filename: lazy.py

Line #    Mem usage    Increment   Line Contents
================================================
     3                             @profile
     4     7.336 MB     0.000 MB   def uniq1(a):
     5     7.340 MB     0.004 MB       b = []
     6     7.922 MB     0.582 MB       for i in a:
     7     7.922 MB     0.000 MB           if not b.count(i):
     8     7.922 MB     0.000 MB               b.append(i)
     9     7.922 MB     0.000 MB       return b


Filename: lazy.py

Line #    Mem usage    Increment   Line Contents
================================================
    19                             @profile
    20     8.500 MB     0.000 MB   def uniq3(a):
    21     8.812 MB     0.312 MB       return set(a)

基本上是相當的明瞭阿!!

如果對如果快速做出 uniq list 有興趣的可以參考下面這篇

http://www.peterbe.com/plog/uniqifiers-benchmark