平时，我们在写python代码的时候，经常会遇到一个程序执行时间过长而需要优化。
可是在优化过程中，有些人经常靠“经验”猜测哪里有性能问题，然后优化，再次运行，一旦发现速度快了便认为自己的优化生效了。我不建议在写程序的时候，凭感觉来做，根据结果进行总结，我们应该理解原理、分析原因，再去做事情，有凭有据的去断言结果。只有这样，对我们的成长才是最有帮助的。
这篇文章，将介绍几种常用的python性能分析工具。
首先，我们编写一个py程序(test.py)：
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方法，我们可以初步看下改程序的花费时间：
[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 re
cProfile.run('re.compile("foo|bar")')
只需要引入cProfile模块，调用cProfile.run方法就ok了，在程序执行完，会自动输出具体的运行时间等细节。
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 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的执行结果：
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
具体操作如下：
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图片文件，还包含函数被调用的次数和消耗的时间。
具体安装过程如下：
root@localhost [~]# yum install graphviz
#安装pycallgraph
root@localhost [~]# pip install pycallgraph
安装完成后，执行一条简单的语句，便可在程序结束后生成一个png图片。
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工具，基本能满足解决学习、工作中遇到的大部分性能优化问题。
Leave a Reply