Effective Python -- 第 8 章 部署（下）

第 8 章 部署（下）

第 57 条：考虑用 pdb 实现交互调试

编写程序的时候，总会遇到代码中的 bug。print 函数可以帮我们追查到很多问题的来源。针对具体用例编写测试，也是一种隔离可疑代码并寻找错误根源的好办法。

但是这些手段未必总是能查到问题的根源。如果要使用更为强大的调试工具，那就请试试 Python 内置的交互调试器（interactive debugger）。这种调试器能够检视程序状态、打印局部变量，并能够以步进的方式来执行程序中的每一条语句。

在其他大部分编程语言中，先必须告诉调试器应该在源代码的哪一行停下来，然后再调试程序。但 Python 则不是这样，最简单的调试手法，就是修改程序，并在可疑的代码上方直接启动调试器，以探查代码中的问题。用调试器来运行 Python 程序，与正常运行 Python 程序，是没有区别的。

只需引入内置的 pdb 模块，并运行其 set_trace 函数，即可触发调试器。这两个操作，通常会写在同一行之中，这使得开发者在不需要调试的时候，能够用一个 # 号，把整行代码注释掉。

def complex_func(a, b, c):
    # ...
    import pdb; pdb.set_trace()

只要运行到那行语句，程序就会暂停。执行该程序所用的那个终端机，会转入交互式的 Python 提示符界面。

-> import pdb; pdb.set_trace()
(Pdb)

在（Pdb）提示符界面中，可以输人局部变量的名称，以打印它们的值，也可以调用内置的 locals 函数，来列出所有的局部变量，还可以引入模块、检视全局状态、构建新对象、运行内置的 help 函数，甚至修改程序中的某个部分。凡是有助于调试的操作，都可以在调试器界面中执行。此外，调试器还提供了三个命令，可以更加方便地查看正在调试的程序。

• bt: 针对当前执行点的调用栈，打印其回溯（traceback）信息。可以据此判断出程序当前执行到了哪个位置，也可以看出程序是如何从最开头运行到触发 pdb.set_trace 函数的这一点的。
• up: 把调试范围沿着函数调用栈上移一层，回到当前函数的调用者那里。该命令使得我们可以检视调用栈上层的局部变量。
• down: 把调试范围沿着函数调用栈下移一层。

检视过当前的状态之后，我们可以用下面几个调试器命令来精确地控制程序，使其继续往下执行。

• step: 执行当前这行代码，并把程序继续运行到下一条可执行的语句开头，然后把控制权交还给调试器。如果当前这行代码中带有函数调用操作，那么调试器会进入受调用的那个函数，并停留在那个函数开头。
• next: 执行当前这行代码，并把程序继续运行到下一条可执行的语句开头，然后把控制权交还给调试器。如果当前这行代码中带有函数调用操作，那么调试器不会停留在函数里面，而是会调用那个函数，并等待其返回。
• return: 继续运行程序，直至到达当前函数的 return 语句开头，然后把控制权交还给调试器。
• continue: 继续运行程序,直至到达下一个断点或下一个 set_trace 调用点。

总结

• 可以修改 Python 程序，在想要调试的代码上方直接加入 import pdb; pdb.set_trace() 语句，以触发互动调试器。
• Python 调试器也是一个完整的 Python 提示符界面，可以检视并修改受测程序的状态。
• 可以在 pdb 提示符中输人命令，以便精确地控制程序的执行流程，这些命令使得我们能够交替地查看程序状态并继续向下运行程序。

第 58 条：先分析性能，然后再优化

由于 Python 是一门动态语言，所以 Python 程序的运行效率可能与预想的结果有很大差距。有一些操作，认为应该执行得比较慢，但实际上却很快，例如，对字符串的各种操作，以及生成器等；而另外一些语言特性，认为应该执行得比较快，但实际上却很慢，例如，属性访问及函数调用等操作。所以，导致 Python 程序效率低下的真正原因，可能是很难看出来的。

