Python 性能分析器

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


性能分析器简介

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

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

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

  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 个是原始的,这意味着调用不是通过递归引起的。 下一行: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 将分析结果写入文件而不是标准输出

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

-m 指定正在分析的是模块而不是脚本。

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%(关于 .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 对象并将结果打印到标准输出。

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'

不适用

累计时间

'file'

不适用

文件名

'filename'

SortKey.FILENAME

文件名

'module'

不适用

文件名

'ncalls'

不适用

调用次数

'pcalls'

SortKey.PCALLS

原始调用次数

'line'

SortKey.LINE

行号

'name'

SortKey.NAME

函数名称

'nfl'

SortKey.NFL

名称/文件/行

'stdname'

SortKey.STDNAME

标准名称

'time'

SortKey.TIME

内部时间

'tottime'

不适用

内部时间

请注意,所有统计数据的排序均按降序排列(将最耗时的项目放在首位),而名称、文件和行号搜索则按升序排列(按字母顺序)。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 类的此方法打印由指定函数调用的所有函数的列表。除了调用方向的反转(关于:调用与被调用)之外,参数和顺序与 print_callers() 方法相同。

get_stats_profile()

此方法返回 StatsProfile 的实例,其中包含函数名称到 FunctionProfile 实例的映射。每个 FunctionProfile 实例都包含与函数配置文件相关的信息,例如函数运行所需的时间、调用次数等。

3.9 版中的新内容: 添加了以下数据类:StatsProfile、FunctionProfile。添加了以下函数:get_stats_profile。

什么是确定性分析?

确定性分析旨在反映所有函数调用函数返回异常事件都被监控,并且对这些事件之间的间隔(在此期间用户代码正在执行)进行精确计时。相比之下,统计分析(不是由该模块完成)随机抽取有效指令指针,并推断出时间花费在哪里。后一种技术传统上开销较小(因为代码不需要插桩),但只能提供时间花费在哪里的相对指示。

在 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()