Question

根据Ian的观点，Robert Kern的line_profiler是调查Python的CPU密集型性能问题最强大的工具。它可以对函数进行逐行分析，你应该先用cProfile找到需要分析的函数，然后用line_profiler对函数进行分析。

当你修改你的代码时，值得打印出这个工具的输出以及代码的版本，这样你就拥有一个代码变化（无论有没有用）的记录，让你可以随时查阅。当你在进行逐行改变时，不要依赖你的记忆。

输入命令pip install line_profiler来安装line_profiler。

用修饰器（@profile）标记选中的函数。用kernprof.py脚本运行你的代码，被选函数每一行花费的CPU时间以及其他信息就会被记录下来。

　备忘　

需要修改源代码这点比较讨厌，因为额外的修饰器会影响你的单元测试，除非你创建一个伪修饰器——见2.13节中的No-op的@profile修饰器。

运行时参数-l代表逐行分析而不是逐函数分析，-v用于显示输出。没有-v，你会得到一个.lprof的输出文件，回头你可以用line_profiler模块对其进行分析。例2-6中，我们会完整运行一遍我们的CPU密集型函数。

例2-6　运行kernprof逐行分析被修饰函数的CPU开销

$ kernprof -l -v julia1_lineprofiler.py ... Wrote profile results to julia1_lineprofiler.py.lprof Timer unit: 1e-06 s File: julia1_lineprofiler.py Function: calculate_z_serial_purepython at line 9 Total time: 100.81 s Line # Hits Per Hit % Time Line Contents ================================================== 9 @profile 10 def calculate_z_serial_purepython(maxiter, zs, cs): 11 """Calculate output list using Julia update rule""" 12 1 6870.0 0.0 output = [0] * len(zs) 13 1000001 0.8 0.8 for i in range(len(zs)): 14 1000000 0.8 0.8 n = 0 15 1000000 0.8 0.8 z = zs[i] 16 1000000 0.8 0.8 c = cs[i] 17 34219980 1.1 36.2 while abs(z) < 2 and n < maxiter: 18 33219980 1.0 32.6 z = z * z + c 19 33219980 0.8 27.2 n += 1 20 1000000 0.9 0.9 output[i] = n 21 1 4.0 0.0 return output

引入kernprof.py导致了额外的运行时间。本例的calculate_z_serial_purepython花费了100秒，远高于使用print语句的13秒和cProfile的19秒。获得的好处则是我们现在得到了一个函数内部每一行花费时间的分析结果。

%Time列最有用——我们可以看到36%的时间花在了while测试上。不过我们不知道是第一条语句（abs(z) < 2）还是第二条语句（n < maxiter）更花时间。循环内，我们可以看到更新z也颇花时间。甚至n += 1都很贵！每次循环时，Python的动态查询机制都在工作，即使每次循环中我们使用的变量都是同样的类型——在这一点上，编译和类型指定（第7章）可以给我们带来巨大的好处。创建output列表以及第20行上的更新相对整个while循环来说相当便宜。

对while语句更进一步的分析明显就是将两个判断拆开。Python社区中有一些讨论关于是否需要重写.pyc文件中对于一行语句中多个部分的具体信息，但目前还没有一个工具提供比line_profiler更细粒度的分析。

在例2-7中，我们将while语句分拆成多个语句。这一额外的复杂度会增加函数的运行时间，因为我们有了更多行代码需要执行，但它可能可以帮助我们了解这部分代码的开销。

　问题

在你看代码之前，你是否认为我们可以用这种方式了解基本操作的开销？其他因素会不会让分析变得更复杂？

例2-7　将组合式while语句拆成单个语句来记录每一部分的开销

$ kernprof.py -l -v julia1_lineprofiler2.py ... Wrote profile results to julia1_lineprofiler2.py.lprof Timer unit: 1e-06 s File: julia1_lineprofiler2.py Function: calculate_z_serial_purepython at line 9 Total time: 184.739 s Line # Hits Per Hit % Time Line Contents =================================================== 9 @profile 10 def calculate_z_serial_purepython(maxiter, zs, cs): 11 """Calculate output list using Julia update rule""" 12 1 6831.0 0.0 output = [0] * len(zs) 13 1000001 0.8 0.4 for i in range(len(zs)): 14 1000000 0.8 0.4 n = 0 15 1000000 0.9 0.5 z = zs[i] 16 1000000 0.8 0.4 c = cs[i] 17 34219980 0.8 14.9 while True: 18 34219980 1.0 19.0 not_yet_escaped = abs(z) < 2 19 34219980 0.8 15.5 iterations_left = n < maxiter 20 34219980 0.8 15.1 if not_yet_escaped and iterations_left: 21 33219980 1.0 17.5 z = z * z + c 22 33219980 0.9 15.3 n += 1 23 else: 24 1000000 0.8 0.4 break 25 1000000 0.9 0.5 output[i] = n 26 1 5.0 0.0 return output

