B.3 软件开发工具

    IPython的调试器用tab补全、语法增强、逐行异常追踪增强了pdb。调试代码的最佳时间就是刚刚发生错误。异常发生之后就输入%debug，就启动了调试器，进入抛出异常的堆栈框架：

    一旦进入调试器，你就可以执行任意的Python代码，在每个堆栈框架中检查所有的对象和数据（解释器会保持它们活跃）。默认是从错误发生的最低级开始。通过u（up）和d（down），你可以在不同等级的堆栈踪迹切换：

    2. > /home/wesm/code/pydata-book/examples/ipython_bug.py(13)calling_things()
    3.      12     works_fine()
    4. ---> 13     throws_an_exception()
    5.      14

    执行%pdb命令，可以在发生任何异常时让IPython自动启动调试器，许多用户会发现这个功能非常好用。

    用调试器帮助开发代码也很容易，特别是当你希望设置断点或在函数和脚本间移动，以检查每个阶段的状态。有多种方法可以实现。第一种是使用%run和-d，它会在执行传入脚本的任何代码之前调用调试器。你必须马上按s（step）以进入脚本：

    1. In [5]: run -d examples/ipython_bug.py
    2. Breakpoint 1 at /home/wesm/code/pydata-book/examples/ipython_bug.py:1
    3. NOTE: Enter 'c' at the ipdb>  prompt to start your script.
    4. > <string>(1)<module>()
    6. ipdb> s
    7. --Call--
    8. > /home/wesm/code/pydata-book/examples/ipython_bug.py(1)<module>()
    9. 1---> 1 def works_fine():
    10.       2     a = 5
    11.       3     b = 6

    然后，你就可以决定如何工作。例如，在前面的异常，我们可以设置一个断点，就在调用works_fine之前，然后运行脚本，在遇到断点时按c（continue）：

    1. ipdb> b 12
    2. ipdb> c
    3. > /home/wesm/code/pydata-book/examples/ipython_bug.py(12)calling_things()
    4.      11 def calling_things():
    5. 2--> 12     works_fine()
    6.      13     throws_an_exception()

    这时，你可以step进入works_fine()，或通过按n（next）执行works_fine()，进入下一行：

    1. ipdb> n
    2. > /home/wesm/code/pydata-book/examples/ipython_bug.py(13)calling_things()
    3. 2    12     works_fine()
    4. ---> 13     throws_an_exception()
    5.      14

    然后，我们可以进入throws_an_exception，到达发生错误的一行，查看变量。注意，调试器的命令是在变量名之前，在变量名前面加叹号！可以查看内容：

    1. ipdb> s
    2. --Call--
    3. > /home/wesm/code/pydata-book/examples/ipython_bug.py(6)throws_an_exception()
    4.       5
    5. ----> 6 def throws_an_exception():
    6.       7     a = 5
    8. ipdb> n
    9. > /home/wesm/code/pydata-book/examples/ipython_bug.py(7)throws_an_exception()
    10.       6 def throws_an_exception():
    11. ----> 7     a = 5
    12.       8     b = 6
    14. ipdb> n
    15. > /home/wesm/code/pydata-book/examples/ipython_bug.py(8)throws_an_exception()
    16.       7     a = 5
    17. ----> 8     b = 6
    18.       9     assert(a + b == 10)
    20. ipdb> n
    21. > /home/wesm/code/pydata-book/examples/ipython_bug.py(9)throws_an_exception()
    22.       8     b = 6
    23. ----> 9     assert(a + b == 10)
    24.      10
    26. ipdb> !a
    27. 5
    28. ipdb> !b
    29. 6

    提高使用交互式调试器的熟练度需要练习和经验。表B-2，列出了所有调试器命令。如果你习惯了IDE，你可能觉得终端的调试器在一开始会不顺手，但会觉得越来越好用。一些Python的IDEs有很好的GUI调试器，选择顺手的就好。

    还有一些其它工作可以用到调试器。第一个是使用特殊的set_trace函数（根据pdb.set_trace命名的），这是一个简装的断点。还有两种方法是你可能想用的（像我一样，将其添加到IPython的配置）：

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

    第一个函数set_trace非常简单。如果你想暂时停下来进行仔细检查（比如发生异常之前），可以在代码的任何位置使用set_trace：

    1. In [7]: run examples/ipython_bug.py
    2. > /home/wesm/code/pydata-book/examples/ipython_bug.py(16)calling_things()
    3. ---> 16     throws_an_exception()
    4.      17

    按c（continue）可以让代码继续正常行进。

    我们刚看的debug函数，可以让你方便的在调用任何函数时使用调试器。假设我们写了一个下面的函数，想逐步分析它的逻辑：

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

    这两个简单方法节省了我平时的大量时间。

    最后，调试器可以和%run一起使用。脚本通过运行%run -d，就可以直接进入调试器，随意设置断点并启动脚本：

    1. In [1]: %run -d examples/ipython_bug.py
    2. Breakpoint 1 at /home/wesm/code/pydata-book/examples/ipython_bug.py:1
    3. NOTE: Enter 'c' at the ipdb>  prompt to start your script.
    4. > <string>(1)<module>()
    6. ipdb>

    加上-b和行号，可以预设一个断点：

    1. In [2]: %run -d -b2 examples/ipython_bug.py
    3. Breakpoint 1 at /home/wesm/code/pydata-book/examples/ipython_bug.py:2
    4. NOTE: Enter 'c' at the ipdb>  prompt to start your script.
    5. > <string>(1)<module>()
    7. ipdb> c
    8. > /home/wesm/code/pydata-book/examples/ipython_bug.py(2)works_fine()
    9.       1 def works_fine():
    10. 1---> 2     a = 5
    11.       3     b = 6
    13. ipdb>

    对于大型和长时间运行的数据分析应用，你可能希望测量不同组件或单独函数调用语句的执行时间。你可能想知道哪个函数占用的时间最长。幸运的是，IPython可以让你开发和测试代码时，很容易地获得这些信息。

    手动用time模块和它的函数time.clock和time.time给代码计时，既单调又重复，因为必须要写一些无趣的模板化代码：

    1. import time
    2. start = time.time()
    3. for i in range(iterations):
    4.     # some code to run here
    5. elapsed_per = (time.time() - start) / iterations

    因为这是一个很普通的操作，IPython有两个魔术函数，%time和%timeit，可以自动化这个过程。

    %time会运行一次语句，报告总共的执行时间。假设我们有一个大的字符串列表，我们想比较不同的可以挑选出特定开头字符串的方法。这里有一个含有600000字符串的列表，和两个方法，用以选出foo开头的字符串：

    1. # a very large list of strings
    2. strings = ['foo', 'foobar', 'baz', 'qux',
    3.            'python', 'Guido Van Rossum'] * 100000
    5. method1 = [x for x in strings if x.startswith('foo')]
    7. method2 = [x for x in strings if x[:3] == 'foo']

    看起来它们的性能应该是同级别的，但事实呢？用%time进行一下测量：

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

    Wall time（wall-clock time的简写）是主要关注的。第一个方法是第二个方法的两倍多，但是这种测量方法并不准确。如果用%time多次测量，你就会发现结果是变化的。要想更准确，可以使用%timeit魔术函数。给出任意一条语句，它能多次运行这条语句以得到一个更为准确的时间：

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

    这个例子说明了解Python标准库、NumPy、pandas和其它库的性能是很有价值的。在大型数据分析中，这些毫秒的时间就会累积起来！

    %timeit特别适合分析执行时间短的语句和函数，即使是微秒或纳秒。这些时间可能看起来毫不重要，但是一个20微秒的函数执行1百万次就比一个5微秒的函数长15秒。在上一个例子中，我们可以直接比较两个字符串操作，以了解它们的性能特点：

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

    分析代码与代码计时关系很紧密，除了它关注的是“时间花在了哪里”。Python主要的分析工具是cProfile模块，它并不局限于IPython。cProfile会执行一个程序或任意的代码块，并会跟踪每个函数执行的时间。

    使用cProfile的通常方式是在命令行中运行一整段程序，输出每个函数的累积时间。假设我们有一个简单的在循环中进行线型代数运算的脚本（计算一系列的100×100矩阵的最大绝对特征值）：

    1. import numpy as np
    2. from numpy.linalg import eigvals
    4. def run_experiment(niter=100):
    5.     K = 100
    6.     results = []
    7.     for _ in xrange(niter):
    8.         mat = np.random.randn(K, K)
    9.         max_eigenvalue = np.abs(eigvals(mat)).max()
    10.         results.append(max_eigenvalue)
    11.     return results
    12. some_results = run_experiment()
    13. print 'Largest one we saw: %s' % np.max(some_results)

    运行之后，你会发现输出是按函数名排序的。这样要看出谁耗费的时间多有点困难，最好用-s指定排序：

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

    只显示出前15行。扫描cumtime列，可以容易地看出每个函数用了多少时间。如果一个函数调用了其它函数，计时并不会停止。cProfile会记录每个函数的起始和结束时间，使用它们进行计时。

    除了在命令行中使用，cProfile也可以在程序中使用，分析任意代码块，而不必运行新进程。Ipython的%prun和%run -p，有便捷的接口实现这个功能。%prun使用类似cProfile的命令行选项，但是可以分析任意Python语句，而不用整个py文件：

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

    相似的，调用%run -p -s cumulative cprof_example.py有和命令行相似的作用，只是你不用离开Ipython。

    在Jupyter notebook中，你可以使用%%prun魔术方法（两个%）来分析一整段代码。这会弹出一个带有分析输出的独立窗口。便于快速回答一些问题，比如“为什么这段代码用了这么长时间”？

    使用IPython或Jupyter，还有一些其它工具可以让分析工作更便于理解。其中之一是SnakeViz（

    有些情况下，用%prun（或其它基于cProfile的分析方法）得到的信息，不能获得函数执行时间的整个过程，或者结果过于复杂，加上函数名，很难进行解读。对于这种情况，有一个小库叫做line_profiler（可以通过PyPI或包管理工具获得）。它包含IPython插件，可以启用一个新的魔术函数%lprun，可以对一个函数或多个函数进行逐行分析。你可以通过修改IPython配置（查看IPython文档或本章后面的配置小节）加入下面这行，启用这个插件：

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

    你还可以运行命令：

    1. %load_ext line_profiler

    line_profiler也可以在程序中使用（查看完整文档），但是在IPython中使用是最为强大的。假设你有一个带有下面代码的模块prof_mod，做一些NumPy数组操作：

    1. from numpy.random import randn
    3. def add_and_sum(x, y):
    4.     added = x + y
    5.     summed = added.sum(axis=1)
    6.     return summed
    8. def call_function():
    9.     x = randn(1000, 1000)
    10.     y = randn(1000, 1000)
    11.     return add_and_sum(x, y)

    如果想了解add_and_sum函数的性能，%prun可以给出下面内容：

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

    上面的做法启发性不大。激活了IPython插件line_profiler，新的命令%lprun就能用了。使用中的不同点是，我们必须告诉%lprun要分析的函数是哪个。语法是：

    1. %lprun -f func1 -f func2 statement_to_profile

    我们想分析add_and_sum，运行：

    1. In [573]: %lprun -f add_and_sum add_and_sum(x, y)
    2. Timer unit: 1e-06 s
    3. File: prof_mod.py
    4. Function: add_and_sum at line 3
    5. Total time: 0.045936 s
    6. Line #      Hits         Time  Per Hit   % Time  Line Contents
    7. ==============================================================
    8.      3                                           def add_and_sum(x, y):
    9.      4         1        36510  36510.0     79.5      added = x + y

    这样就容易诠释了。我们分析了和代码语句中一样的函数。看之前的模块代码，我们可以调用call_function并对它和add_and_sum进行分析，得到一个完整的代码性能概括：