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 对象,并将结果打印到标准输出。

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'

不适用

累积时间

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