平时,我们在写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