平时,我们在写python代码的时候,经常会遇到一个程序执行时间过长而需要优化。


可是在优化过程中,有些人经常靠“经验”猜测哪里有性能问题,然后优化,再次运行,一旦发现速度快了便认为自己的优化生效了。我不建议在写程序的时候,凭感觉来做,根据结果进行总结,我们应该理解原理、分析原因,再去做事情,有凭有据的去断言结果。只有这样,对我们的成长才是最有帮助的。

这篇文章,将介绍几种常用的python性能分析工具。

首先,我们编写一个py程序(test.py):

# -*- coding: utf-8 -*-

import random
import timeit

#递归排序
def sorts(arr):
    if not arr:
        return arr
    prefix, arr = arr[0], arr[1:]
    return sorts([i for i in arr if i < prefix]) + [prefix] + sorts([i for i in arr if i >= prefix])

ls = [random.randint(0, 1000) for i in range(5000)]
print sorts(ls)

#递归累加
def digui_test(n):
    if(n <= 0):
        return n
    return digui_test(n - 1) + n

print digui_test(900)

通过linux自带的time方法,我们可以初步看下改程序的花费时间:

root@localhost [~]# time python test.py
[0, 0, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 2, 2, 2, 2, 2, 2, 2, 3, 3,...省略大量结果内容的显示...]

real    0m0.062s
user    0m0.053s
sys     0m0.006s

real代表实际使用时间,user为用户态使用时间,sys为内核使用时间。
由于程序有时候用到输出、sleep等方法,因此real一般要大于user和sys之和。

1. cProfile

cProfile是Python自带的性能分析的内置模块,同类的模块还有profile和hotshot,不过他们的基本原理方法都差不多,有的是python写的有的是c实现的。

在平时优化中,选用哪种都可以,这里主要讲解下cProfile模块吧。

对于cProfile,官方文档给出了一个精彩的描述:


cProfile模块提供给使用者非常简洁的方法,我们不建议大家读手册。

有多么简单,看看下面文件代码,test2.py:

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

只需要引入cProfile模块,调用cProfile.run方法就ok了,在程序执行完,会自动输出具体的运行时间等细节。

