Python性能分析指南

英文原文：A guide to analyzing Python performance
尽管并非每个你写的Python程序都需要严格的性能分析，但了解一下Python的生态系统中很多优秀的在你需要做性能分析的时候可以使用的工具仍然是一件值得去做的事。

分析一个程序的性能，最终都归结为回答4个基本的问题：

    1.程序运行速度有多快？
    2.运行速度瓶颈在哪儿？
    3.程序使用了多少内存？
    4.内存泄露发生在哪里？
下面，我们将使用一些优秀的工具深入回答这些问题。

使用time工具粗糙定时

首先，我们可以使用快速然而粗糙的工具：古老的unix工具time，来为我们的代码检测运行时间。
1    $ time python yourprogram.py
2    
3    real    0m1.028s
4    user    0m0.001s
5    sys     0m0.003s
上面三个输入变量的意义在文章 stackoverflow article 中有详细介绍。简单的说：

    real - 表示实际的程序运行时间
    user - 表示程序在用户态的cpu总时间
    sys - 表示在内核态的cpu总时间

通过sys和user时间的求和，你可以直观的得到系统上没有其他程序运行时你的程序运行所需要的CPU周期。

若sys和user时间之和远远少于real时间，那么你可以猜测你的程序的主要性能问题很可能与IO等待相关。

使用计时上下文管理器进行细粒度计时

我们的下一个技术涉及访问细粒度计时信息的直接代码指令。这是一小段代码，我发现使用专门的计时测量是非常重要的：

timer.py
01    import time
02    
03    class Timer(object):
04        def __init__(self, verbose=False):
05            self.verbose = verbose
06    
07        def __enter__(self):
08            self.start = time.time()
09            return self
10    
11        def __exit__(self, *args):
12            self.end = time.time()
13            self.secs = self.end - self.start
14            self.msecs = self.secs * 1000  # millisecs
15            if self.verbose:
16                print 'elapsed time: %f ms' % self.msecs

为了使用它，你需要用Python的with关键字和Timer上下文管理器包装想要计时的代码块。它将会在你的代码块开始执行的时候启动计时器，在你的代码块结束的时候停止计时器。

这是一个使用上述代码片段的例子：
01    from timer import Timer
02    from redis import Redis
03    rdb = Redis()
04    
05    with Timer() as t:
06        rdb.lpush("foo", "bar")
07    print "=> elasped lpush: %s s" % t.secs
08    
09    with Timer as t:
10        rdb.lpop("foo")
11    print "=> elasped lpop: %s s" % t.secs

我经常将这些计时器的输出记录到文件中，这样就可以观察我的程序的性能如何随着时间进化。

使用分析器逐行统计时间和执行频率

Robert Kern有一个称作line_profiler的不错的项目，我经常使用它查看我的脚步中每行代码多快多频繁的被执行。

想要使用它，你需要通过pip安装该python包：
1    $ pip install line_profiler

一旦安装完成，你将会使用一个称做“line_profiler”的新模组和一个“kernprof.py”可执行脚本。

想要使用该工具，首先修改你的源代码，在想要测量的函数上装饰@profile装饰器。不要担心，你不需要导入任何模组。kernprof.py脚本将会在执行的时候将它自动地注入到你的脚步的运行时。