这个版本花了184秒执行，而之前的仅100秒。其他因素确实让分析变得更复杂。本例中每一条额外语句都执行了34219980次，拖慢了代码。如果不是通过kernprof.py调查了每行的影响，我们可能会在缺乏证据的情况下得出是其他原因导致了变慢的结论。

此时有必要回到之前的timeit技术来测试每个单独表达式的开销：

>>> z = 0+0j # a point in the middle of our image
>>> %timeit abs(z) < 2 # tested inside IPython

10000000 loops, best of 3: 119 ns per loop

>>> n = 1
>>> maxiter = 300
>>> %timeit n < maxiter

10000000 loops, best of 3: 77 ns per loop

从这一简单分析上来看，对n的逻辑测试的速度几乎是abs函数调用的两倍。既然Python语句的评估次序是从左到右且支持短路，那么我们应该将最便宜的测试放在左边。每301次测试就有1次n < maxiter的值为False，这样Python就不必评估and操作符右边的语句了。

在评估前我们永远无法知道abs(z) < 2的值何时为False，而我们之前对复数平面的观察告诉我们300次迭代中大约10%的可能是True。如果我们想要更进一步了解这段代码的时间复杂度，有必要继续进行数值分析。不过在目前的情况下，我们只是想要看看有没有快速提高的机会。

我们可以做一个新的假设声明，“通过交换while语句的次序，我们会获得一个可靠的速度提升。”我们可以用kernprof.py测试这个假设，但是其额外的开销　 可能会给我们的结果带来太多噪声。所以我们用一个之前版本的代码，测试比较while abs(z) < 2 and n < maxiter:和while n < maxiter and abs(z) < 2:之间的区别。

结果显示出大约0.4秒的稳定提升。这一结果显然很无足轻重且局限性太强，使用另一个更合适的方法（如换用第7章描述的Cython或PyPy）来解决问题会带来更高的收益。

我们对自己的结果有信心，是因为：

我们声明的假设易于测试。

我们对代码的改动仅局限于假设的测试（永远不要一次测试两件事！）。

我们收集了足够的证据支持我们的结论。

为了保持完整性，我们可以在包含了我们优化的两个主要函数上最后运行一次kernprof.py来确认我们代码整体的复杂度。例2-8交换了第17行while测试的语句，我们可以看到原来占用的36.1%的执行时间现在仅占用35.9%（这一结果在多次运行中稳定存在）。

例2-8　交换while语句的次序提升测试的速度

$ kernprof.py -l -v julia1_lineprofiler3.py
...
Wrote profile results to julia1_lineprofiler3.py.lprof
Timer unit: 1e-06 s

File: julia1_lineprofiler3.py
Function: calculate_z_serial_purepython at line 9
Total time: 99.7097 s

Line #   Hits   PerHit   %Time   Line Contents
==================================================
   9               @profile
  10               def calculate_z_serial_purepython(maxiter,
                                   zs, cs):
  11                 """Calculate output list using
                     Julia update rule"""
  12    1   6831.0   0.0     output = [0] * len(zs)
  13  1000001    0.8   0.8     for i in range(len(zs)):
  14  1000000    0.8   0.8       n = 0
  15  1000000    0.9   0.9       z = zs[i]
  16  1000000    0.8   0.8       c = cs[i]
  17 34219980    1.0  35.9       while n < maxiter and abs(z) < 2:
  18 33219980    1.0  32.0         z = z * z + c
  19 33219980    0.8  27.9         n += 1
  20  1000000    0.9  0.9      output[i] = n
  21  1      5.0  0.0    return output

和预期的一样，我们可以看例2-9的输出中，calculate_z_serial_purepython占用了其父函数97%的时间。创建列表的步骤相对来说无足轻重。

例2-9　逐行测试设置阶段的开销

File: julia1_lineprofiler3.py
Function: calc_pure_python at line 24
Total time: 195.218 s

Line #   Hits   Per Hit   % Time  Line Contents
=================================================
  24                @profile
  25                def calc_pure_python(draw_output,
                             desired_width,
                             max_iterations):
...
  44    1     1.0    0.0   zs = []
  45    1     1.0    0.0   cs = []
  46   1001     1.1    0.0   for ycoord in y:
  47  1001000     1.1    0.5     for xcoord in x:
  48  1000000     1.5    0.8       zs.append(
                            complex(xcoord, ycoord))
  49  1000000     1.6    0.8       cs.append(
                            complex(c_real, c_imag))
  50
  51    1    51.0    0.0    print "Length of x:", len(x)
  52    1    11.0    0.0    print "Total elements:", len(zs)
  53    1     6.0    0.0    start_time = time.time()
  54    1 191031307.0    97.9   output =
                      calculate_z_serial_purepython
                      (max_iterations, zs, cs)
  55    1     4.0    0.0    end_time = time.time()
  56    1     2.0    0.0    secs = end_time - start_time
  57    1    58.0    0.0    print calculate_z_serial_purepython
                      .func_name + " took", secs, "seconds"
  58
                   # this sum is expected for 1000^2 grid...
  59    1   9799.0   0.0   assert sum(output) == 33219980