17.9. profile and pstats — 性能分析

Python 3 标准库实例教程 /

本节目标：了解如何 Python 程序性能分析

profile 模块提供一组用于收集和分析统计 Python 如何执行资源的 API。

注意

本节中的输出报告为了适配页面做了格式化。行末尾有反斜杠（\）的均表示本行未完。

运行 Profiler

最基本的使用 profile 是使用 run()。它接受一个字符串声明为参数，同时会创建一份执行代码时每行运行时间的报告。

profile_fibonacci_raw.py

import profile

def fib(n):
    # from literateprograms.org
    # http://bit.ly/hlOQ5m
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)

def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n - 1))
    seq.append(fib(n))
    return seq

profile.run('print(fib_seq(20)); print()')

我们使用递归版本的斐波那契数列可以有效的演示 profile，因为递归版本的很慢，我们改进的话可以有非常明显的性能提升。标准的报告显示了一份概述和每个函数的执行详情。

$ python3 profile_fibonacci_raw.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 98\
7, 1597, 2584, 4181, 6765]

         57359 function calls (69 primitive calls) in 0.127 seco\
nds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(fu\
nction)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.127    0.127 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.127    0.127 <string>:1(<module\
>)
        1    0.000    0.000    0.127    0.127 profile:0(print(fi\
b_seq(20)); print())
        0    0.000             0.000          profile:0(profiler\
)
 57291/21    0.126    0.000    0.126    0.006 profile_fibonacci_\
raw.py:11(fib)
     21/1    0.000    0.000    0.127    0.127 profile_fibonacci_\
raw.py:22(fib_seq)

此版本执行了 57359 次函数调用花费了0.127秒。实际上其实只需要69次原生调用即可但递归却用了 57K 次。结果详情中显示出了函数的哪些地方花费了巨量时间，在列表中同样还有调用次数，函数的总时间花费，每次调用的时间，函数的累积花费时间和累积时间在原生调用中所占比率。

毫无意外，花费最多的时间是重复调用 fib() 。我们添加一个缓存来生成递归调用计数，这样我们对此函数的执行就有一个比较全面的理解。

profile_fibonacci_memoized.py

import functools
import profile

@functools.lru_cache(maxsize=None)
def fib(n):
    # from literateprograms.org
    # http://bit.ly/hlOQ5m
    if n == 0:
        return 0
    elif n == 1:
        return 1
    else:
        return fib(n - 1) + fib(n - 2)

def fib_seq(n):
    seq = []
    if n > 0:
        seq.extend(fib_seq(n - 1))
    seq.append(fib(n))
    return seq

if __name__ == '__main__':
    profile.run('print(fib_seq(20)); print()')

记住了每层斐波那契数列数列的值，避免了大量递归，运行次数降到了89，运行时间只需 0.001 秒。ncalls 的计数显示 fib() 从未进行递归。

$ python3 profile_fibonacci_memoized.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 98\
7, 1597, 2584, 4181, 6765]

         89 function calls (69 primitive calls) in 0.001 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(fu\
nction)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.000    0.000 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module\
>)
        1    0.000    0.000    0.001    0.001 profile:0(print(fi\
b_seq(20)); print())
        0    0.000             0.000          profile:0(profiler\
)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:12(fib)
     21/1    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:24(fib_seq)

在上下文中运行

有时，为了避免构建一个复杂的 run() 表达式，我们可以写一个简单些的表达式，然后使用 runctx() 传入上下文参数。

profile_runctx.py

import profile
from profile_fibonacci_memoized import fib, fib_seq

if __name__ == '__main__':
    profile.runctx(
        'print(fib_seq(n)); print()',
        globals(),
        {'n': 20},
    )

本例中，n 的值我们通过本地变量上下文来传入，避免了直接在声明语句中使用。

$ python3 profile_runctx.py

[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,
987, 1597, 2584, 4181, 6765]

        148 function calls (90 primitive calls) in 0.002 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(\
function)
       21    0.000    0.000    0.000    0.000 :0(append)
        1    0.000    0.000    0.001    0.001 :0(exec)
       20    0.000    0.000    0.000    0.000 :0(extend)
        2    0.000    0.000    0.000    0.000 :0(print)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        1    0.000    0.000    0.001    0.001 <string>:1(<module\
>)
        1    0.000    0.000    0.002    0.002 profile:0(print(fi\
b_seq(n)); print())
        0    0.000             0.000          profile:0(profiler\
)
    59/21    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:19(__call__)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:27(fib)
     21/1    0.000    0.000    0.001    0.001 profile_fibonacci_\
memoized.py:39(fib_seq)

pstats: 保存以及分析统计

profile 生成的标准报告并不是很流畅。不过，我们可以通过 run() 和 runctx() 保存的原分析数据使用 pstats.Stats 类生成自定义报告。

我们运行多组同样的迭代看看结果：

profile_stats.py

import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# 创建5组统计信息。
for i in range(5):
    filename = 'profile_stats_{}.stats'.format(i)
    profile.run('print({}, fib_seq(20))'.format(i), filename)

# 用同一个对象读取全部的5个统计文件。
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))

# 清理报告文件
stats.strip_dirs()

# 以累积花费的时间进行排序
stats.sort_stats('cumulative')

stats.print_stats()

输出的报告会以累积时间的降序排序，目录名我们也移除了，以免水平过长导致页面画风崩塌。

$ python3 profile_stats.py