primes.py
01    @profile
02    def primes(n):
03        if n==2:
04            return [2]
05        elif n<2:
06            return []
07        s=range(3,n+1,2)
08        mroot = n ** 0.5
09        half=(n+1)/2-1
10        i=0
11        m=3
12        while m <= mroot:
13            if s[i]:
14                j=(m*m-3)/2
15                s[j]=0
16                while j
17                    s[j]=0
18                    j+=m
19            i=i+1
20            m=2*i+3
21        return [2]+[x for x in s if x]
22    primes(100)
一旦你已经设置好了@profile装饰器，使用kernprof.py执行你的脚步。
1    $ kernprof.py -l -v fib.py
-l选项通知kernprof注入@profile装饰器到你的脚步的内建函数，-v选项通知kernprof在脚本执行完毕的时候显示计时信息。上述脚本的输出看起来像这样：
01    Wrote profile results to primes.py.lprof
02    Timer unit: 1e-06 s
03    
04    File: primes.py
05    Function: primes at line 2
06    Total time: 0.00019 s
07    
08    Line #      Hits         Time  Per Hit   % Time  Line Contents
09    ==============================================================
10         2                                           @profile
11         3                                           def primes(n):
12         4         1            2      2.0      1.1      if n==2:
13         5                                                   return [2]
14         6         1            1      1.0      0.5      elif n<2:
15         7                                                   return []
16         8         1            4      4.0      2.1      s=range(3,n+1,2)
17         9         1           10     10.0      5.3      mroot = n ** 0.5
18        10         1            2      2.0      1.1      half=(n+1)/2-1
19        11         1            1      1.0      0.5      i=0
20        12         1            1      1.0      0.5      m=3
21        13         5            7      1.4      3.7      while m <= mroot:
22        14         4            4      1.0      2.1          if s[i]:
23        15         3            4      1.3      2.1              j=(m*m-3)/2
24        16         3            4      1.3      2.1              s[j]=0
25        17        31           31      1.0     16.3              while j
26        18        28           28      1.0     14.7                  s[j]=0
27        19        28           29      1.0     15.3                  j+=m
28        20         4            4      1.0      2.1          i=i+1
29        21         4            4      1.0      2.1          m=2*i+3
30        22        50           54      1.1     28.4      return [2]+[x for x in s if x]

寻找具有高Hits值或高Time值的行。这些就是可以通过优化带来最大改善的地方。

程序使用了多少内存？

现在我们对计时有了较好的理解，那么让我们继续弄清楚程序使用了多少内存。我们很幸运，Fabian Pedregosa模仿Robert Kern的line_profiler实现了一个不错的内存分析器。

首先使用pip安装:
1    $ pip install -U memory_profiler
2    $ pip install psutil

（这里建议安装psutil包，因为它可以大大改善memory_profiler的性能）。

就像line_profiler，memory_profiler也需要在感兴趣的函数上面装饰@profile装饰器：
1    @profile
2    def primes(n):
3        ...
4        ...
想要观察你的函数使用了多少内存，像下面这样执行：
1    $ python -m memory_profiler primes.py
一旦程序退出，你将会看到看起来像这样的输出：
01    Filename: primes.py
02    
03    Line #    Mem usage  Increment   Line Contents
04    ==============================================
05         2                           @profile
06         3    7.9219 MB  0.0000 MB   def primes(n):
07         4    7.9219 MB  0.0000 MB       if n==2:
08         5                                   return [2]
09         6    7.9219 MB  0.0000 MB       elif n<2:
10         7                                   return []
11         8    7.9219 MB  0.0000 MB       s=range(3,n+1,2)
12         9    7.9258 MB  0.0039 MB       mroot = n ** 0.5
13        10    7.9258 MB  0.0000 MB       half=(n+1)/2-1
14        11    7.9258 MB  0.0000 MB       i=0
15        12    7.9258 MB  0.0000 MB       m=3
16        13    7.9297 MB  0.0039 MB       while m <= mroot:
17        14    7.9297 MB  0.0000 MB           if s[i]:
18        15    7.9297 MB  0.0000 MB               j=(m*m-3)/2
19        16    7.9258 MB -0.0039 MB               s[j]=0
20        17    7.9297 MB  0.0039 MB               while j
21        18    7.9297 MB  0.0000 MB                   s[j]=0
22        19    7.9297 MB  0.0000 MB                   j+=m
23        20    7.9297 MB  0.0000 MB           i=i+1
24        21    7.9297 MB  0.0000 MB           m=2*i+3
25        22    7.9297 MB  0.0000 MB       return [2]+[x for x in s if x]

line_profiler和memory_profiler的IPython快捷方式

memory_profiler和line_profiler有一个鲜为人知的小窍门，两者都有在IPython中的快捷命令。你需要做的就是在IPython会话中输入以下内容：
1    %load_ext memory_profiler
2    %load_ext line_profiler

