Python 分析器

源代码: Lib/profile.pyLib/pstats.py


分析器简介

cProfileprofile 提供了 Python 程序的 确定性分析分析 (profile) 是一组统计数据,描述了程序的各个部分执行的频率和时长。这些统计数据可以通过 pstats 模块格式化为报告。

Python 标准库提供了两种不同的对同一分析接口的实现:

  1. cProfile 推荐给大多数用户使用;它是一个 C 扩展,具有合理的开销,使其适用于分析长时间运行的程序。基于 lsprof,由 Brett Rosen 和 Ted Czotter 贡献。

  2. profile,一个纯 Python 模块,其接口被 cProfile 模仿,但它会给被分析的程序增加显著的开销。如果你想以某种方式扩展分析器,使用这个模块可能会更容易。最初由 Jim Roskind 设计和编写。

备注

分析器模块旨在为给定程序提供执行分析,而不是用于基准测试(为此,有 timeit 模块可以提供相当准确的结果)。这尤其适用于将 Python 代码与 C 代码进行基准测试:分析器会给 Python 代码引入开销,但不会给 C 级别的函数引入开销,因此 C 代码看起来会比任何 Python 代码都快。

即时用户手册

本节为“不想阅读手册”的用户提供。它提供了一个非常简短的概述,并允许用户快速对现有应用程序执行分析。

要分析一个接受单个参数的函数,你可以这样做:

import cProfile
import re
cProfile.run('re.compile("foo|bar")')

(如果你的系统上没有 cProfile,请使用 profile 代替。)

上述操作将运行 re.compile() 并打印出类似以下的分析结果:

      214 function calls (207 primitive calls) in 0.002 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.002    0.002 {built-in method builtins.exec}
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 __init__.py:250(compile)
     1    0.000    0.000    0.001    0.001 __init__.py:289(_compile)
     1    0.000    0.000    0.000    0.000 _compiler.py:759(compile)
     1    0.000    0.000    0.000    0.000 _parser.py:937(parse)
     1    0.000    0.000    0.000    0.000 _compiler.py:598(_code)
     1    0.000    0.000    0.000    0.000 _parser.py:435(_parse_sub)

第一行表示监控了 214 次调用。在这些调用中,有 207 次是 原始的 (primitive),意味着这次调用不是通过递归引起的。下一行:Ordered by: cumulative time 表示输出是按 cumtime 值排序的。列标题包括:

ncalls

调用的次数。

tottime

在给定函数中花费的总时间(不包括调用子函数的时间)

percall

tottime 除以 ncalls 的商

cumtime

是在此函数和所有子函数中花费的累积时间(从调用到退出)。这个数字即使对于递归函数也是准确的。

percall

cumtime 除以原始调用次数的商

filename:lineno(function)

提供每个函数的相应数据

当第一列有两个数字时(例如 3/1),表示该函数发生了递归。第二个值是原始调用的次数,前一个值是总调用次数。请注意,当函数不递归时,这两个值是相同的,并且只打印单个数字。

你也可以不把输出打印在分析运行的末尾,而是通过为 run() 函数指定一个文件名来将结果保存到文件中:

import cProfile
import re
cProfile.run('re.compile("foo|bar")', 'restats')

pstats.Stats 类从文件中读取分析结果,并以各种方式格式化它们。

cProfileprofile 文件也可以作为脚本调用来分析另一个脚本。例如:

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)
-o <output_file>

将分析结果写入文件,而不是标准输出。

-s <sort_order>

指定 sort_stats() 的排序值之一来对输出进行排序。这仅在未提供 -o 时适用。

-m <module>

指定正在分析的是一个模块而不是一个脚本。

在 3.7 版本加入: cProfile 添加了 -m 选项。

在 3.8 版本加入: profile 添加了 -m 选项。

pstats 模块的 Stats 类有多种方法用于操作和打印保存到分析结果文件中的数据:

import pstats
from pstats import SortKey
p = pstats.Stats('restats')
p.strip_dirs().sort_stats(-1).print_stats()

strip_dirs() 方法从所有模块名称中移除了多余的路径。sort_stats() 方法根据打印的标准模块/行/名称字符串对所有条目进行排序。print_stats() 方法打印出所有统计信息。你可以尝试以下排序调用:

