相同的 Python 代码似乎具有不同的性能特征

Posted 2023-03-06

【中文标题】相同的 Python 代码似乎具有不同的性能特征

【英文标题】：Same Python code appears to have different performance characteristics

【发布时间】：2020-05-28 05:52:34

【问题描述】：

说明

在我创建N 长度为k 的随机字符串的代码中，用于创建随机k 字符串的生成器表达式被调用N+1 或(N+1)*k（又名N*k+N）次。这似乎发生在exact same code 上，我可以通过重新定义chrs() 辅助函数来看似不确定地来回切换。我怀疑分析器，但对机制没有任何线索。

系统详细信息，以防万一：HP Envy 15k (i7-4720) 上的 Ubuntu 18.04 上的 CPython、Python 2.7.17 和 Python 3.6.9

重现问题

不是正确的 MCVE，因为我无法确定性地重现该问题；相反，运行它有望导致以下两个分析器输出之一。如果您尝试在 REPL 中运行它并使用相同的代码重复重新定义 chrs() 函数，您可能能够获得两个分析器输出。

我在对各种生成N (num_strings) 长度为k (len_string) 的随机字符串的方法进行基准测试时编写了这个bits_strings() 函数：

import cProfile
import random
import string

def chrs(bits, len_string):
    return ''.join(chr((bits >> (8*x)) & 0xff) for x in range(len_string))

def bits_strings(num_strings, len_string):
    return list(
        chrs(random.getrandbits(len_string*8), len_string)
        for x in range(num_strings)
    )

cProfile.run('bits_strings(1000, 2000)')

为了对其进行基准测试，我使用了cProfile.run()。

当我第一次运行代码时，它看起来相当快：

cProfile.run('bits_strings(1000, 2000)')
         2005005 function calls in 0.368 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.970    1.970 <stdin>:1(bits_strings)
     1000    0.001    0.000    1.963    0.002 <stdin>:1(chrs)
     1001    0.001    0.000    1.970    0.002 <stdin>:2(<genexpr>)
        1    0.000    0.000    1.970    1.970 <string>:1(<module>)
  2000000    0.173    0.000    0.173    0.000 chr
        1    0.000    0.000    0.000    0.000 method 'disable' of '_lsprof.Profiler' objects
     1000    0.005    0.000    0.005    0.000 method 'getrandbits' of '_random.Random' objects
     1000    0.178    0.000    1.953    0.002 method 'join' of 'str' objects
     1001    0.009    0.000    0.009    0.000 range

但在当天晚些时候：

cProfile.run('bits_strings(1000, 2000)')

         4005004 function calls in 1.960 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.961    1.961 <stdin>:1(bits_strings)
     1000    0.001    0.000    1.954    0.002 <stdin>:1(chrs)
  2001000    1.593    0.000    1.762    0.000 <stdin>:2(<genexpr>)
        1    0.000    0.000    1.961    1.961 <string>:1(<module>)
  2000000    0.170    0.000    0.170    0.000 chr
        1    0.000    0.000    0.000    0.000 method 'disable' of '_lsprof.Profiler' objects
     1000    0.005    0.000    0.005    0.000 method 'getrandbits' of '_random.Random' objects
     1000    0.182    0.000    1.944    0.002 method 'join' of 'str' objects
     1001    0.009    0.000    0.009    0.000 range

区别似乎来自<genexpr>，它来自cumtime 和各种类似测试的位置，我推断是chrs() 中的那个。 （我的直觉是 (chr((bits >> (8*x)) & 0xff) for x in range(len_string)) 应该被称为 N 次，而 chr((bits >> (8*x)) & 0xff) 应该被称为 N*k 次）。

那么这两个bits_strings() 函数有什么区别呢？当试图找到两次尝试之间的代码差异时，我没有找到。事实上，我有一个 Python REPL 会话，我在其中定义了函数，运行分析器两次（第二次，检查这是否是缓存问题），然后使用向上箭头重新定义函数以检索我的之前输入的代码。它表现出相同的分歧：https://pastebin.com/1u1j1ZUt

理论与思想

我怀疑 cProfile。

通过重新定义chrs() 在“快”和“慢”版本之间切换，但cProfile.run() 由cProfile.run() 配置。根据外部cProfile.run() 的报告，在观察到的时间和中，看起来内部cProfile.run()（配置文件bits_strings()）偶尔少报bits_strings() 需要多长时间： https://pastebin.com/C4W4FEjJ

