Introduction to Python performance analysis tools

Introduction to Performance Analysis and Tuning Tools

There will always be a time when you want to improve the execution efficiency of the program, want to see which part takes too long to become a bottleneck, and want to know the memory and CPU usage when the program is running. At this time you will need some methods to perform performance analysis and tuning of the program.

By Context Manager

The context manager can implement a timer by itself. See what was done in the previous introduction to timeit article, and implement the managed function timing by defining the __enter__ and __exit__ methods of the class, similar to:

# timer.py
import time

class Timer(object):
    def __init__(self, verbose=False):
        self.verbose = verbose

    def __enter__(self):
        self.start = time.time()
        return self

    def __exit__(self, *args):
        self.end = time.time()
        self.secs = self.end - self.start
        self.msecs = self.secs * 1000            # 毫秒
        if self.verbose:
            print 'elapsed time: %f ms' % self.msecs

The usage is as follows:

from timer import Timer

with Timer() as t:
    foo()
print "=> foo() spends %s s" % t.secs

By Decorator

However, I think the decorator method is more elegant

import time
from functools import wraps

def timer(function):
    @wraps(function)
    def function_timer(*args, **kwargs):
        t0 = time.time()
        result = function(*args, **kwargs)
        t1 = time.time()
        print ("Total time running %s: %s seconds" %
                (function.func_name, str(t1-t0))
                )
        return result
    return function_timer

It is very simple to use:

@timer
def my_sum(n):
    return sum([i for i in range(n)])

if __name__ == "__main__":
    my_sum(10000000)

Running results:

➜  python profile.py
Total time running my_sum: 0.817697048187 seconds

The system’s own time command

Usage examples are as follows:

➜ time python profile.py
Total time running my_sum: 0.854454040527 seconds
python profile.py  0.79s user 0.18s system 98% cpu 0.977 total

Explanation of the above results: 0.79s CPU time is consumed to execute the script, 0.18 seconds is consumed to execute the kernel function, and the total time is 0.977s.
Among them, total time - (user time + system time) = time consumed in input and output and system execution of other tasks

python timeit module

can be used for benchmarking, and can easily repeat the number of times a program is executed. View program can run multiple blocks. Please refer to the previously written article for details.

cProfile

Just look at the annotated usage examples.

#coding=utf8

def sum_num(max_num):
    total = 0
    for i in range(max_num):
        total += i
    return total


def test():
    total = 0
    for i in range(40000):
        total += i

    t1 = sum_num(100000)
    t2 = sum_num(200000)
    t3 = sum_num(300000)
    t4 = sum_num(400000)
    t5 = sum_num(500000)
    test2()

    return total

def test2():
    total = 0
    for i in range(40000):
        total += i

    t6 = sum_num(600000)
    t7 = sum_num(700000)

    return total


if __name__ == "__main__":
    import cProfile

    # # 直接把分析结果打印到控制台
    # cProfile.run("test()")
    # # 把分析结果保存到文件中
    # cProfile.run("test()", filename="result.out")
    # 增加排序方式
    cProfile.run("test()", filename="result.out", sort="cumulative")

cProfile saves the analysis results to the result.out file, but it is stored in binary form. If you want to view it directly, use the provided pstats to view it.

import pstats

# 创建Stats对象
p = pstats.Stats("result.out")

# strip_dirs(): 去掉无关的路径信息
# sort_stats(): 排序，支持的方式和上述的一致
# print_stats(): 打印分析结果，可以指定打印前几行

# 和直接运行cProfile.run("test()")的结果是一样的
p.strip_dirs().sort_stats(-1).print_stats()

# 按照函数名排序，只打印前3行函数的信息, 参数还可为小数,表示前百分之几的函数信息
p.strip_dirs().sort_stats("name").print_stats(3)

# 按照运行时间和函数名进行排序
p.strip_dirs().sort_stats("cumulative", "name").print_stats(0.5)

# 如果想知道有哪些函数调用了sum_num
p.print_callers(0.5, "sum_num")