p.sort_stats(SortKey.NAME)
p.print_stats()

第一个调用实际上会按函数名对列表进行排序,第二个调用会打印出统计信息。以下是一些有趣的调用可以尝试:

p.sort_stats(SortKey.CUMULATIVE).print_stats(10)

这将按函数中的累积时间对分析结果进行排序,然后只打印最重要的十行。如果你想了解哪些算法耗时,上面这行就是你所需要的。

如果你想查看哪些函数循环次数多且耗时,你可以这样做:

p.sort_stats(SortKey.TIME).print_stats(10)

以根据每个函数内部花费的时间进行排序,然后打印前十个函数的统计信息。

你也可以尝试:

p.sort_stats(SortKey.FILENAME).print_stats('__init__')

这将按文件名对所有统计数据进行排序,然后只打印类初始化方法的统计信息(因为它们的名字中带有 __init__)。作为最后一个例子,你可以尝试:

p.sort_stats(SortKey.TIME, SortKey.CUMULATIVE).print_stats(.5, 'init')

此行以时间为主键,累积时间为次键对统计信息进行排序,然后打印出部分统计信息。具体来说,列表首先被缩减到其原始大小的 50%(re: .5),然后只保留包含 init 的行,并打印该子列表。

如果你想知道哪些函数调用了上述函数,你现在可以(p 仍然按照最后一个标准排序)这样做:

p.print_callers(.5, 'init')

你会得到一个列出的每个函数的调用者列表。

如果你想要更多功能,你需要阅读手册,或者猜测以下函数的作用:

p.print_callees()
p.add('restats')

当作为脚本调用时,pstats 模块是一个用于读取和检查分析转储文件的统计浏览器。它有一个简单的面向行的接口(使用 cmd 实现)和交互式帮助。

profilecProfile 模块参考

profilecProfile 模块都提供了以下函数:

profile.run(command, filename=None, sort=-1)

该函数接受一个可以传递给 exec() 函数的单个参数,以及一个可选的文件名。在所有情况下,此例程都会执行:

exec(command, __main__.__dict__, __main__.__dict__)

并从执行中收集分析统计数据。如果没有文件名,则此函数会自动创建一个 Stats 实例并打印一个简单的分析报告。如果指定了排序值,它将被传递给此 Stats 实例以控制结果的排序方式。

profile.runctx(command, globals, locals, filename=None, sort=-1)

此函数与 run() 类似,但增加了参数来为 command 字符串提供全局和局部命名空间映射。此例程执行:

exec(command, globals, locals)

并像上面的 run() 函数一样收集分析统计数据。

class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)

这个类通常只在需要比 cProfile.run() 函数提供的更精确的分析控制时使用。

可以通过 timer 参数提供一个自定义的计时器来测量代码运行所需的时间。这必须是一个返回表示当前时间的单个数字的函数。如果该数字是整数,则 timeunit 指定一个乘数,用于指定每个时间单位的持续时间。例如,如果计时器返回以千分之一秒为单位测量的时间,则时间单位将为 .001

直接使用 Profile 类可以格式化分析结果,而无需将分析数据写入文件:

import cProfile, pstats, io
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

Profile 类也可以用作上下文管理器(仅在 cProfile 模块中支持。参见 上下文管理器类型):

import cProfile

with cProfile.Profile() as pr:
    # ... do something ...

    pr.print_stats()

在 3.8 版本发生变更: 添加了上下文管理器支持。

enable()

开始收集分析数据。仅在 cProfile 中可用。

disable()

停止收集分析数据。仅在 cProfile 中可用。

create_stats()

停止收集分析数据,并将结果作为当前分析在内部记录。

print_stats(sort=-1)

基于当前分析创建一个 Stats 对象,并将结果打印到标准输出。

sort 参数指定了显示统计信息的排序顺序。它接受一个键或一个键的元组以启用多级排序,就像在 Stats.sort_stats 中一样。

在 3.13 版本加入: print_stats() 现在接受一个键的元组。

dump_stats(filename)

将当前分析的结果写入 filename

run(cmd)

通过 exec() 分析 cmd。

runctx(cmd, globals, locals)

通过 exec() 使用指定的全局和局部环境分析 cmd。