应对性能问题的最佳方式，是在优化程序之前先分析其性能，而不是靠直觉去判断。Python 提供了内置的性能分析工具（profiler），它可以计算出程序中某个部分的执行时间，在总体执行时间中所占的比率。通过这些数据，可以找到最为显著的性能瓶颈，并把注意力放在优化这部分代码上面，而不要在不影响速度的那些地方浪费精力。

例如，想查明程序中的某个算法为什么运行得比较慢。下面定义的这个函数，采用插入排序法（insertion sort）来排列一组数据:

def insertion_sort(data):
    result = []
    for value in data:
        insert_value(result, value)
    return result

插入排序法的核心机制，就是 inscrt_valuc 函数，该函数用来查找每项数据的插入点。下面定义的这个 insert_valuc 函数，要对外界输入的 array 序列进行线性扫描，以确定插入点，因此，它的效率是非常低的:

def insert_value(array, value):
    for i, existing in enumerate(array):
        if existing > value:
            array.insert(i, value)
            return
    array.append(value)

为了分析 insertion_sort 和 insert_value 的效率，创建了一组随机数字，并定义了 test 函数，以便将该函数传给 profiler。

from random import randint

max_size = 10**4
data = [randint(0, max_size) for _ in range(max_size)]
test = lambda: insertion_sort(data)

Python 提供了两种内置的 profiler，一种是纯 Python 的 profiler（名字叫做 profile），另外一种是 C 语言扩展模块（名字叫做 cProfile）。在这两者中，内置的 cProfile 模块更好，因为它在做性能分析时，对受测程序的效率只会产生很小的影响，而纯 Python 版的 profiler，则会产生较大的开销，从而使测试结果变得不够准确。

下面实例化 cProfile 模块中的 Profile 对象，并通过 runcall 方法来运行刚才定义的 test 函数:

profiler = Profile()
profiler.runcall(test)

test 函数运行完毕之后，采用内置的 pstats 模块和模块中的 Stats 类，来剖析由 Profile 对象所收集到的性能统计数据。Stats 对象提供了各种方法，可以用这些方法对性能分析数据进行遴选及排序，以便把自己所关注的那部分信息单独列出来。

stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()

上面那段代码会输出一张表格，其中的信息是按照函数来分组的。表格中的数据，是在 profiler 处于激活状态的时候统计出来的，也就是说，这些时间数据，都是在执行刚才那个 runcall 方法的过程中统计出来的。

>>>
        20003 function ca11s in 1.812 seconds

Ordered by : cumulative time

