软件开发工具

软件开发工具
- 交互式调试器

In [2]: run ch03/ipython_bug.py调试器的其他使用场景

测试代码的执行时间：%time和%timeit
基本性能分析：%prun和%run -p
逐行分析函数性能

IPython不仅是一种舒适的交互式计算和数据分析环境，同时也非常适合成为一种软件开发环境。在数据分析应用程序中，最重要的事情就是拥有正确的代码。幸运的是，IPython紧密集成并加强了Python内置的pdb调试器。此外，你还希望代码运行能足够快。为此，IPython提供了一些简单易用的代码运行时间及性能分析工具。下面，我将对这些工具做一个详细介绍。

交互式调试器

IPython的调试器增强了pdb，如Tab键自动完成、语法高亮、为异常跟踪的每条信息添加上下文参考等。调试代码的最佳时机之一就是错误刚刚发生那会儿。%debug命令（在发生异常之后马上输入）将会调用那个“事后”调试器，并直接跳转到引发异常的那个栈帧（stack frame）：

In [2]: run ch03/ipython_bug.py

AssertionError Traceback (most recent call last) /home/wesm/book_scripts/ch03/ipython_bug.py in <module>() 13 throws_an_exception() 14 —-> 15 calling_things()

/home/wesm/book_scripts/ch03/ipython_bug.py in calling_things() 11 def calling_things(): 12 works_fine() —-> 13 throws_an_exception() 14 15 calling_things()

/home/wesm/book_scripts/ch03/ipython_bug.py in throws_an_exception() 7 a = 5 8 b = 6 ——> 9 assert(a + b == 10) 10 11 def calling_things():

AssertionError:

In [3]: %debug > /home/wesm/book_scripts/ch03/ipython_bug.py(9)throws_an_exception() 8 b = 6 ——> 9 assert(a + b == 10) 10

ipdb>

在这个调试器中，你可以执行任意Python代码并查看各个栈帧中的一切对象和数据（也就是解释器还“留了条生路”的那些）。默认是从最低级开始的（即错误发生的地方）。输入u（或up）和d（或down）即可在栈跟踪的各级别之间切换：

ipdb> u
> /home/wesm/book_scripts/ch03/ipython_bug.py(13)calling_things()
     12     works_fine()
---> 13     throws_an_exception()
     14

执行%pdb命令可以让IPython在出现异常之后自动调用调试器。很多人都认为这是一个非常实用的功能。

此外，调试器还可以为代码开发工作提供帮助，尤其是当你想要设置断点或对函数/脚本进行单步调试以查看各条语句的执行情况时。实现这个目的的方式有几个。第一，使用带有-d选项的%run命令，这将会在执行脚本文件中的代码之前先打开调试器。必须立即输入s（或step）才能进入脚本：^译注15

In [5]: run -d ch03/ipython_bug.py
Breakpoint 1 at /home/wesm/book_scripts/ch03/ipython_bug.py:1
NOTE: Enter 'c' at the ipdb>  prompt to start your script.
> <string>(1)<module>()
 
ipdb> s
> g:\ipython_bug.py(1)<module>()
1---> 1 def works_fine():
      2     a = 5
      3     b = 6

在此之后，该文件接下来的执行方式就全凭你一句话了。比如说，在上面那个异常中，我们可以在调用works_fine方法的地方设置一个断点，然后输入c（或continue）使脚本一直运行下去直到该断点时为止：

ipdb> b 12
ipdb> c
> /home/wesm/book_scripts/ch03/ipython_bug.py(12)calling_things()
     11 def calling_things():
2--> 12     works_fine()
     13     throws_an_exception()

这时可以单步进入works_fine()或执行works_fine()（输入n（或next）直接执行到下一行^译注16）：

ipdb> n
> /home/wesm/book_scripts/ch03/ipython_bug.py(13)calling_things()
2    12     works_fine()
---> 13     throws_an_exception()
     14

然后，我们单步进入throws_an_exception并前进到发生错误的那一行，查看在此范围内的变量。注意，调试器命令的优先级高于变量名。这时在变量前面加上感叹号（！）即可查看其内容。