runcall(func, /, *args, **kwargs)

分析 func(*args, **kwargs)

请注意,只有当被调用的命令/函数实际返回时,分析才会起作用。如果解释器被终止(例如,在被调用的命令/函数执行期间通过 sys.exit() 调用),则不会打印任何分析结果。

Stats

分析器数据的分析是使用 Stats 类完成的。

class pstats.Stats(*filenames or profile, stream=sys.stdout)

这个类的构造函数从一个 filename(或文件名列表)或一个 Profile 实例创建一个“统计对象”的实例。输出将被打印到由 stream 指定的流中。

上述构造函数选择的文件必须是由相应版本的 profilecProfile 创建的。具体来说,与此分析器的未来版本保证文件兼容性,并且与其他分析器生成的文件或在不同操作系统上运行的相同分析器生成的文件不兼容。如果提供了多个文件,所有相同函数的统计数据将被合并,以便可以在一个报告中考虑多个进程的总体视图。如果需要将其他文件与现有 Stats 对象中的数据结合起来,可以使用 add() 方法。

除了从文件中读取分析数据,还可以使用 cProfile.Profileprofile.Profile 对象作为分析数据源。

Stats 对象有以下方法:

strip_dirs()

这个 Stats 类的方法会从文件名中移除所有前导路径信息。这在减少打印输出的大小以适应(接近)80列时非常有用。此方法会修改对象,被剥离的信息会丢失。执行剥离操作后,该对象的条目被认为处于“随机”顺序,就像对象初始化和加载后一样。如果 strip_dirs() 导致两个函数名无法区分(它们在同一文件的同一行,并且具有相同的函数名),那么这两个条目的统计数据将累积到一个条目中。

add(*filenames)

Stats 类的这个方法将额外的分析信息累积到当前的分析对象中。它的参数应该引用由相应版本的 profile.run()cProfile.run() 创建的文件名。对于同名(即文件、行号、名称相同)的函数的统计数据会自动累积到单个函数统计中。

dump_stats(filename)

将加载到 Stats 对象中的数据保存到名为 filename 的文件中。如果文件不存在,则创建该文件;如果文件已存在,则覆盖它。这与 profile.ProfilecProfile.Profile 类上的同名方法等效。

sort_stats(*keys)

此方法通过根据提供的标准对 Stats 对象进行排序来修改它。参数可以是字符串或 SortKey 枚举,用于标识排序的依据(例如:'time', 'name', SortKey.TIMESortKey.NAME)。SortKey 枚举参数比字符串参数的优势在于它更健壮且不易出错。

当提供多个键时,如果之前选择的所有键都相等,则使用附加键作为次要标准。例如,sort_stats(SortKey.NAME, SortKey.FILE) 将根据函数名对所有条目进行排序,并通过按文件名排序来解决所有平局(函数名相同的情况)。

对于字符串参数,任何键名都可以使用缩写,只要缩写是明确的。

以下是有效的字符串和 SortKey:

有效字符串参数

有效枚举参数

含义

'calls'

SortKey.CALLS

调用次数

'cumulative'

SortKey.CUMULATIVE

累积时间

'cumtime'

N/A

累积时间

'file'

N/A

文件名

'filename'

SortKey.FILENAME

文件名

'module'

N/A

文件名

'ncalls'

N/A

调用次数

'pcalls'

SortKey.PCALLS

原始调用次数

'line'

SortKey.LINE

行号

'name'

SortKey.NAME

函数名

'nfl'

SortKey.NFL

名称/文件/行

'stdname'

SortKey.STDNAME

标准名称

'time'

SortKey.TIME

内部时间

'tottime'

N/A

内部时间

请注意,所有统计数据的排序都是降序的(将耗时最多的项放在前面),而名称、文件和行号的搜索是升序的(按字母顺序)。SortKey.NFLSortKey.STDNAME 之间的细微区别在于,标准名称是按打印的名称排序,这意味着嵌入的行号会以一种奇怪的方式进行比较。例如,行 3、20 和 40(如果文件名相同)将以字符串顺序 20、3 和 40 出现。相比之下,SortKey.NFL 会对行号进行数字比较。实际上,sort_stats(SortKey.NFL)sort_stats(SortKey.NAME, SortKey.FILENAME, SortKey.LINE) 相同。