0 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,\
987, 1597, 2584, 4181, 6765]
1 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,\
987, 1597, 2584, 4181, 6765]
2 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,\
987, 1597, 2584, 4181, 6765]
3 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,\
987, 1597, 2584, 4181, 6765]
4 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,\
987, 1597, 2584, 4181, 6765]
Sat Dec 31 07:46:22 2016    profile_stats_0.stats
Sat Dec 31 07:46:22 2016    profile_stats_1.stats
Sat Dec 31 07:46:22 2016    profile_stats_2.stats
Sat Dec 31 07:46:22 2016    profile_stats_3.stats
Sat Dec 31 07:46:22 2016    profile_stats_4.stats

         351 function calls (251 primitive calls) in 0.000 secon\
ds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(fu\
nction)
        5    0.000    0.000    0.000    0.000 {built-in method b\
uiltins.exec}
        5    0.000    0.000    0.000    0.000 <string>:1(<module\
>)
    105/5    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:24(fib_seq)
        5    0.000    0.000    0.000    0.000 {built-in method b\
uiltins.print}
      100    0.000    0.000    0.000    0.000 {method 'extend' o\
f 'list' objects}
       21    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:12(fib)
      105    0.000    0.000    0.000    0.000 {method 'append' o\
f 'list' objects}
        5    0.000    0.000    0.000    0.000 {method 'disable'\
of '_lsprof.Profiler' objects}

限制报告内容

输出的内容可以经由函数修改。下面我们使用正则表达式让内容只输出关于 fib() 和 fib_seq()。

profile_stats_restricted.py

import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# 让单个对象读取5个统计文件。
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')

# 限制输出，只能是"(fib"的才能输出。
stats.print_stats('\(fib')

正则表达式中我们写了左括号（(）来匹配函数名中的一部分作为我们想要的结果。

$ python3 profile_stats_restricted.py

Sat Dec 31 07:46:22 2016    profile_stats_0.stats
Sat Dec 31 07:46:22 2016    profile_stats_1.stats
Sat Dec 31 07:46:22 2016    profile_stats_2.stats
Sat Dec 31 07:46:22 2016    profile_stats_3.stats
Sat Dec 31 07:46:22 2016    profile_stats_4.stats

         351 function calls (251 primitive calls) in 0.000 secon\
ds

   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(fu\
nction)
    105/5    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:24(fib_seq)
       21    0.000    0.000    0.000    0.000 profile_fibonacci_\
memoized.py:12(fib)

调用 / 被调用图表

Stats 同样有打印出调用/ 被调用函数的方法。

profile_stats_callers.py

import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq

# 用同样的对象读取5个统计文件。
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
    stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')

print('INCOMING CALLERS:')
stats.print_callers('\(fib')

print('OUTGOING CALLEES:')
stats.print_callees('\(fib')

print_callers() 和 print_callees() 与 print_stats() 的参数一样。输出的话会显示出调用者，被调用者，调用的次数，和累积的运行时间。

$ python3 profile_stats_callers.py

INCOMING CALLERS:
   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

Function                                   was called by...
                                               ncalls  tottime\
cumtime
profile_fibonacci_memoized.py:24(fib_seq)  <-       5    0.000\
  0.000  <string>:1(<module>)
                                                100/5    0.000\
  0.000  profile_fibonacci_memoized.py:24(fib_seq)
profile_fibonacci_memoized.py:12(fib)      <-      21    0.000\
  0.000  profile_fibonacci_memoized.py:24(fib_seq)

OUTGOING CALLEES:
   Ordered by: cumulative time
   List reduced from 8 to 2 due to restriction <'\\(fib'>

Function                                   called...
                                               ncalls  tottime\
cumtime
profile_fibonacci_memoized.py:24(fib_seq)  ->      21    0.000\
  0.000  profile_fibonacci_memoized.py:12(fib)
                                                100/5    0.000\
  0.000  profile_fibonacci_memoized.py:24(fib_seq)
                                                  105    0.000\
  0.000  {method 'append' of 'list' objects}
                                                  100    0.000\
  0.000  {method 'extend' of 'list' objects}
profile_fibonacci_memoized.py:12(fib)      ->

参阅

profile 标准库文档

functools.lru_cache() -- 本节中用于提高执行效率的缓存装饰器

The Stats Class -- pstats.Stats 标准库文档.

Gprof2Dot -- 性能数据可视化工具

Python Decorators: Syntactic Sugar | avina... -- 另外一种有记忆的斐波那契数列生成器的 Python 实现。.

Smiley -- Python 应用程序追踪器

本文章首发在 LearnKu.com 网站上。

本译文仅用于学习和交流目的，转载请务必注明文章译者、出处、和本文链接
我们的翻译工作遵照 CC 协议，如果我们的工作有侵犯到您的权益，请及时联系我们。

原文地址：https://learnku.com/docs/pymotw/profile-...

译文地址：https://learnku.com/docs/pymotw/profile-...

17.9. profile and pstats — 性能分析

注意

运行 Profiler

在上下文中运行

pstats: 保存以及分析统计

限制报告内容

调用 / 被调用图表

参阅

社区赞助商

关于 LearnKu

资源推荐

服务提供商

其他信息

17.9. profile and pstats — 性能分析

注意

运行 Profiler

在上下文中运行

pstats: 保存以及分析统计

限制报告内容

调用 / 被调用 图表

参阅

社区赞助商

关于 LearnKu

资源推荐

服务提供商

其他信息

请登录

调用 / 被调用图表