2.6 使用模块cProfile
cProfile是标准库内置的一个剖析工具。它通过潜入CPython虚拟机来测量每个函数的执行时间。这引入了更大的开销，但提供的信息也更多。在有些情况下，这些额外的信息可能让你对代码有意外的洞见。
cProfile是标准库内置的两个剖析器之一，另一个是profile。profile是纯Python剖析器，历史更悠久，但速度更慢；cProfile与profile具有相同的接口，并且是用C语言编写的，因此开销更低。如果你对这些库的历史感兴趣，可参阅Armin Rigo于2005年撰写的文章（参见Bitly公司官网cProfile Request页面），该文呼吁将cProfile纳入标准库中。
对剖析来说，一种不错的做法是，在剖析前就代码各部分的速度做出假设。作者喜欢将代码打印出来并进行标注。预先做出假设后，你将发现有些假设非常离谱，进而加深对某些编码风格的认识。
警告：不要因为直觉会出错，就避免在剖析中依靠直觉。剖析前做出假设绝对是值得的，因为它可以帮助你学会如何找出代码中运行缓慢的部分。但是，你必须用证据来证明你的假设。
务必以测量结果为导向，并首先进行粗糙的剖析，确保将劲用对了地方。你可能巧妙地优化了一段代码，但几小时或几天后却发现自己忽视了进程中速度最慢的部分，根本没有解决真正的问题。没有什么比这更令人羞愧的了。
我们先假设函数calculate_z_serial_purepython是速度最慢的代码部分。在这个函数中，我们执行了大量的解引用操作和基本算术运算，还大量地调用了函数abs。这些很可能消耗大量的CPU资源。
这里将使用模块cProfile来运行代码的一个版本。输出虽然简单，但可以帮助我们确定该对哪部分代码做进一步分析。
标志-s cumulative让cProfile根据占用的累计时间对函数进行排序，这让我们知道哪部分代码的运行速度最慢。cProfile的输出被直接显示到屏幕上，它们位于print语句输出的后面：
$ python -m cProfile -s cumulative julia1_nopil.py
...
Length of x: 1000
Total elements: 1000000
calculate_z_serial_purepython took 11.498265266418457 seconds
36221995 function calls in 12.234 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 12.234 12.234 {built-in method builtins.exec}
1 0.038 0.038 12.234 12.234 julia1_nopil.py:1(<module>)
1 0.571 0.571 12.197 12.197 julia1_nopil.py:23
(calc_pure_python)
1 8.369 8.369 11.498 11.498 julia1_nopil.py:9
(calculate_z_serial_purepython)
34219980 3.129 0.000 3.129 0.000 {built-in method builtins.abs}
2002000 0.121 0.000 0.121 0.000 {method 'append' of 'list' objects}
1 0.006 0.006 0.006 0.006 {built-in method builtins.sum}
3 0.000 0.000 0.000 0.000 {built-in method builtins.print}
2 0.000 0.000 0.000 0.000 {built-in method time.time}
4 0.000 0.000 0.000 0.000 {built-in method builtins.len}
1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
通过对累计时间排序，我们能够知道执行时间主要花在什么地方。上述结果表明，在仅仅12 s多点的时间（其中包括cProfile的开销）内，发生了36 221 995次函数调用。而以前，代码的执行时间大约8 s，换句话说，为测量每个函数的执行时间，增加了4 s的开销。
从上述输出可知，代码入口（julia1_nopil.py的第1行）花费的时间为12 s。这行代码位于主函数中，它调用calc_pure_python。ncalls为1，表明这行代码只执行了一次。
在calc_pure_python内部，调用calculate_z_serial_purepython的代码耗费了11 s。函数calc_pure_python和calculate_z_serial_purepython都只调用了一次，由此可以推断，在函数calc_pure_python中，除调用CPU密集型函数calculate_z_serial_ purepython外的其他代码耗费的时间大约为1 s。但是，仅使用cProfile无法推断出这些时间是函数中的哪些代码消耗的。
在函数calculate_z_serial_purepython中，花在非函数调用代码上的时间为8 s。这个函数调用了函数abs 34 219 980次，总共花费了3 s；它还调用了其他一些开销不高的函数。
abs调用的情况如何呢？输出指出了在calculate_z_serial_purepython中每次调用abs花费的时间。虽然每次调用的开销微不足道（显示的结果为0.000 s），但34 219 980次调用花费的总时间为3 s。我们无法预测abs到底将被调用多少次，因为朱利亚函数具有不可预测性，这也是人们对它感兴趣的原因所在。
我们只能说它至少会被调用100万次，因为我们要计算1000像素×1000像素的值；它最多会被调用3亿次，因为我们要计算100万像素的值，而计算每个像素时最多迭代300次。上述输出表明，调用了大约3400万次，这意味着需要迭代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项（调用次数为1 000 000 × 2），这些元素是由1000个x坐标和1000个y坐标的列表创建的，因此需要追加总共2 002 000次调用。
需要注意的是，cProfile的输出并不是按父函数排序的，它总结了被执行的代码块中所有函数的开销。使用cProfile很难搞明白每行代码的情况，因为它只提供了有关函数调用的剖析信息，而没有提供函数中各行代码的剖析信息。
在函数calculate_z_serial_purepython中，我们可获悉有关函数abs的信息，这个函数总共消耗了大约3.1 s。我们还知道，calculate_z_serial_purepython总共消耗了大约11.4 s。
上述剖析输出的最后一行包含字样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]: <pstats.Stats at 0x7f77088edf28>
In [4]: p.print_stats()
Fri Jun 14 17:59:28 2019 profile.stats
36221995 function calls in 12.169 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 12.169 12.169 {built-in method builtins.exec}
1 0.033 0.033 12.169 12.169 julia1_nopil.py:1(<module>)
1 0.576 0.576 12.135 12.135 julia1_nopil.py:23
(calc_pure_python)
1 8.266 8.266 11.429 11.429 julia1_nopil.py:9
(calculate_z_serial_purepython)
34219980 3.163 0.000 3.163 0.000 {built-in method builtins.abs}
2002000 0.123 0.000 0.123 0.000 {method 'append' of 'list' objects}
1 0.006 0.006 0.006 0.006 {built-in method builtins.sum}
3 0.000 0.000 0.000 0.000 {built-in method builtins.print}
4 0.000 0.000 0.000 0.000 {built-in method builtins.len}
2 0.000 0.000 0.000 0.000 {built-in method time.time}
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
{built-in method builtins.exec} <-
julia1_nopil.py:1(<module>) <- 1 0.033 12.169
{built-in method builtins.exec}
julia1_nopil.py:23(calc_pure_python) <- 1 0.576 12.135
:1(<module>)
julia1_nopil.py:9(...) <- 1 8.266 11.429
:23(calc_pure_python)
{built-in method builtins.abs} <- 34219980 3.163 3.163
:9(calculate_z_serial_purepython)
{method 'append' of 'list' objects} <- 2002000 0.123 0.123
:23(calc_pure_python)
{built-in method builtins.sum} <- 1 0.006 0.006
:23(calc_pure_python)
{built-in method builtins.print} <- 3 0.000 0.000
:23(calc_pure_python)
{built-in method builtins.len} <- 2 0.000 0.000
:9(calculate_z_serial_purepython)
2 0.000 0.000
:23(calc_pure_python)
{built-in method time.time} <- 2 0.000 0.000
:23(calc_pure_python)
也可以反过来，显示哪些函数调用了其他函数：
In [6]: p.print_callees()
Ordered by: cumulative time
Function called...
ncalls tottime cumtime
{built-in method builtins.exec} -> 1 0.033 12.169
julia1_nopil.py:1(<module>)
julia1_nopil.py:1(<module>) -> 1 0.576 12.135
julia1_nopil.py:23
(calc_pure_python)
julia1_nopil.py:23(calc_pure_python) -> 1 8.266 11.429
julia1_nopil.py:9
(calculate_z_serial_purepython)
2 0.000 0.000
{built-in method builtins.len}
3 0.000 0.000
{built-in method builtins.print}
1 0.006 0.006
{built-in method builtins.sum}
2 0.000 0.000
{built-in method time.time}
2002000 0.123 0.123
{method 'append' of 'list' objects}
julia1_nopil.py:9(...) -> 34219980 3.163 3.163
{built-in method builtins.abs}
{built-in method builtins.len}
cProfile的输出非常详细，为避免在大量单词中间换行，我们可能需要两个显示器。cProfile是内置的，为你快速找出瓶颈提供了极大的便利。本章后面将介绍line_profiler和memory_profiler，它们可以帮助你深入剖析需要关注的代码行。