ipdb> s
--Call--
> /home/wesm/book_scripts/ch03/ipython_bug.py(6)throws_an_exception()
      5
----> 6 def throws_an_exception():
      7     a = 5
 
ipdb> n
> /home/wesm/book_scripts/ch03/ipython_bug.py(7)throws_an_exception()
      6 def throws_an_exception():
----> 7     a = 5
      8     b = 6
 
ipdb> n
> /home/wesm/book_scripts/ch03/ipython_bug.py(8)throws_an_exception()
      7     a = 5
----> 8     b = 6
      9     assert(a + b == 10)
 
ipdb> n
> /home/wesm/book_scripts/ch03/ipython_bug.py(9)throws_an_exception()
      8     b = 6
----> 9     assert(a + b == 10)
     10
 
ipdb> !a
5
ipdb> !b
6

要想精通这个交互式调试器，必须经过大量的实践才行。表3-4列出了该调试器的全部命令。如果你习惯了使用某款IDE，刚开始用这种终端型调试器的时候可能会觉得有点麻烦，但慢慢就会习惯了。虽然大部分Python IDE都拥有优秀的GUI调试器，但是在IPython中调试程序却往往会带来更高的生产率。

软件开发工具 - 图1

软件开发工具 - 图2

调试器的其他使用场景

除上面提到的之外，还有另外几种调用调试器的手段。第一，使用set_trace这个特别的函数（以pdb.set_trace命名），这差不多可以算作一种“穷人的断点^译注17”。下面这两个方法可能会在你的日常工作中派上用场（你也可以像我一样直接将其添加到IPython配置中）：

def set_trace():
    from IPython.core.debugger import Pdb
    Pdb(color_scheme='Linux').set_trace(sys._getframe().f_back)
 
def debug(f, *args, **kwargs):
    from IPython.core.debugger import Pdb
    pdb = Pdb(color_scheme='Linux')
    return pdb.runcall(f, *args, **kwargs)

第一个函数（set_trace）非常简单。你可以将其放在代码中任何希望停下来查看一番的地方（比如发生异常的地方）：

In [7]: run ch03/ipython_bug.py
> /home/wesm/book_scripts/ch03/ipython_bug.py(16)calling_things()
     15       set_trace()
---> 16       throws_an_exception()
     17

按下c（或continue）仍然会使代码恢复执行，不受任何影响。

另外那个debug函数使你能够直接在任意函数上使用调试器。假设我们写了如下函数：

def f(x, y, z=1):
    tmp = x + y
    return tmp / z

现在想对其进行单步调试。f的正常使用方式应该类似于f(1,2,z=3)这个样子。为了能够单步进入f，将f作为第一个参数传给debug，后面按顺序再跟上各个需要传给f的关键字参数：

In [6]: debug(f, 1, 2, z=3)
> <ipython-input>(2)f()
      1 def f(x, y, z):
----> 2     tmp = x + y
      3     return tmp / z
 
ipdb>

我发现这两个函数虽然简单，但是在日常工作当中却节省了我不少的时间。

此外，这个调试器还可以结合%run使用。通过%run-d执行脚本，你将会直接进入调试器，然后可以设置一些断点并启动脚本：

In [1]: %run -d ch03/ipython_bug.py
Breakpoint 1 at /home/wesm/book_scripts/ch03/ipython_bug.py:1
NOTE: Enter 'c' at the ipdb>  prompt to start your script.
> <string>(1)<module>()
 
ipdb>

如果再加上-b和一个行号，则调试器在启动时就会自动设置一个断点：

In [2]: %run -d -b2 ch03/ipython_bug.py
Breakpoint 1 at /home/wesm/book_scripts/ch03/ipython_bug.py:2
NOTE: Enter 'c' at the ipdb>  prompt to start your script.
> <string>(1)<module>()
 
ipdb> c
> /home/wesm/book_scripts/ch03/ipython_bug.py(2)works_fine()
      1 def works_fine():
