用profile协助程序性能优化

python] 用profile协助程序性能优化

       上帝说：“选择了脚本，就不要考虑性能。”我是很支持这句话的，使用脚本要的就是开发速度、良好的扩展性以及可维护性。可惜到了最后，我们的程序难免会运行得太慢，我们的客户不能忍受，这时候，我们就不得不考虑对代码的性能进行优化了。

 

       程序运行慢的原因有很多，比如存在太多的劣化代码（如在程序中存在大量的“.”操作符），但真正的原因往往是比较是一两段设计并不那么良好的不起眼的程序，比如对一序列元素进行自定义的类型转换等。因为程序性能影响是符合80／20法则的，即20%的代码的运行时间占用了80%的总运行时间（实际上，比例要夸张的多，通常是几十行代码占用了95%以上的运行时间），靠经验就很难找出造成性能瓶颈的代码了。这时候，我们需要一个工具——profile！最近我手上的项目也在一些关键的地方遇到了性能问题，那时已经接近项目完工日期，幸好因为平时的代码模块化程度比较高，所以通过profile分析相关的独立模块，基本上解决了性能问题。通过这件事，让我下决心写一篇关于profile的文章，分享一下profile的使用心得。

 

初识profile

      profile是python的标准库。可以统计程序里每一个函数的运行时间，并且提供了多样化的报表。使用profile来分析一个程序很简单，举例说如果有一个程序如下：

def foo():        sum = 0        for i in range(100):               sum += i        return sum   if __name__ == "__main__":        foo()

现在要用profile分析这个程序，很简单，把if程序块改为如下：

if __name__ == "__main__":        import profile        profile.run("foo()")

我们仅仅是import了profile这个模块，然后以程序的入口函数名为参数调用了profile.run这个函数，程序运行的输出如下：

5 function calls in 0.143 CPU seconds      Ordered by: standard name      ncalls tottime percall cumtime percall filename:lineno(function)         1    0.000    0.000    0.000    0.000 :0(range)         1    0.143    0.143    0.143    0.143 :0(setprofile)         1    0.000    0.000    0.000    0.000 <string>:1(?)         1    0.000    0.000    0.000    0.000 prof1.py:1(foo)         1    0.000    0.000    0.143    0.143 profile:0(foo())         0    0.000             0.000          profile:0(profiler)

上图显示了prof1.py里函数调用的情况，根据图表我们可以清楚地看到foo()函数占用了100%的运行时间，foo()函数是这个程序里名至实归的热点。

       除了用这种方式，profile还可以直接用python解释器调用profile模块来剖分py程序，如在命令行界面输入如下命令：

python -m profile prof1.py

产生的输出跟直接修改脚本调用profile.run()函数有一样的功效。

       profile的统计结果分为ncalls, tottime, percall, cumtime, percall, filename:lineno(function)等若干列：

ncalls	函数的被调用次数
tottime	函数总计运行时间，除去函数中调用的函数运行时间
percall	函数运行一次的平均时间，等于tottime/ncalls
cumtime	函数总计运行时间，含调用的函数运行时间
percall	函数运行一次的平均时间，等于cumtime/ncalls
filename:lineno(function)	函数所在的文件名，函数的行号，函数名

 

       通常情况下，profile的输出都直接输出到命令行，而且默认是按照文件名排序输出的。这就给我们造成了障碍，我们有时候希望能够把输出保存到文件，并且能够以各种形式来查看结果。profile简单地支持了一些需求，我们可以在profile.run()函数里再提供一个实参，就是保存输出的文件名；同样的，在命令行参数里，我们也可以加多一个参数，用来保存profile的输出。

 

用pstats自定义报表

       profile解决了我们的一个需求，还有一个需求：以多种形式查看输出，我们可以通过profile的另一个类Stats来解决。在这里我们需要引入一个模块pstats，它定义了一个类Stats，Stats的构造函数接受一个参数——就是profile的输出文件的文件名。Stats提供了对profile输出结果进行排序、输出控制等功能，如我们把前文的程序改为如下：

# … 略 if __name__ == "__main__":        import profile        profile.run("foo()", "prof.txt")        import pstats        p = pstats.Stats("prof.txt")        p.sort_stats("time").print_stats()

引入pstats之后，将profile的输出按函数占用的时间排序，输出如下：

Sun Jan 14 00:03:12 2007    prof.txt            5 function calls in 0.002 CPU seconds      Ordered by: internal time      ncalls tottime percall cumtime percall filename:lineno(function)         1    0.002    0.002    0.002    0.002 :0(setprofile)         1    0.000    0.000    0.002    0.002 profile:0(foo())         1    0.000    0.000    0.000    0.000 G:/prof1.py:1(foo)         1    0.000    0.000    0.000    0.000 <string>:1(?)         1    0.000    0.000    0.000    0.000 :0(range)         0    0.000             0.000          profile:0(profiler)

Stats有若干个函数，这些函数组合能给我们输出不同的profile报表，功能非常强大。下面简单地介绍一下这些函数：

strip_dirs()	用以除去文件名前名的路径信息。
add(filename,[…])	把profile的输出文件加入Stats实例中统计
dump_stats(filename)	把Stats的统计结果保存到文件
sort_stats(key,[…])	最重要的一个函数，用以排序profile的输出
reverse_order()	把Stats实例里的数据反序重排
print_stats([restriction,…])	把Stats报表输出到stdout
print_callers([restriction,…])	输出调用了指定的函数的函数的相关信息
print_callees([restriction,…])	输出指定的函数调用过的函数的相关信息

这里最重要的函数就是sort_stats和print_stats，通过这两个函数我们几乎可以用适当的形式浏览所有的信息了，下面来详细介绍一下。

sort_stats()接受一个或者多个字符串参数，如”time”、”name”等，表明要根据哪一列来排序，这相当有用，例如我们可以通过用time为key来排序得知最消耗时间的函数，也可以通过cumtime来排序，获知总消耗时间最多的函数，这样我们优化的时候就有了针对性，也就事半功倍了。sort_stats可接受的参数如下：

‘ncalls’	被调用次数
‘cumulative’	函数运行的总时间
‘file’	文件名
‘module’	文件名
‘pcalls’	简单调用统计（兼容旧版，未统计递归调用）
‘line’	行号
‘name’	函数名
‘nfl’	Name/file/line
‘stdname’	标准函数名
‘time’	函数内部运行时间（不计调用子函数的时间）

       另一个相当重要的函数就是print_stats——用以根据最后一次调用sort_stats之后得到的报表。print_stats有多个可选参数，用以筛选输出的数据；print_stats的参数可以是数字也可以是perl风格的正则表达式，相关的内容通过其它渠道了解，这里就不详述啦，仅举三个例子：

print_stats(“.1”, “foo:”)

这个语句表示将stats里的内容取前面的10%，然后再将包含”foo:”这个字符串的结果输出。

print_stats(“foo:”,”.1”)

这个语句表示将stats里的包含”foo:”字符串的内容的前10%输出。

print_stats(10)

这个语句表示将stats里前10条数据输出。

       实际上，profile输出结果的时候相当于这样调用了Stats的函数：

p.strip_dirs().sort_stats(-1).print_stats()

其中sort_stats函数的参数是-1，这也是为了与旧版本兼容而保留的。sort_stats可以接受-1,0,1,2之一，这四个数分别对应”stdname”, “calls”, “time”和”cumulative”；但如果你使用了数字为参数，那么pstats只按照第一个参数进行排序，其它参数将被忽略。