ncalls tottime percal1 cumtime perca11 filename:lineno(function)
1       0.000   0.000   1.812   1.812   main.py:34(<1ambda>)
1       0.003   0.003   1.812   1.812   main.py:10(insertion_sort)
10000   1.797   0.000   1.810   0.000   main.py:20(insert_value)
9992    0.013   0.000   0.013   0.000   {method 'insert' of "list' objects}
8       0.000   0.000   0.000   0.000   {method 'append' of 'list' objects}
1       0.000   0.000   0.000   0.000   {method 'disable' of '_1sprof.Profiler' objects}

下面简述性能统计表中每一列的含义:

• ncalls: 该函数在性能分析期间的调用次数。
• tottime: 执行该函数所花的总秒数。本函数因调用其他函数所耗费的时间，不记入在内。
• tottime percall: 每次调用该函数所花的平均秒数。本函数因调用其他函数所耗费的时间，不记人在内。此值等于 tottime 与 ncalls 相除的商。
• cumtime: 执行该函数及其中的全部函数调用操作，所花的总秒数。
• cumtime percall: 每次执行该函数及其中的全部函数调用操作，所花的平均秒数。此值等于 cumtime 与 ncalls 相除的商。

通过 profiler 给出的统计表可以看到，在 cumulative time (累积时间）一栏中，insert_value 函数所占用的 CPU 份额是最大的。于是，改用内置的 bisect 模块来重新定义此函数:

from bisect import bisect_left
def insert_value(array, value):
    i = bisect_left(array, value)
    array.insert(i, value)

再次运行 profiler。根据新生成的这张性能统计表可以看出，新函数要比原来快得多，insert_value 函数所耗费的累积时间，几乎是原来的百分之一。

>>>

        30003 function calls in 0.028 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall  filename:lineno(function)
1       0.000     0.000     0.028   0.028   main.py:34(<lambda>)
1       0.002     0.002     0.028   0.028   main.py:10(insertion_sort)
10000   0.005     0.000     0.026   0.000   main.py:112(insert_value)
10000   0.014     0.000     0.014   0.000   {method 'insert' of 'list' objects}
10000   0.007     0.000     0.007   0.000   {built-in method bisect_left}
1       0.000     0.000     0.000   0.000   {method 'disable' of '_lsprof.Profiler' objects)

有时，在分析整个程序的性能时，可能会发现，某个常用的工具函数，占据了大部分执行时间。而从 profiler 所给出的默认统计数据里，却无法清晰地分辨出：程序中的不同部分，究竞是如何调用这个工具函数的。

例如，程序中有两个不同的函数，都会频繁调用下面这个名为 my_utility 的工具函数:

def my_utility(a, b):
    # ...

def first_func():
    for _in range(1000):
        my _utility(4, 5)

def second_func(:
    for _ in range(10):
        my_utility(1, 3)

def my_program():
    for _ in range(20):
        first_func()
        second_func()

在分析完范例代码的性能，并用 print_stats 打出默认的结果之后，就会发现：输出的统计结果是令人困惑的。

>>>

    20242 function calls in 0.208 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall  filename:lineno(function)
1       0.000    0.000      0.208   0.208   main.py:176(my_program)
20      0.005    0.000      0.206   0.010   main.py:168(first_func)
20200   0.203    0.000      0.203   0.000   main.py:161(my_utility)
20      0.000    0.000      0.002   0.000   main.py:172(second_func)
1       0.000    0.000      0.000   0.000   {method 'disable'of '_lsprof.Profiler’ objects}

毫无疑问，my_utility 函数是占据执行时间最多的函数，但是，并不清楚程序究竟为什么要把该函数调用那么多次。在翻阅程序代码的过程中，可以看到很多个调用 my_utility 的地方，所以，这种格式的性能统计结果，是不够清晰的。

Python 的 profiler 提供了一种方式，可以在性能分析数据中列出每个函数的调用者，可以据此看出该函数所耗费的执行时间，究竟是由哪些调用者所分别引发的。

stats.print_callers()

在这次打印出来的性能统计数据中，左边列出的是受测函数，右边列出的是该函数的调用者。据此可以看出，调用 my_utility 最为频繁的是 first_func 函数，my_utility 的大部分执行时间都是由 first_func 所引发的:

>>>
        Ordered by: cumulative time

Function                    was called by . . .
                                ncalls  tottime  cumtime
main.py:176(my_program)     <-
main.py:168(first_func)     <-     20   0.005     0.206 main.py:176(my_program)
main.py : 161(my _utility   <-  20000   0.202     0.202 main.py:168(first_func)
                                  200   0.002     0.002 main.py:172(second_func)
main.py :172(second_func)   <-     20   0.000     0.002 main.py:176(my_program)

总结

• 优化Python程序之前，一定要先分析其性能，因为 Python 程序的性能瓶颈通常很难直接观察出来。
• 做性能分析时，应该使用 cProfile 模块，而不要使用 profile 模块，因为前者能够给出更为精确的性能分析数据。
• 可以通过 Profile 对象的 runcall 方法来分析程序的性能，该方法能够提供性能分析所需的全部信息，它会按照树状的函数调用关系，来单独地统计每个函数的性能。
• 可以用 Stats 对象来筛选性能分析数据，并打印出所需的那一部分，以便据此了解程序的性能。

第 59 条：用 tracemalloc 来掌握内存的使用及泄漏情况

在 Python 的默认实现方式，也就是 CPython 中，内存管理是通过引用计数来处理的。这样做可以保证：当指向某个对象的全部引用都过期的时候，受引用的这个对象也能够同时得到清理。另外，CPython 还内置了循环检测器（cycle detector），使得垃圾回收机制能够把那些自我引用的（self-referencing）对象清理掉。

从理论上说，这意味着大部分 Python 程序员都不用担心程序的内存分配和内存释放问题，因为 Python 语言及 CPython 运行时系统会自动把这些问题处理好。但实际上，程序还是会因为保留了过多的引用而导致内存耗尽。要想在 Python 程序中找出消耗内存或泄漏内存的地方，其实是比较困难的。

调试内存使用状况的第一种办法，是向内置的gc模块进行查询，请它列出垃圾收集器当前所知的每个对象。尽管这是个相当笨拙的工具，但这种做法确实能够使我们迅速得知程序的内存使用状况。

下面先运行一个程序，该程序会保留许多个指向相关对象的引用，进而浪费一些内存。然后，打印出程序执行期间所创建的对象数量，并在程序所分配的这些对象之中，选取一个较小的样本，将其展示出来。

# using_gc.py
import gc
found_objects = gc.get_objects()
print('%d objects before' % len(found_objects))

import waste_memory
x = waste_memory.run()
found_objects = gc.get_objects()
print('%d objects after' % len(found_objects))
for obj in found_objects[:3]:
    print(repr(obj)[:100])
>>>
4756 objects before
14873 objects after
<waste_memory.MyObject object at 0x1063f6940>
<waste_memory.My0bject object at 0x1063f6978>
<waste_memory.MyObject object at 0x1063f69b0>

gc.get_objects 函数的缺点是，它不能告诉我们这些对象到底是如何分配出来的。在较为复杂的程序中，代码会以多种不同的方式，来分配某个类的对象，所以，不仅要知道对象的总数量，而且更为重要的是，要知道这些对象究竞是由哪一部分代码分配出来的，了解到这一信息，才可以更好地判断内存泄漏的原因。

Python 3.4 推出了一个新的内置模块，名叫 tracemalloc，它可以解决这个问题。tracemalloc 可以把某个对象与该对象的内存分配地点联系起来。下面用 tracemalloc 打印出导致内存用量增大的前三个对象:

# top_n.py
import tracemalloc
tracemalloc.start(10)  # Save up to 10 stack frames

time1 = tracemalloc.take_snapshot()
import waste_memory
= waste_memory.run()
time2 = tracemalloc.take_snapshot()

stats = time2.compare_to(time1, 'lineno')
for stat in stats[:3]:
    print(stat)
>>>
waste_memory.py:6: size=2235 KiB (+2235 KiB), count=29981 (+29981)，average=76 B
waste_memory.py:7: size=869 KiB (+869 KiB), count=10000 (+10000)，average=89 B
waste_memory.py:12: size=547 KiB (+547 KiB), count=10000 (+10000)，average=56 B

通过上述信息，立刻就能看出导致内存用量变大的主要因素，以及分配那些对象的语句在源代码中的位置。

tracemalloc 模块也可以打印出 Python 系统在执行每一个分配内存操作时，所具备的完整堆栈信息（full stack trace），打印的最大栈帧数量，由传给 start 函数的参数来决定。下面找到程序中最消耗内存的那个内存分配操作，并将该操作的堆栈信息打印出来。

# with_trace.py
# ...
stats = time2.compare_to(time1, 'traceback')
top = stats[0]
print('\n'.join(top.traceback.format()))
>>>
FiTe "waste_memory.py", line 6
  self.x = os.urandom(100)
File "waste_memory .py", line 12
  obj = My0bject()
File "waste_memory .py", line 19
  deep_values.append(get_data())
File "with_trace.py", line 10
  x = waste_memory.run()

如果程序中有多个地点都调用了同一个函数，那么通过上述方式就可以更好地看出，究竟是哪一行调用代码导致内存占用量变大的。

Python 2 虽然没有内置这个 tracemalloc 模块，但是有许多开源软件包（如 heapy 等）也可以追踪内存用量，然而它们在功能上面，与 tracemalloc 并不是完全相同的。

总结

• Python 程序的内存使用情况和内存泄漏情况是很难判断的。
• 虽然可以通过 gc 模块来了解程序中的对象，但是并不能由此看出这些对象究竞是如何分配出来的。
• 内置的 tracemalloc 模块提供了许多强大的工具，使得可以找出导致内存使用量增大的根源。
• 只有 Python 3.4 及后续版本，才支持 tracemalloc 模块。