1---> 2     a = 5
      3     b = 6
 
ipdb>

测试代码的执行时间：%time和%timeit

对于规模更大、运行时间更长的数据分析应用程序，你可能会希望测试一下各个部分或函数调用或语句的执行时间。你可能会希望了解某个复杂计算过程中到底是哪些函数占用的时间最多。幸运的是，在开发和测试代码的过程中，IPython能够让你轻松得到这些信息。使用内置的time模块及其time.clock和time.time函数手工测试代码执行时间是一件令人烦闷的事情，因为你必须编写许多一模一样的了无生趣的公式化代码：

import time
start = time.time()
for i in range(iterations):
    # 这里放一些待执行的代码
    elapsed_per = (time.time() - start) / iterations

由于这是一个非常常用的功能，所以IPython专门提供了两个魔术函数（%time和%timeit）以便自动完成该过程。%time一次执行一条语句，然后报告总体执行时间。假设我们有一大堆字符串，希望对几个“能够选出具有特殊前缀的字符串”的函数进行比较。下面是一个拥有60万字符串的数组，以及两个不同的“能够选出其中以foo开头的字符串”的方法：

# 一个非常大的字符串数组
strings = ['foo', 'foobar', 'baz', 'qux', 'python', 'Guido Van Rossum'] * 100000
 
method1 = [x for x in strings if x.startswith('foo')]
 
method2 = [x for x in strings if x[:3] == 'foo']

看上去它们的性能表现应该差不多，对吧？我们通过%time来确认一下：

In [561]: %time method1 = [x for x in strings if x.startswith('foo')]
CPU times: user 0.19 s, sys: 0.00 s, total: 0.19 s
Wall time: 0.19 s
 
In [562]: %time method2 = [x for x in strings if x[:3] == 'foo']
CPU times: user 0.09 s, sys: 0.00 s, total: 0.09 s
Wall time: 0.09 s

墙上时间（Wall time）是我们最感兴趣的数字。所以，看上去第一个方法耗费了两倍以上的时间，但这并不是一个非常精确的结果。如果你对相同语句多次执行%time的话，就会发现其结果是会变的。为了得到更为精确的结果，需要使用魔术函数%timeit。对于任意语句，它会自动多次执行以产生一个非常精确的平均执行时间。

In [563]: %timeit [x for x in strings if x.startswith('foo')]
10 loops, best of 3: 159 ms per loop
 
In [564]: %timeit [x for x in strings if x[:3] == 'foo']
10 loops, best of 3: 59.3 ms per loop

这个貌似平淡无奇的例子正好说明了一个事实：我们非常有必要了解Python标准库、NumPy、pandas以及本书中所用到的其他库的性能特点。在大型数据分析应用程序中，这些不起眼的毫秒数是会不断累积的！

对于那些执行时间非常短（甚至是那些微秒（1e-6秒）或纳秒（1e-9秒）级的）的分析语句和函数而言，%timeit是非常有用的。虽然这些时间值小到几乎可以忽略不计，但同样执行100万次一个20微秒的函数，所用的时间要比一个5微秒的多15秒。在上面那个例子中，我们可以直接对那两个字符串运算进行比较以了解其性能特点：

In [565]: x = 'foobar'
 
In [566]: y = 'foo'
 
In [567]: %timeit x.startswith(y)
1000000 loops, best of 3: 267 ns per loop
 
In [568]: %timeit x[:3] == y
10000000 loops, best of 3: 147 ns per loop

基本性能分析：%prun和%run -p

代码的性能分析跟代码执行时间密切相关，只不过它关注的是耗费时间的位置。主要的Python性能分析工具是cProfile模块，它不是专为IPython设计的。cProfile在执行一个程序或代码块时，会记录各函数所耗费的时间。

cProfile一般是在命令行上使用的，它将执行整个程序然后输出各函数的执行时间。假设我们有一个简单的脚本：在一个循环中执行一些线性代数计算（计算一个100×100的矩阵的最大本征值绝对值）。

import numpy as np
from numpy.linalg import eigvals
 