在这样做的时候你需要访问魔法命令%lprun和%mprun，它们的行为类似于他们的命令行形式。主要区别是你不需要使用@profiledecorator来修饰你要分析的函数。只需要在IPython会话中像先前一样直接运行分析：
1    In [1]: from primes import primes
2    In [2]: %mprun -f primes primes(1000)
3    In [3]: %lprun -f primes primes(1000)

这样可以节省你很多时间和精力，因为你的源代码不需要为使用这些分析命令而进行修改。

内存泄漏在哪里？

cPython解释器使用引用计数做为记录内存使用的主要方法。这意味着每个对象包含一个计数器，当某处对该对象的引用被存储时计数器增加，当引用被删除时计数器递减。当计数器到达零时，cPython解释器就知道该对象不再被使用，所以删除对象，释放占用的内存。

如果程序中不再被使用的对象的引用一直被占有，那么就经常发生内存泄漏。

查找这种“内存泄漏”最快的方式是使用Marius Gedminas编写的objgraph，这是一个极好的工具。该工具允许你查看内存中对象的数量，定位含有该对象的引用的所有代码的位置。

一开始，首先安装objgraph:
1    pip install objgraph
一旦你已经安装了这个工具，在你的代码中插入一行声明调用调试器：
1    import pdb; pdb.set_trace()
最普遍的对象是哪些？

在运行的时候，你可以通过执行下述指令查看程序中前20个最普遍的对象：
01    (pdb) import objgraph
02    (pdb) objgraph.show_most_common_types()
03    
04    MyBigFatObject             20000
05    tuple                      16938
06    function                   4310
07    dict                       2790
08    wrapper_descriptor         1181
09    builtin_function_or_method 934
10    weakref                    764
11    list                       634
12    method_descriptor          507
13    getset_descriptor          451
14    type                       439
哪些对象已经被添加或删除？

我们也可以查看两个时间点之间那些对象已经被添加或删除：
01    (pdb) import objgraph
02    (pdb) objgraph.show_growth()
03    .
04    .
05    .
06    (pdb) objgraph.show_growth()   # this only shows objects that has been added or deleted since last show_growth() call
07    
08    traceback                4        +2
09    KeyboardInterrupt        1        +1
10    frame                   24        +1
11    list                   667        +1
12    tuple                16969        +1
谁引用着泄漏的对象？

继续，你还可以查看哪里包含给定对象的引用。让我们以下述简单的程序做为一个例子：
1    x = [1]
2    y = [x, [x], {"a":x}]
3    import pdb; pdb.set_trace()
想要看看哪里包含变量x的引用，执行objgraph.show_backref()函数：
1    (pdb) import objgraph
2    (pdb) objgraph.show_backref([x], filename="/tmp/backrefs.png")


该命令的输出应该是一副PNG图像，保存在/tmp/backrefs.png，它看起来是像这样：


最下面有红字的盒子是我们感兴趣的对象。我们可以看到，它被符号x引用了一次，被列表y引用了三次。如果是x引起了一个内存泄漏，我们可以使用这个方法，通过跟踪它的所有引用，来检查为什么它没有自动的被释放。

回顾一下，objgraph 使我们可以：

    显示占据python程序内存的头N个对象
    显示一段时间以后哪些对象被删除活增加了
    在我们的脚本中显示某个给定对象的所有引用

努力与精度

在本帖中，我给你显示了怎样用几个工具来分析python程序的性能。通过这些工具与技术的武装，你可以获得所有需要的信息，来跟踪一个python程序中大多数的内存泄漏，以及识别出其速度瓶颈。

对许多其他观点来说，运行一次性能分析就意味着在努力目标与事实精度之间做出平衡。如果感到困惑，那么就实现能适应你目前需求的最简单的解决方案。
参考

    stack overflow - time explained（堆栈溢出 - 时间解释）
    line_profiler（线性分析器）
    memory_profiler（内存分析器）
    objgraph（对象图）