我还在cProfile.run('bits_strings(1000,1000)) 调用之前/之后使用了time.time()，并注意到“快速”配置文件cumtime 与运行该方法时所用的实际挂钟时间之间存在差异。

但我仍然不清楚机制。

缓存：相同的代码，运行之间截然不同的性能可能是缓存的事情。然而，快速版本是我第一次运行这段代码（尽管我之前在同一个 REPL 会话中运行过其他代码）。我可以通过简单地重新定义chrs() 和bits_strings() 从慢到快或从快到慢切换，尽管我是否真的切换似乎是随机的。另外值得注意的是，我只能通过重新定义函数来切换（afaict），而不是简单地重新运行它们。所以我不确定 什么 会被缓存，或者它会如何在重新定义函数时将<genexpr> 调用的数量更改为k。

cProfile 怪癖：我在没有cProfile.run() 的情况下运行相同的代码，并通过两次将当前的time.time() 放入bits_strings 来对其进行计时；对于慢速情况，总时间与cProfile.run() 相当。所以cProfile.run() 至少不会减慢速度。快速结果有可能被cProfile.run(), 污染，但有趣的是N 和k ((10000, 10000)) 的大值我注意到bits_strings() 的第一次运行之间存在明显差异以及当天晚些时候的缓慢的。

解释器怪癖：我认为这可能是因为解释器错误地优化了 chrs() 和 bits_strings() 中的生成器表达式，但这是你付钱给你- 编写 CPython 解释器，这似乎不太可能。

Python 2.7 怪癖：重新定义 chrs()（使用向上箭头检索先前的定义）不一致地在 python3 中执行相同的技巧：https://pastebin.com/Uw7PgF7i

Zalgo 为我使用正则表达式解析 HTML 的那一次报复：不排除

我很想相信bits_strings()，在不同的时间（相同函数的不同定义，相同的代码，不同的运行），实际上表现不同。但我不知道为什么会这样。我怀疑这与chrs() 的关系比与bits_strings() 的关系更密切。

我不清楚为什么重新定义 chrs() 似乎会不可预测地影响分析器输出。

【问题讨论】：

奇怪...“2005005 个函数在 0.368 秒内调用”摘要行看起来很快，但如果您检查 cumtime 列，总执行时间似乎在 1.970 秒左右。

哦，哇，感谢您注意到这一点。我检查了我的 REPL 日志，这不是错误粘贴，所以看起来除了 <genexpr> 调用的令人困惑的行为之外，cProfile 中的摘要和 cumtime 中可能存在报告错误（或非常令人困惑的 WAI 行为） .看起来也发生在pastebin 中。也许cProfile 不知何故忘记了N*k <genexpr> 的电话？它可能只跟踪<genexpr> 的外部部分（“生成N 随机字符串”部分）并以某种方式在其报告中删除“生成1 k-长度字符串”部分。

我怀疑 cProfile 被两个具有完全相同文件名和 lineno 的 genexp 弄糊涂了。 2001000 是 chrs 中的 genexp 的编号（每个生成器重新进入都算作一次调用），而 1001 是 bits_strings 中的 genexp 的编号。报告中只显示了一个生成器。

对我来说似乎是最有可能的解释。您对如何确定性地重现该问题有任何想法吗？希望验证并希望将此问题标记为已回答。

查看 cProfile 源代码，结果似乎取决于代码对象的内存地址，因此重现它的最佳方法似乎是继续重新定义函数，直到结果发生变化。

【参考方案1】：

这是 cProfile 结果报告的一个工件，它无法区分具有相同名称、文件名和行号的两个代码对象。

在收集统计信息时，统计信息保存在 randomly-rebalancing binary search tree 中，显然是随机展开树的变体。 Code object memory addresses are used as keys 用于 Python 函数（以及 PyMethodDef 内存地址用于 C 函数）。

但是，当分析完成时，数据是reorganized 到一个字典中，使用（文件名、行号、代码对象名）元组作为 Python 函数的键。如果这些键不是唯一的，例如您的示例，这会丢失信息。在这种情况下，具有最高内存地址的代码对象最后被处理，因此该代码对象的统计信息出现在结果字典中。

---

在您的测试中，您会看到 chrs 中的 genexp 或 bits_strings 中的 genexp 的统计信息。您看到的统计信息取决于哪个 genexp 的代码对象具有更高的内存地址。

如果您将代码作为脚本而不是交互方式运行，则可以通过行号区分 genexp，并且两个 genexp 都会出现在结果中。交互模式为交互输入的每个“单元”代码重新启动行号（一个>>> 提示和所有后续... 提示）。但是，在某些情况下，此分析工件会以非交互方式发生，例如同一行上有两个 genexp，或具有相同名称的两个文件。