def run_experiment(niter=100):
    K = 100
    results = []
    for _ in xrange(niter):
        mat = np.random.randn(K, K)
        max_eigenvalue = np.abs(eigvals(mat)).max()
        results.append(max_eigenvalue)
    return results
some_results = run_experiment()
print 'Largest one we saw: %s' % np.max(some_results)

如果你还不懂NumPy，暂时先别管，后面会讲的。在命令行中输入下列命令即可通过cProfile启动该脚本：

python -m cProfile cprof_example.py

执行之后，你会发现输出结果是按函数名排序的。这让我们很难发现哪里才是最花时间的地方，因此通常都会再用-s标记指定一个排序规则：

$ python -m cProfile -s cumulative cprof_example.py
Largest one we saw: 11.923204422
     15116 function calls (14927 primitive calls) in 0.720 seconds
 
Ordered by: cumulative time
 
ncalls      tottime       percall  cumtime percall filename:lineno(function)
1       0.001    0.001    0.721    0.721 cprof_example.py:1(<module>)
100     0.003    0.000    0.586    0.006 linalg.py:702(eigvals)
200     0.572    0.003    0.572    0.003 {numpy.linalg.lapack_lite.dgeev}
1       0.002    0.002    0.075    0.075 __init__.py:106(<module>)
100     0.059    0.001    0.059    0.001 {method 'randn')
1       0.000    0.000    0.044    0.044 add_newdocs.py:9(<module>)
2       0.001    0.001    0.037    0.019 __init__.py:1(<module>)
2       0.003    0.002    0.030    0.015 __init__.py:2(<module>)
1       0.000    0.000    0.030    0.030 type_check.py:3(<module>)
1       0.001    0.001    0.021    0.021 __init__.py:15(<module>)
1       0.013    0.013    0.013    0.013 numeric.py:1(<module>)
1       0.000    0.000    0.009    0.009 __init__.py:6(<module>)
1       0.001    0.001    0.008    0.008 __init__.py:45(<module>)
262     0.005    0.000    0.007    0.000 function_base.py:3178(add_newdoc)
100     0.003    0.000    0.005    0.000 linalg.py:162(_assertFinite)
...

这里只给出了输出结果中的前15行。只需查看cumtime列即可发现各函数所耗费的总时间。注意，如果一个函数调用了别的函数，计时器是不会停下来重新计时的。cProfile记录的是各函数调用的起始和结束时间，并依此计算总时间。

除命令行用法之外，cProfile还可以编程的方式分析任意代码块的性能。IPython为此提供了一个方便的接口，即%prun命令和带-p选项的%run。%prun的格式跟cProfile差不多，但它分析的是Python语句而不是整个.py文件：

In [4]: %prun -l 7 -s cumulative run_experiment()
         4203 function calls in 0.643 seconds
 
Ordered by: cumulative time
List reduced from 32 to 7 due to restriction <7>
 
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.643    0.643 <string>:1(<module>)
     1    0.001    0.001    0.643    0.643 cprof_example.py:4(run_experiment)
   100    0.003    0.000    0.583    0.006 linalg.py:702(eigvals)
   200    0.569    0.003    0.569    0.003 {numpy.linalg.lapack_lite.dgeev}
   100    0.058    0.001    0.058    0.001 {method 'randn'}
   100    0.003    0.000    0.005    0.000 linalg.py:162(_assertFinite)
   200    0.002    0.000    0.002    0.000 {method 'all' of 'numpy.ndarray' objects}

执行%run -p -s cumulative cprof_example.py也能达到上面那条系统命令行命令一样的效果，但是却无需退出IPython。

逐行分析函数性能

有些时候，从%prun（或其他基于cProfile的性能分析手段）得到的信息要么不足以说明函数的执行时间，要么就复杂到难以理解（按函数名聚合）。对于这种情况，我们可以使用一个叫做line_profiler的小型库（可以通过PyPI或随便一种包管理工具获取）。其中有一个新的魔术函数%lprun，它可以对一个或多个函数进行逐行性能分析。你可以修改IPython配置（参考IPython文件或本章稍后关于配置的内容）以启用这个扩展，代码如下所示：