出于向后兼容性的原因,允许使用数字参数 -1012。它们分别被解释为 'stdname''calls''time''cumulative'。如果使用这种旧式格式(数字),则只会使用一个排序键(数字键),并且会静默忽略其他参数。

在 3.7 版本加入: 添加了 SortKey 枚举。

reverse_order()

这个 Stats 类的方法会反转对象内基本列表的顺序。请注意,默认情况下,升序与降序会根据所选的排序键正确选择。

print_stats(*restrictions)

Stats 类的这个方法会打印出 profile.run() 定义中描述的报告。

打印的顺序是基于对象上最后一次 sort_stats() 操作(受 add()strip_dirs() 中的注意事项限制)。

提供的参数(如果有)可用于将列表限制为重要的条目。最初,列表被视为已分析函数的完整集合。每个限制可以是整数(选择行数)、0.0 到 1.0 之间的小数(选择行百分比)或将被解释为正则表达式的字符串(用于模式匹配打印的标准名称)。如果提供了多个限制,则它们将按顺序应用。例如:

print_stats(.1, 'foo:')

将首先将打印限制为列表的前 10%,然后只打印属于文件名 .*foo: 的函数。相比之下,命令

print_stats('foo:', .1)

会将列表限制为所有文件名为 .*foo: 的函数,然后只打印其中的前 10%。

print_callers(*restrictions)

Stats 类的这个方法打印出分析数据库中每个函数的调用者列表。排序与 print_stats() 提供的相同,限制参数的定义也相同。每个调用者都在自己的行上报告。格式根据生成统计数据的分析器略有不同:

  • 使用 profile 时,每个调用者后面都会显示一个括号中的数字,以显示该特定调用被执行了多少次。为了方便,右侧会重复显示一个非括号中的数字,表示在该函数中花费的累积时间。

  • 使用 cProfile 时,每个调用者前面都有三个数字:此特定调用被执行的次数,以及当此特定调用者调用时,在当前函数中花费的总时间和累积时间。

print_callees(*restrictions)

Stats 类的这个方法会打印出被指定函数调用的所有函数的列表。除了调用方向相反(即:被调用 vs. 调用者),参数和排序与 print_callers() 方法相同。

get_stats_profile()

此方法返回一个 StatsProfile 的实例,其中包含函数名到 FunctionProfile 实例的映射。每个 FunctionProfile 实例都包含与函数分析相关的信息,例如函数运行了多长时间、被调用了多少次等。

在 3.9 版本加入: 添加了以下数据类:StatsProfile、FunctionProfile。添加了以下函数:get_stats_profile。

什么是确定性分析?

确定性分析 (Deterministic profiling) 旨在反映所有*函数调用*、*函数返回*和*异常*事件都被监控,并且对这些事件之间的间隔(用户代码执行期间)进行精确计时。相比之下,统计分析 (statistical profiling)(本模块未实现)会随机抽样有效的指令指针,并推断时间花费在哪里。后一种技术传统上开销较小(因为代码不需要被插桩),但只提供了时间花费的相对指示。

在 Python 中,由于在执行期间有一个活动的解释器,因此不需要插桩代码来进行确定性分析。Python 会自动为每个事件提供一个 钩子(可选的回调)。此外,Python 的解释性特性往往会给执行增加很多开销,以至于确定性分析在典型应用中通常只增加很小的处理开销。结果是确定性分析并不昂贵,却能提供关于 Python 程序执行的广泛运行时统计信息。

调用计数统计可用于识别代码中的错误(意外的计数),并识别可能的内联扩展点(高调用计数)。内部时间统计可用于识别应仔细优化的“热循环”。累积时间统计应用于识别算法选择中的高级错误。请注意,此分析器对累积时间的特殊处理允许将算法的递归实现的统计数据直接与迭代实现进行比较。

限制

一个限制与计时信息的准确性有关。确定性分析器在准确性方面存在一个根本性问题。最明显的限制是底层的“时钟”仅以(通常)约 0.001 秒的速率计时。因此,任何测量都不会比底层时钟更准确。如果进行足够多的测量,那么“误差”将趋于平均。不幸的是,消除这第一个误差会引入第二个误差源。

