• B.3 软件开发工具
    • 交互调试器
    • 使用调试器的其它方式
    • 代码计时:%time 和 %timeit
    • 基础分析:%prun和%run -p
    • 逐行分析函数

    B.3 软件开发工具

    除了作为优秀的交互式计算和数据探索环境,IPython也是有效的Python软件开发工具。在数据分析中,最重要的是要有正确的代码。幸运的是,IPython紧密集成了和加强了Python内置的pdb调试器。第二,需要快速的代码。对于这点,IPython有易于使用的代码计时和分析工具。我会详细介绍这些工具。

    交互调试器

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

    1. In [2]: run examples/ipython_bug.py
    2. ---------------------------------------------------------------------------
    3. AssertionError Traceback (most recent call last)
    4. /home/wesm/code/pydata-book/examples/ipython_bug.py in <module>()
    5. 13 throws_an_exception()
    6. 14
    7. ---> 15 calling_things()
    8. /home/wesm/code/pydata-book/examples/ipython_bug.py in calling_things()
    9. 11 def calling_things():
    10. 12 works_fine()
    11. ---> 13 throws_an_exception()
    12. 14
    13. 15 calling_things()
    14. /home/wesm/code/pydata-book/examples/ipython_bug.py in throws_an_exception()
    15. 7 a = 5
    16. 8 b = 6
    17. ----> 9 assert(a + b == 10)
    18. 10
    19. 11 def calling_things():
    20. AssertionError:
    21. In [3]: %debug
    22. > /home/wesm/code/pydata-book/examples/ipython_bug.py(9)throws_an_exception()
    23. 8 b = 6
    24. ----> 9 assert(a + b == 10)
    25. 10
    26. ipdb>

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

    1. ipdb> u
    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>()
    5. ipdb> s
    6. --Call--
    7. > /home/wesm/code/pydata-book/examples/ipython_bug.py(1)<module>()
    8. 1---> 1 def works_fine():
    9. 2 a = 5
    10. 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
    7. ipdb> n
    8. > /home/wesm/code/pydata-book/examples/ipython_bug.py(7)throws_an_exception()
    9. 6 def throws_an_exception():
    10. ----> 7 a = 5
    11. 8 b = 6
    12. ipdb> n
    13. > /home/wesm/code/pydata-book/examples/ipython_bug.py(8)throws_an_exception()
    14. 7 a = 5
    15. ----> 8 b = 6
    16. 9 assert(a + b == 10)
    17. ipdb> n
    18. > /home/wesm/code/pydata-book/examples/ipython_bug.py(9)throws_an_exception()
    19. 8 b = 6
    20. ----> 9 assert(a + b == 10)
    21. 10
    22. ipdb> !a
    23. 5
    24. ipdb> !b
    25. 6

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

    表B-2 IPython调试器命令

    使用调试器的其它方式

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

    1. from IPython.core.debugger import Pdb
    2. def set_trace():
    3. Pdb(color_scheme='Linux').set_trace(sys._getframe().f_back)
    4. def debug(f, *args, **kwargs):
    5. pdb = Pdb(color_scheme='Linux')
    6. 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. 15 set_trace()
    4. ---> 16 throws_an_exception()
    5. 17

    按c(continue)可以让代码继续正常行进。

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

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

    普通地使用f,就会像f(1, 2, z=3)。而要想进入f,将f作为第一个参数传递给debug,再将位置和关键词参数传递给f:

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

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

    最后,调试器可以和%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>()
    5. ipdb>

    加上-b和行号,可以预设一个断点:

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

    代码计时:%time 和 %timeit

    对于大型和长时间运行的数据分析应用,你可能希望测量不同组件或单独函数调用语句的执行时间。你可能想知道哪个函数占用的时间最长。幸运的是,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
    4. method1 = [x for x in strings if x.startswith('foo')]
    5. 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
    4. In [562]: %time method2 = [x for x in strings if x[:3] == 'foo']
    5. CPU times: user 0.09 s, sys: 0.00 s, total: 0.09 s
    6. 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
    3. In [564]: %timeit [x for x in strings if x[:3] == 'foo']
    4. 10 loops, best of 3: 59.3 ms per loop

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

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

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

    基础分析:%prun和%run -p

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

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

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

    你可以用cProfile运行这个脚本,使用下面的命令行:

    1. python -m cProfile cprof_example.py

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

    1. $ python -m cProfile -s cumulative cprof_example.py
    2. Largest one we saw: 11.923204422
    3. 15116 function calls (14927 primitive calls) in 0.720 seconds
    4. Ordered by: cumulative time
    5. ncalls tottime percall cumtime percall filename:lineno(function)
    6. 1 0.001 0.001 0.721 0.721 cprof_example.py:1(<module>)
    7. 100 0.003 0.000 0.586 0.006 linalg.py:702(eigvals)
    8. 200 0.572 0.003 0.572 0.003 {numpy.linalg.lapack_lite.dgeev}
    9. 1 0.002 0.002 0.075 0.075 __init__.py:106(<module>)
    10. 100 0.059 0.001 0.059 0.001 {method 'randn')
    11. 1 0.000 0.000 0.044 0.044 add_newdocs.py:9(<module>)
    12. 2 0.001 0.001 0.037 0.019 __init__.py:1(<module>)
    13. 2 0.003 0.002 0.030 0.015 __init__.py:2(<module>)
    14. 1 0.000 0.000 0.030 0.030 type_check.py:3(<module>)
    15. 1 0.001 0.001 0.021 0.021 __init__.py:15(<module>)
    16. 1 0.013 0.013 0.013 0.013 numeric.py:1(<module>)
    17. 1 0.000 0.000 0.009 0.009 __init__.py:6(<module>)
    18. 1 0.001 0.001 0.008 0.008 __init__.py:45(<module>)
    19. 262 0.005 0.000 0.007 0.000 function_base.py:3178(add_newdoc)
    20. 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
    3. Ordered by: cumulative time
    4. List reduced from 32 to 7 due to restriction <7>
    5. ncalls tottime percall cumtime percall filename:lineno(function)
    6. 1 0.000 0.000 0.643 0.643 <string>:1(<module>)
    7. 1 0.001 0.001 0.643 0.643 cprof_example.py:4(run_experiment)
    8. 100 0.003 0.000 0.583 0.006 linalg.py:702(eigvals)
    9. 200 0.569 0.003 0.569 0.003 {numpy.linalg.lapack_lite.dgeev}
    10. 100 0.058 0.001 0.058 0.001 {method 'randn'}
    11. 100 0.003 0.000 0.005 0.000 linalg.py:162(_assertFinite)
    12. 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(https://github.com/jiffyclub/snakeviz/),它会使用d3.js产生一个分析结果的交互可视化界面。

    逐行分析函数

    有些情况下,用%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
    2. def add_and_sum(x, y):
    3. added = x + y
    4. summed = added.sum(axis=1)
    5. return summed
    6. def call_function():
    7. x = randn(1000, 1000)
    8. y = randn(1000, 1000)
    9. return add_and_sum(x, y)

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

    1. In [569]: %run prof_mod
    2. In [570]: x = randn(3000, 3000)
    3. In [571]: y = randn(3000, 3000)
    4. In [572]: %prun add_and_sum(x, y)
    5. 4 function calls in 0.049 seconds
    6. Ordered by: internal time
    7. ncalls tottime percall cumtime percall filename:lineno(function)
    8. 1 0.036 0.036 0.046 0.046 prof_mod.py:3(add_and_sum)
    9. 1 0.009 0.009 0.009 0.009 {method 'sum' of 'numpy.ndarray'}
    10. 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
    10. 5 1 9425 9425.0 20.5 summed = added.sum(axis=1)
    11. 6 1 1 1.0 0.0 return summed

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

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

    我的经验是用%prun (cProfile)进行宏观分析,%lprun (line_profiler)做微观分析。最好对这两个工具都了解清楚。

    笔记:使用%lprun必须要指明函数名的原因是追踪每行的执行时间的损耗过多。追踪无用的函数会显著地改变结果。