# A list of dotted module names of IPython extensions to load.
c.TerminalIPythonApp.extensions = ['line_profiler']

line_profiler可以通过编程的方式使用（请参阅完整文档），但其最强大的一面却是在IPython中的交互式使用。假设你有一个prof_mod模块，其中有一些用于NumPy数组计算的代码，如下所示：

from numpy.random import randn
 
def add_and_sum(x, y):
    added = x + y
    summed = added.sum(axis=1)
    return summed
 
def call_function():
    x = randn(1000, 1000)
    y = randn(1000, 1000)
    return add_and_sum(x, y)

如果我们想了解add_and_sum函数的性能，%prun会给出如下所示的结果：

In [569]: %run prof_mod
 
In [570]: x = randn(3000, 3000)
In [571]: y = randn(3000, 3000)
In [572]: %prun add_and_sum(x, y)
        4 function calls in 0.049 seconds
Ordered by: internal time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1  0.036   0.036  0.046  0.046 prof_mod.py:3(add_and_sum)
     1  0.009   0.009  0.009  0.009 {method 'sum' of 'numpy.ndarray' objects}
     1  0.003   0.003  0.049  0.049 <string>:1(<module>)
     1  0.000   0.000  0.000  0.000 {method 'disable' of '_lsprof.Profiler' objects}

这个结果并不能说明什么问题。启用line_profiler这个IPython扩展之后，就会出现一个新的魔术命令%lprun。用法上唯一的区别就是：必须为%lprun指明想要测试哪个或哪些函数。%lprun的通用语法为：

%lprun -f func1 -f func2 statement_to_profile

在本例中，我们想要测试的是add_and_sum，于是执行：

In [573]: %lprun -f add_and_sum add_and_sum(x, y)
Timer unit: 1e-06 s
File: book_scripts/prof_mod.py
Function: add_and_sum at line 3
Total time: 0.045936 s
Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     3                                           def add_and_sum(x, y):
     4      1           36510  36510.0     79.5      added = x + y
     5      1            9425   9425.0     20.5      summed = added.sum(axis=1)
     6      1               1      1.0      0.0      return summed

这个结果就容易理解多了。这里我们测试的只是add_and_sum这一个函数。上面那个模块中还有一个call_function函数，我们可以结合add_and_sum一起测试，于是最终的测试命令就成了下面这个样子：

In [574]: %lprun -f add_and_sum -f call_function call_function()
Timer unit: 1e-06 s
File: book_scripts/prof_mod.py
Function: add_and_sum at line 3
Total time: 0.005526 s
Line #       Hits     Time  Per Hit    % Time  Line Contents
==============================================================
    3                                          def add_and_sum(x, y):
    4         1       4375     4375.0   79.2       added = x + y
    5         1       1149     1149.0   20.8       summed = added.sum(axis=1)
    6         1          2        2.0    0.0       return summed
File: book_scripts/prof_mod.py
Function: call_function at line 8
Total time: 0.121016 s
Line #       Hits    Time    Per Hit     % Time  Line Contents
==============================================================
    8                                            def call_function():
    9        1       57169     57169.0    47.2       x = randn(1000, 1000)
   10        1       58304     58304.0    48.2       y = randn(1000, 1000)
   11        1        5543      5543.0     4.6       return add_and_sum(x, y)

通常，我会用%prun（cProfile）做“宏观的”性能分析，而用%lprun（line_profiler）做“微观的”性能分析。这两个工具都很有必要了解一下。

注意：在使用%lprun时，之所以必须显式指明待测试的函数名，是因为“跟踪”每一行代码的执行时间所需的开销很大。对不感兴趣的函数进行跟踪将会对性能分析结果造成显著的影响。

译注15：第一，s不一定行，看提示，要用c；第二，这个s实际上是step into。

译注16：也就是step over。

译注17：作者在这里的意思是这种断点比较随便，是硬编码的。