root@localhost [~]# python test2.py
         195 function calls (190 primitive calls) in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 re.py:192(compile)
        1    0.000    0.000    0.000    0.000 re.py:230(_compile)
        1    0.000    0.000    0.000    0.000 sre_compile.py:228(_compile_charset)
        1    0.000    0.000    0.000    0.000 sre_compile.py:256(_optimize_charset)
        1    0.000    0.000    0.000    0.000 sre_compile.py:433(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:546(isstring)
        1    0.000    0.000    0.000    0.000 sre_compile.py:552(_code)
        1    0.000    0.000    0.000    0.000 sre_compile.py:567(compile)
      3/1    0.000    0.000    0.000    0.000 sre_compile.py:64(_compile)
        5    0.000    0.000    0.000    0.000 sre_parse.py:135(__len__)
       12    0.000    0.000    0.000    0.000 sre_parse.py:139(__getitem__)
        7    0.000    0.000    0.000    0.000 sre_parse.py:147(append)
      3/1    0.000    0.000    0.000    0.000 sre_parse.py:149(getwidth)
        1    0.000    0.000    0.000    0.000 sre_parse.py:187(__init__)
       10    0.000    0.000    0.000    0.000 sre_parse.py:191(__next)
        2    0.000    0.000    0.000    0.000 sre_parse.py:204(match)
        8    0.000    0.000    0.000    0.000 sre_parse.py:210(get)
        1    0.000    0.000    0.000    0.000 sre_parse.py:310(_parse_sub)
        2    0.000    0.000    0.000    0.000 sre_parse.py:388(_parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:67(__init__)
        1    0.000    0.000    0.000    0.000 sre_parse.py:686(parse)
        3    0.000    0.000    0.000    0.000 sre_parse.py:90(__init__)
        1    0.000    0.000    0.000    0.000 {_sre.compile}
       15    0.000    0.000    0.000    0.000 {isinstance}
    39/38    0.000    0.000    0.000    0.000 {len}
        2    0.000    0.000    0.000    0.000 {max}
       48    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        5    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
        1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        8    0.000    0.000    0.000    0.000 {min}
        6    0.000    0.000    0.000    0.000 {ord}

有几个字段需要解释一下。
ncalls:函数的被调用次数
tottime:函数总计运行时间,除去函数中调用的函数运行时间
percall:函数运行一次的平均时间,等于tottime/ncalls
cumtime:函数总计运行时间,含调用的函数运行时间(递归方法使用这个时间更为精准)
percall:函数运行一次的平均时间,等于cumtime/ncalls
filename:函数所在的文件名,函数的行号,函数名

上面程序可以看到,cProfile的输出都直接输出到终端命令行中了,而且是按照文件名进行排序的。有时候,我们在分析的时候可能需要不同的形式查看,或者保存到文件中再做分析。cProfile模块已经考虑到了这些需求,提供了非常简单而又适用的支持。

在run方法中加入路径,输出结果将保存到文件中:

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

除了在程序中引入cProfile模块外,还可以直接命令行执行:

python -m cProfile [-o output_file] [-s sort_order] myscript.py

-o 传入保存的文件位置
-s 指明具体的排序方式(具体常见参数及意义见下表)

参数 意义
ncalls 被调用次数
cumulative 函数运行的总时间
file 文件名
line 行数
time 函数内部运行时间(不计调用子函数的时间)

python cProfile指令接受-o参数后,-s参数无效。-s参数仅在没有-o参数存在下才会生效,即直接输出到屏幕。

一般情况下,我比较习惯于先将执行结果保存到文件中,再进行分析,这样的好处是进行不同的排序而不需要再次执行程序。

如果我们直接打开生成的文件,会发现是乱码,我们需要使用pstats来打开,该模块提供了常用方法:

方法名 描述
strip_dirs() 不显示文件名前缀路径
add(filename,[…]) 向统计中加入新的输出文件
dump_stats(filename) 结果保存到文件
sort_stats(key,[…]) 排序
reverse_order() 数据反序重排(初始是由大到小)
print_callers([restriction,…]) 输出到终端
print_callees([restriction,…]) 输出指定函数调用的结果信息

这里,我经常用到的两个函数是sort_stats、print_callers排序和输出。

接下来我们使用cProfile和pstats来分析test.py的执行结果:

#cProfile执行程序,结果存入test1.out中
root@localhost [~]# python -m cProfile  -o test1.out test.py
#import pstats引入模块
#p=pstats.Stats('test1.out')载入结果
#p.sort_stats('time')按照时间排序
#reverse_order()从小到大排序
#print_stats()输出结果
root@localhost [~]# python -c "import pstats; p=pstats.Stats('test1.out'); p.sort_stats('time').reverse_order().print_stats()"

         25955 function calls (15055 primitive calls) in 0.101 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_sha224}
        6    0.000    0.000    0.000    0.000 {globals}
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_sha1}
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_sha384}
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_sha256}
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_sha512}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/__future__.py:74(_Feature)
        1    0.000    0.000    0.004    0.004 /usr/local/lib/python2.7/random.py:91(__init__)
        7    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/__future__.py:75(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/random.py:805(SystemRandom)
        1    0.000    0.000    0.000    0.000 {_hashlib.openssl_md5}
        6    0.000    0.000    0.000    0.000 {getattr}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/random.py:655(WichmannHill)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/timeit.py:105(Timer)
        1    0.000    0.000    0.000    0.000 {math.sqrt}
        1    0.000    0.000    0.000    0.000 {method 'union' of 'set' objects}
        2    0.000    0.000    0.000    0.000 {math.log}
        6    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/hashlib.py:100(__get_openssl_constructor)
        1    0.000    0.000    0.000    0.000 {math.exp}
        1    0.000    0.000    0.000    0.000 {binascii.hexlify}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/random.py:72(Random)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python2.7/__future__.py:48(<module>)
        1    0.000    0.000    0.004    0.004 /usr/local/lib/python2.7/random.py:100(seed)
        1    0.000    0.000    0.000    0.000 {range}
     5000    0.001    0.000    0.001    0.000 {method 'random' of '_random.Random' objects}
        1    0.001    0.001    0.001    0.001 /usr/local/lib/python2.7/timeit.py:53(<module>)
        1    0.001    0.001    0.001    0.001 {function seed at 0x7fefa2f5be60}
        1    0.001    0.001    0.012    0.012 /usr/local/lib/python2.7/random.py:40(<module>)
    901/1    0.002    0.000    0.002    0.002 test.py:17(digui_test)
     5000    0.003    0.000    0.026    0.000 /usr/local/lib/python2.7/random.py:238(randint)
        1    0.004    0.004    0.004    0.004 {posix.urandom}
        1    0.007    0.007    0.007    0.007 /usr/local/lib/python2.7/hashlib.py:56(<module>)
        1    0.009    0.009    0.101    0.101 test.py:3(<module>)
     5000    0.023    0.000    0.023    0.000 /usr/local/lib/python2.7/random.py:175(randrange)
  10001/1    0.050    0.000    0.050    0.050 test.py:7(sorts)

由此我们可以看到,sorts方法最为耗时。

2. gprof2dot

由于cProfile模块的输出结果为文本内容,有时候观察起来不是很方便,因此gprof2dot应运而生,只需要将cProfile生成的结果传给gprof2dot,它便可以进行数据处理生成可视化结果。

gprof2dot最大的特点是不需要安装,只需要下载一个py文件即可执行,不过gprof2dot需要graphviz源。

gprof2dot模块下载地址,若google无法访问,可以从我这里下载,地址如下:

http://static.ranshy.com/code/gprof2dot.py

具体操作如下:

#下载所需依赖graphviz
root@localhost [~]# yum install graphviz
#下载gprof2dot
root@localhost [~]# wget http://gprof2dot.jrfonseca.googlecode.com/git/gprof2dot.py
#加入可执行权限
root@localhost [~]# chmod 744 ./gprof2dot.py
#测试
root@localhost [~]# ./gprof2dot.py -f pstats test.out | dot -Tpng -o gprof2dot.png
root@localhost [~]# ls -l
-rw-r--r-- 1 root root    79918 Sep 21 21:01 gprof2dot.png

执行完成后,会发现生成了一个gprof2dot.png。

如图所示,这里详细地记录了所有调用细节,包括基础模块的引用细节,图片里面没有写明具体的执行时间。但是不妨碍我们分析,因为每一处都包含了代码行数、时间百分比

最上面是文件起始位置,test总共运行时间100%,自身耗时43.94%(主要是屏幕输出等耗时),调用其它程序执行时间为56.06%。其它程序又包括:
randint函数5000次
timeit module引用
sorts函数调用(可以看到有个自身箭头指向,并标注2,说明该代码为递归,且每次产生两个新的递归)
randommodule模块引用
digui_test方法调用,901次,为单次递归

通过此图,我们可以很清楚地分析出来,总程序在终端(屏幕输出)耗时较多为50%左右,逻辑执行sorts耗时较多为29.78%。

3. pycallgraph

pycallgraph是一个能够为python程序创建调用图像的python模块。它生成一个展示一个模块的函数调用以及他们对其它函数的调用的PNG图片文件,还包含函数被调用的次数和消耗的时间。

具体安装过程如下:

#下载所需依赖graphviz
root@localhost [~]# yum install graphviz
#安装pycallgraph
root@localhost [~]# pip install pycallgraph

安装完成后,执行一条简单的语句,便可在程序结束后生成一个png图片。

#后面是需要运行的py文件
root@localhost [~]# pycallgraph graphviz -- ./test.py
#执行完成后,会生成一个pycallgraph.png文件
root@localhost [~]# ls -l
-rw-r--r-- 1 root root    19685 Sep 21 21:01 pycallgraph.png

该图片如下,我们可以看到最上面是开始执行时的main,然后有一个model的引用,下面两个分支digui_test和sorts,这两个分支循环调用次数也有标识。里面内方框,写明了每个代码块调用的总共时间。

个人觉得生成的图片质量不怎么高,调用情况说明不是非常详细。

4. 总结

一共介绍了三种常用的性能分析工具,这里进行一些简单的总结:

cProfile gprof2dot pycallgraph
性能分析 准确 准确 准确
分析结果 详细 详细 简单
安装 不需要安装 下载一个文件 需要安装
可视化 不支持 图片 图片但模糊
依赖 无任何依赖 依赖cProfile、graphviz 依赖graphviz

我个人认为,只要我们对python有相对深入的了解和认知,一般情况下我们使用cProfile就可以解决我们的大部分问题。再配合使用gprof2dot工具,基本能满足解决学习、工作中遇到的大部分性能优化问题。