# 查看test()函数中调用了哪些函数
p.print_callees("test")

Intercept an output example to see which functions are called by test():

➜  python python profile.py
   Random listing order was used
   List reduced from 6 to 2 due to restriction <&#39;test&#39;>

Function              called...
                          ncalls  tottime  cumtime
profile.py:24(test2)  ->       2    0.061    0.077  profile.py:3(sum_num)
                               1    0.000    0.000  {range}
profile.py:10(test)   ->       5    0.073    0.094  profile.py:3(sum_num)
                               1    0.002    0.079  profile.py:24(test2)
                               1    0.001    0.001  {range}

profile.Profile

cProfile also provides customizable classes for more detailed analysis, see the documentation for details.
The format is like: class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)
The following example is from the official documentation:

import cProfile, pstats, StringIO
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = StringIO.StringIO()
sortby = 'cumulative'
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print s.getvalue()

lineprofiler

lineprofiler是一个对函数进行逐行性能分析的工具，可以参见github项目说明，地址: https://github.com/rkern/line...

示例

#coding=utf8

def sum_num(max_num):
    total = 0
    for i in range(max_num):
        total += i
    return total


@profile                     # 添加@profile 来标注分析哪个函数
def test():
    total = 0
    for i in range(40000):
        total += i

    t1 = sum_num(10000000)
    t2 = sum_num(200000)
    t3 = sum_num(300000)
    t4 = sum_num(400000)
    t5 = sum_num(500000)
    test2()

    return total

def test2():
    total = 0
    for i in range(40000):
        total += i

    t6 = sum_num(600000)
    t7 = sum_num(700000)

    return total

test()

通过 kernprof 命令来注入分析，运行结果如下：

➜ kernprof -l -v profile.py
Wrote profile results to profile.py.lprof
Timer unit: 1e-06 s

Total time: 3.80125 s
File: profile.py
Function: test at line 10

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    10                                           @profile
    11                                           def test():
    12         1            5      5.0      0.0      total = 0
    13     40001        19511      0.5      0.5      for i in range(40000):
    14     40000        19066      0.5      0.5          total += i
    15
    16         1      2974373 2974373.0     78.2      t1 = sum_num(10000000)
    17         1        58702  58702.0      1.5      t2 = sum_num(200000)
    18         1        81170  81170.0      2.1      t3 = sum_num(300000)
    19         1       114901 114901.0      3.0      t4 = sum_num(400000)
    20         1       155261 155261.0      4.1      t5 = sum_num(500000)
    21         1       378257 378257.0     10.0      test2()
    22
    23         1            2      2.0      0.0      return total

hits（执行次数） 和 time（耗时） 值高的地方是有比较大优化空间的地方。

memoryprofiler

类似于"lineprofiler"对基于行分析程序内存使用情况的模块。github 地址：https://github.com/fabianp/me... 。ps:安装 psutil, 会分析的更快。

同样是上面"lineprofiler"中的代码，运行 python -m memory_profiler profile.py 命令生成结果如下:

➜ python -m memory_profiler profile.py
Filename: profile.py

Line #    Mem usage    Increment   Line Contents
================================================
    10   24.473 MiB    0.000 MiB   @profile
    11                             def test():
    12   24.473 MiB    0.000 MiB       total = 0
    13   25.719 MiB    1.246 MiB       for i in range(40000):
    14   25.719 MiB    0.000 MiB           total += i
    15
    16  335.594 MiB  309.875 MiB       t1 = sum_num(10000000)
    17  337.121 MiB    1.527 MiB       t2 = sum_num(200000)
    18  339.410 MiB    2.289 MiB       t3 = sum_num(300000)
    19  342.465 MiB    3.055 MiB       t4 = sum_num(400000)
    20  346.281 MiB    3.816 MiB       t5 = sum_num(500000)
    21  356.203 MiB    9.922 MiB       test2()
    22
    23  356.203 MiB    0.000 MiB       return total