第二个问题是,从事件被分派到分析器调用获取时间*实际*获取时钟状态需要“一段时间”。类似地,从获取时钟值(然后保存起来)到用户代码再次执行,退出分析器事件处理程序时也存在一定的延迟。因此,被多次调用的函数或调用许多函数的函数通常会累积这种误差。以这种方式累积的误差通常小于时钟的精度(小于一个时钟滴答),但它*可以*累积并变得非常显著。

这个问题对于 profile 模块比对于开销更低的 cProfile 更为重要。因此,profile 提供了一种针对给定平台进行校准的方法,以便可以概率性地(平均而言)消除此误差。分析器校准后,它将更准确(在最小二乘意义上),但有时会产生负数(当调用次数异常低,且概率之神与你作对时 :-) )。不要对分析中的负数感到惊慌。它们*只有*在您校准了分析器后才应该出现,并且结果实际上比未校准时更好。

校准

profile 模块的分析器会从每个事件处理时间中减去一个常数,以补偿调用时间函数和存储结果的开销。默认情况下,该常数为 0。可以使用以下过程为给定平台获取一个更好的常数(参见 限制)。

import profile
pr = profile.Profile()
for i in range(5):
    print(pr.calibrate(10000))

该方法直接执行参数给定的 Python 调用次数,并在分析器下再次执行,测量两者的时间。然后它计算每个分析器事件的隐藏开销,并将其作为浮点数返回。例如,在运行 macOS 的 1.8GHz Intel Core i5 上,使用 Python 的 time.process_time() 作为计时器,这个神奇的数字大约是 4.04e-6。

这个练习的目的是得到一个相当一致的结果。如果你的计算机*非常*快,或者你的计时器函数分辨率很差,你可能需要传递 100000,甚至 1000000,才能得到一致的结果。

当您得到一个一致的答案时,有三种方式可以使用它:

import profile

# 1. Apply computed bias to all Profile instances created hereafter.
profile.Profile.bias = your_computed_bias

# 2. Apply computed bias to a specific Profile instance.
pr = profile.Profile()
pr.bias = your_computed_bias

# 3. Specify computed bias in instance constructor.
pr = profile.Profile(bias=your_computed_bias)

如果你有选择,最好选择一个较小的常数,这样你的结果在分析统计中显示为负数的可能性就会“更小”。

使用自定义计时器

如果你想改变确定当前时间的方式(例如,强制使用挂钟时间或经过的进程时间),请将你想要的计时函数传递给 Profile 类的构造函数:

pr = profile.Profile(your_time_func)

生成的分析器随后将调用 your_time_func。根据您使用的是 profile.Profile 还是 cProfile.Profileyour_time_func 的返回值将被不同地解释:

profile.Profile

your_time_func 应该返回一个单独的数字,或者一个其总和为当前时间的数字列表(就像 os.times() 返回的那样)。如果函数返回一个单独的时间数字,或者返回的数字列表长度为 2,那么你将得到一个特别快的调度例程版本。

请注意,你应该为你选择的计时器函数校准分析器类(参见 校准)。对于大多数机器,返回单个整数值的计时器在分析期间的低开销方面会提供最好的结果。(os.times() 相当糟糕,因为它返回一个浮点值的元组)。如果你想以最干净的方式替换一个更好的计时器,请派生一个类并硬编码一个最能处理你的计时器调用的替换调度方法,以及适当的校准常数。

cProfile.Profile

your_time_func 应该返回一个单独的数字。如果它返回整数,你还可以在调用类构造函数时使用第二个参数指定一个时间单位的实际持续时间。例如,如果 your_integer_time_func 返回以千分之一秒为单位测量的时间,你应该如下构造 Profile 实例:

pr = cProfile.Profile(your_integer_time_func, 0.001)

由于 cProfile.Profile 类无法校准,因此应谨慎使用自定义计时器函数,并应尽可能快。为了在使用自定义计时器时获得最佳结果,可能需要在内部 _lsprof 模块的 C 源代码中对其进行硬编码。

Python 3.3 在 time 模块中添加了几个新函数,可用于精确测量进程时间或挂钟时间。例如,参见 time.perf_counter()