python cprofile_《Python高性能编程》——2.6 使用cProfile模块

本节书摘来自异步社区《Python高性能编程》一书中的第2章，第2.6节，作者[美] 戈雷利克 (Micha Gorelick)，胡世杰，徐旭彬 译，更多章节内容可以访问云栖社区“异步社区”公众号查看。

2.6　使用cProfile模块

cProfile是一个标准库内建的分析工具。它钩入CPython的虚拟机来测量其每一个函数运行所花费的时间。这一技术会引入一个巨大的开销，但你会获得更多的信息。有时这些额外的信息会给你的代码带来令人惊讶的发现。

cProfile是标准库内建的三个分析工具之一，另外两个是hotshot和profile。hotshot还处于实验阶段，profile则是原始的纯Python分析器。cProfile具有跟profile一样的接口，且是默认的分析工具。如果你对这些库的历史感兴趣，你可以去看一下Armin Rigo在2005年要求将cProfile包含进标准库的请求(http://bit.ly/cProfile_request)。

分析工作的一个好的实践是在开始分析之前先对你的代码各部分的运行速度进行假设。Ian喜欢将有问题的代码打印出来并加以标注。提前生成一个假设意味着有可能测出你错的有多离谱(而且真的会测出！)并提升你对于某种编程风格的直觉。

警告

永远不要忽视靠直觉进行的性能分析(虽然你一定会犯错！)。在分析前先进行假设是绝对值得的，因为这样可以帮助你学习如何定位你代码中可能有问题的地方，而且你应该始终用证据来证明你的选择。

始终基于你的测量结果，用一些既快且脏的分析手段确保你正在分析正确的地方。没有什么比在聪明地优化了一段代码之后(可能过了几小时或几天)才意识到你其实漏掉了进程最慢的部分且根本没有找到真正的问题所在更令人羞愧的了。

那么我们的假设是什么呢？我们知道calculate_z_serial_purepython可能是代码最慢的部分。我们在那个函数里做了大量的解引用并多次调用基本的算术操作和abs函数。这些可能都是耗CPU资源的大户。

这里，我们用cProfile模块运行我们的代码的一个变种。其输出是格式化的，方便我们搞清去哪里做进一步分析。

-s cumulative开关告诉cProfile对每个函数累计花费的时间进行排序，这能让我们看到代码最慢的部分。cProfile会将输出直接打印到屏幕：

$ python -m cProfile -s cumulative julia1_nopil.py

...

36221992 function calls in 19.664 seconds

Ordered by: cumulative time

Ncalls tottime percall cumtime percall filename:lineno(function)

1 0.034 0.034 19.664 19.664 julia1_nopil.py:1()

1 0.843 0.843 19.630 19.630 julia1_nopil.py:23

(calc_pure_python)

1 14.121 14.121 18.627 18.627 julia1_nopil.py:9

(calculate_z_serial_purepython)

34219980 4.487 0.000 4.487 0.000 {abs}

2002000 0.150 0.000 0.150 0.000 {method 'append' of 'list' objects}

1 0.019 0.019 0.019 0.019 {range}

1 0.010 0.010 0.010 0.010 {sum}

2 0.000 0.000 0.000 0.000 {time.time}

4 0.000 0.000 0.000 0.000 {len}

1 0.000 0.000 0.000 0.000 {method 'disable' of

'_lsprof.Profiler' objects}

对累计时间排序能告诉我们大部分的执行时间花在了哪。这个结果显示出在仅仅19秒的时间里一共发生了36 221 992次函数调用(这个时间包括了使用cProfile的开销)。之前我们的代码需要13秒执行时间——为了测量每个函数执行所花费的时间，我们增加了一个5秒的惩罚。

我们可以看到第一行，julia1_cprofile.py的代码入口点总共花费了19秒。这是通过__main__调用calc_pure_python。ncalls为1,意味着这行仅执行了一次。

在calc_pure_python内部，calculate_z_serial_purepython的调用花费了18.6秒。这两个函数都只执行了一次。我们可以推测出有大约1秒的时间花在了calc_pure_python内部，是调用calculate_z_serial_purepython以外的代码。不过我们用cProfile没法知道是哪些行花掉了这些时间。

在calculate_z_serial_purepython内部，花在(那些没有调用其他函数的)代码行上的时间是14.1秒。该函数调用了34 219 980次abs，总共花了4.4秒，另外还有其他一些不怎么花时间的调用。

那个{abs}是什么东西？这一行测量的是calculate_z_serial_purepython对abs函数的调用。per-call的代价可以忽略(0.000秒)，34219980次调用总共花了4.4秒。我们无法预测会调用多少次abs，因为Julia函数具有不可预测的动态特性(这也是为什么对它的分析如此有趣)。

我们只能说它最少会被调用1 000 000次，因为我们需要计算1000×1000个像素点。它最多会被调用300 000 000次，因为我们对1 000 000个像素点最多进行300次迭代。所以三千四百万次调用仅是最差情况的10%。

如果我们看原始的灰阶图(图2-3)，并在想象中将白色部分挤压进角落，我们可以估算出耗时的白色区域大概占了全图的10%。

接下来的分析输出，{method 'append' of 'list' objects}，表示了对2 002 000个列表项的创建。

问题

为什么是2 002 000个项目？在你读下去之前，先思考一下总共需要创建多少个项目。

2 002 000个列表项的创建发生在calc_pure_python的设置阶段。

列表zs和cs分别有1000×1000个项目，而它们是根据1000个x坐标和1000个y坐标创建的。所以总共要调用2 002 000次append。

需要注意的是cProfile的输出并不以父函数排序，它总结了执行代码块的全部函数。用cProfile很难搞清楚函数内的每一行发生了什么，因为我们只拿到了函数自身调用的分析信息，而不是函数内的每一行。

在calculate_z_serial_purepython内，我们可以对{abs}和{range}进行分析，这两个函数总计花了大约4.5秒。我们知道calculate_z_serial_purepython自身总共花费了18.6秒。

性能分析输出的最后一行提到了lsprof，这是本工具进化到cProfile之前的原始名字，可以忽略。

为了获得对cProfile结果的更多控制，我们可以生成一个统计文件然后通过Python进行分析：

$ python -m cProfile -o profile.stats julia1.py

我们可以这样将其调入Python，它会输出跟之前一样的累计时间报告：

In [1]: import pstats

In [2]: p = pstats.Stats("profile.stats")

In [3]: p.sort_stats("cumulative")

Out[3]:

In [4]: p.print_stats()

Tue Jan 7 21:00:56 2014 profile.stats

36221992 function calls in 19.983 seconds

Ordered by: cumulative time

ncalls tottime percall cumtime percall filename:lineno(function)

1 0.033 0.033 19.983 19.983 julia1_nopil.py:1()

1 0.846 0.846 19.950 19.950 julia1_nopil.py:23

(calc_pure_python)

1 13.585 13.585 18.944 18.944 julia1_nopil.py:9

(calculate_z_serial_purepython)

34219980 5.340 0.000 5.340 0.000 {abs}

2002000 0.150 0.000 0.150 0.000 {method 'append' of 'list' objects}

1 0.019 0.019 0.019 0.019 {range}

1 0.010 0.010 0.010 0.010 {sum}

2 0.000 0.000 0.000 0.000 {time.time}

4 0.000 0.000 0.000 0.000 {len}

1 0.000 0.000 0.000 0.000 {method 'disable' of

'_lsprof.Profiler' objects}

为了追溯我们分析的函数，我们可以打印调用者的信息。在下面的两个列表中，我们可以看到calculate_z_serial_purepython是最耗时的函数，且只在一个地方被调用。如果它被多个地方调用，这些列表也许能帮助我们定位到最耗时的父函数：

In [5]: p.print_callers()

Ordered by: cumulative time

Function was called by...

ncalls tottime cumtime

julia1_nopil.py:1()

julia1_nopil.py:23(calc_pure_python)

julia1_nopil.py:1()

julia1_nopil.py:9(calculate_z_serial_purepython)

julia1_nopil.py:23

(calc_pure_python)

{abs}

julia1_nopil.py:9

(calculate_z_serial_purepython)

{method 'append' of 'list' objects}

julia1_nopil.py:23

(calc_pure_python)

{range}

julia1_nopil.py:9

(calculate_z_serial_purepython)

{sum}

julia1_nopil.py:23

(calc_pure_python)

{time.time}

julia1_nopil.py:23

(calc_pure_python)

{len}

julia1_nopil.py:9

(calculate_z_serial_purepython)

2 0.000 0.000

julia1_nopil.py:23

(calc_pure_python)

{method 'disable' of '_lsprof.Profiler' objects}

我们还可以反过来显示哪个函数调用了其他函数：

In [6]: p.print_callees()

Ordered by: cumulative time

Function called...

ncalls tottime cumtime

julia1_nopil.py:1() -> 1 0.846 19.950

julia1_nopil.py:23

(calc_pure_python)

julia1_nopil.py:23(calc_pure_python) -> 1 13.585 18.944

julia1_nopil.py:9

(calculate_z_serial_purepython)

2 0.000 0.000

{len}

2002000 0.150 0.150

{method 'append' of 'list'

objects}

1 0.010 0.010

{sum}

2 0.000 0.000

{time.time}

julia1_nopil.py:9(calculate_z_serial_purepython) -> 34219980 5.340 5.340

{abs}

2 0.000 0.000

{len}

1 0.019 0.019

{range}

{abs} ->

{method 'append' of 'list' objects} ->

{range} ->

{sum} ->

{time.time} ->

{len} ->

{method 'disable' of '_lsprof.Profiler' objects} ->

cProfile输出的信息很多，你需要有一个副屏幕才能避免整字换行。它是内建的用于快速定位瓶颈的便利工具。然后我们在本章后面讨论的line_profiler、heapy和memory_profiler等工具才能帮助你深入定位到需要你加以注意的具体代码行。