cProfile放置在while循环内时耗时统计结果异常的原因

你遇到的是cProfile手动启停场景下的固有机制偏差，和业务循环逻辑本身无关，核心原因有两个：

• cProfile的统计时长仅覆盖探针开启状态下的CPU执行时间，探针自身的启停操作完全不纳入统计
  你把prof.enable()、prof.disable()放在while循环内部时，每轮迭代都会触发两次探针管理操作：enable()负责给当前线程挂载栈追踪钩子、初始化本轮计时基准；disable()负责卸载追踪钩子、把本轮统计数据合并到全局统计池。这两个操作本身是在探针关闭状态下执行的，耗时完全不会被计入最终的统计结果。当循环迭代次数达到1000次量级时，反复挂载卸载钩子、合并统计结构的累计开销非常高，你测得的7.3s是程序跑完的完整墙钟时间，其中已经包含了这部分额外开销。
• 探针常开状态下的自身追踪开销，在高频启停场景下会被大幅压缩
  当你把探针放在整个循环外侧常开时，探针钩子会拦截所有函数调用、循环跳转、返回操作，每一次拦截都会执行计时、计数、更新统计哈希表的逻辑，这部分探针自身的运行开销会被全程统计进最终时长。两层嵌套的CPU密集型循环会触发天量的跳转/调用事件，常开状态下探针的自开销甚至能占到总统计时长的一半以上。
  而循环内反复启停时，enable()会重置单轮的栈追踪缓存，探针只追踪当前轮次的调用事件，不会累积跨轮次的栈追踪冗余；同时探针关闭间隙的所有解释器调度操作都不会触发钩子，这部分省下来的探针自开销，加上启停操作本身不计入统计，最终就会出现统计时长远低于墙钟时长、但函数调用计数基本一致的现象。

你提到的「单轮3s则2轮就到7s」的推断不成立：3.032s是1000轮迭代中所有被探针捕获的业务逻辑执行时间的累计值，不是单轮耗时。这个认知偏差的本质是把探针输出的追踪范围内CPU时间和现实流逝的墙钟时间划了等号——只要存在探针不覆盖的执行段、探针自身有额外开销，这两个值本来就不会相等。

你可以跑两个对照测试确认机制：

1. 在两组测试的代码首尾都加time.perf_counter()打墙钟时间，你会发现两组的实际墙钟耗时非常接近，循环内启停的第二组甚至会因为千次探针启停操作，墙钟耗时比第一组更高。
2. 把第二组测试的while循环改成只跑1轮就退出，你会看到统计总时长约为3ms，乘以1000轮刚好和你看到的3.032s匹配。

• 如果需要统计整段逻辑的性能分布，不要在高频循环内部反复启停cProfile，直接把待统计的完整逻辑包在一对enable()/disable()外侧即可，避免额外启停开销和统计偏差。
• 如果确实需要分段统计不同代码块的耗时，不要用循环内手动启停的方案，改用@prof.profile()装饰器包裹待统计的目标函数，或者统计完成后用pstats模块按函数、行号维度过滤结果，准确性远高于手动高频启停。

内容的提问来源于stack exchange，提问作者Lost