找到python代码的性能瓶颈

问题定义

想要优化Java中的内存管理，就要查看GC_log来定位内存瓶颈；同理，想要优化python代码，就要统计各函数的运行时间来定位性能瓶颈。
最方便的就是直接使用jupyter notebook自带的两个magic指令：%prun和%lprun

注意：本文默认读者已经熟悉Jupyter notebook和python基础。如果您需要复习，可以参考这篇文章

%prun^[1]

用来统计各函数调用次数及耗时。e.g. :

def f():
    # additional line1...
    # additional line2...
    scores = detector.run_cases(cases_ballon, allow_near_phones=False, show_phone_heatmap=False, fig_ratio=(1, 1)) 
    # additional line3...
    
# -T选项指定写到的文本文件， -l选项指定只显示前多少行
# 另外也可以用 -l <partial func name> 来过滤，只保留name包含指定子串的函数
%prun -T ./res/prun.txt -l 20 f()

# 另外还有一个cell magic，叫 %%prun
# 它相当于把cell内的多行代码，合并成一行长代码；作为最后一个参数送给 %prun；以免用f()来封装代码的麻烦

运行上述cell，会在jupyter notebook中弹窗显示如下结果，并写到文本文件./res/prun.txt

         982179 function calls (971601 primitive calls) in 2.241 seconds

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

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1390    1.422    0.001    1.551    0.001 ctc_based_kws.py:320(score_by_sliding_window)
   436939    0.126    0.000    0.126    0.000 {built-in method builtins.max}
    81438    0.020    0.000    0.033    0.000 {built-in method builtins.isinstance}
7639/7480    0.015    0.000    0.017    0.000 {built-in method numpy.core.multiarray.array}
     2797    0.014    0.000    0.019    0.000 weakref.py:101(__init__)

如上所示，累计耗时最多的function call为score_by_sliding_window()，位于ctc_based_kws.py:320，消耗了1.422秒；其次是某处对python/numpy内置的max()的调用。
通过prun能获得的信息就是这些，只能精确到函数级，而且对于内置函数提供的有用信息并不多。
想要进一步定位问题，可以对关键的几个函数实施代码行级别的profiling，即%lprun

%lprun^[2]

lprun跟prun只有一字之差，但是功能不同——是用来统计各行代码的调用次数和时间的。
而且，前者并没有内置到python中，而且通过一个叫作line_profiler的第三方库^[3]来实现的。

!pip install line_profiler

%load_ext line_profiler # 将这个模块加载到ipython kernel中
# 也可以通过改配置文件的方式，来永久地自动加载这个模块
# vi ~/.ipython/profile_default/ipython_config.py
# c.TerminalIPythonApp.extensions = ['line_profiler',]
# 参考: https://stackoverflow.com/questions/19942653/interactive-python-cannot-get-lprun-to-work-although-line-profiler-is-impor

用起来也比较直观，e.g.:

# 没有-l选项了，只有-f和-m选项
# -f func1 -f func2 -m module1 -m module2 <code to profile> 表示只统计指定的func1和func2两个函数，以及module1和module2两个模块的代码行
# 注意-f指定的必须是可以找到的函数对象，不是函数名称的子串，这一点跟prun有区别
%lprun -T ./res/lprun.txt -f Detector.score_by_sliding_window f()

结果

# 注意时间单位是默认的，最新版的line_profile支持-u选项来设置，但是还没推到pipy上
Timer unit: 1e-06 s

Total time: 0.000665 s
File: /Users/qianws/anaconda/lib/python3.5/site-packages/numpy/core/fromnumeric.py
Function: amax at line 2174

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
  2174                                           def amax(a, axis=None, out=None, keepdims=np._NoValue):
  2175                                               """
  2257                                               ... docstring ...
  2258                                               """
  2259       100           66      0.7      9.9      kwargs = {}
  2260       100           62      0.6      9.3      if keepdims is not np._NoValue:
  2261                                                   kwargs['keepdims'] = keepdims
  2262                                           
  2263       100           72      0.7     10.8      if type(a) is not mu.ndarray:
  2264                                                   try:
  2265                                                       amax = a.max
  2266                                                   except AttributeError:
  2267                                                       pass
  2268                                                   else:
  2269                                                       return amax(axis=axis, out=out, **kwargs)
  2270                                           
  2271       100           74      0.7     11.1      return _methods._amax(a, axis=axis,
  2272       100          391      3.9     58.8                            out=out, **kwargs)

Total time: 5.67407 s # 逐行统计时间本身也对耗时也干扰，这里的数字比正常运行时偏大
File: /Users/qianws/jupyterNotebooks/KWS/ctc_based_kws.py
Function: score_by_sliding_window at line 320

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   320                                               def score_by_sliding_window(self, l: List[str], P: np.ndarray) -> float:
   321                                                   """... docstring ..."""
                                                                ...
   335     55600        44393      0.8      0.8          for t in range(1, T):
   336    542100       469812      0.9      8.3              for s in range(0, S):
                                                                ...
   349    487890       494446      1.0      8.7                  if s >= 2 and l[s] != l[s - 2] and l[s] != '_':
   350    162630       499166      3.1      8.8                      a[s, t] = walk_fn([a[s, t - 1] * mut_l, a[s - 1, t - 1] * p, a[s - 2, t - 1] * p])
   351    325260       255332      0.8      4.5                  elif s >= 1:
   352    271050       721568      2.7     12.7                      a[s, t] = walk_fn([a[s, t - 1] * mut_l, a[s - 1, t - 1] * p])
   353                                                           else:
   354     54210        79284      1.5      1.4                      a[s, t] = mut_l * (a[s, t - 1])  # l[0]必然是blank，其概率不参与重复的连乘                                     
                                                                ...
   361      1390         1314      0.9      0.0          return res

不难看出，第352行的walk_fn的调用占了12.7%的时间，是重点优点目标。
至于其内部具体哪一行慢，可以如法炮制，再跑一轮%lprun

---

1. API详见 http://ipython.readthedocs.io/en/stable/interactive/magics.html#magic-prun ↩

2. 没有独立的API文档页，只能看docstring，详见 https://github.com/rkern/line_profiler/blob/master/line_profiler.py 第266行 ↩

3. 项目地址 https://github.com/rkern/line_profiler ↩