cProfile 的 cumtime 包含子调用耗时,tottime 排除子调用。累计时间最高的外层函数,可能只是在组织一条慢链路;应先展开被调用者,再判断计算、等待和重复调用。定位工具的报告也不能直接当成优化后的基准成绩。
下面是教学模拟。
面试官:Python 程序慢,你先改哪个函数?
我:cProfile 按 cumtime 排序,第一名最该重写。
面试官:它只调用一个计算函数,再等一个外部结果呢?
我:把父函数和子函数耗时加起来比较。
面试官:同一段执行时间,是不是算了两遍?
tottime 与 cumtime,应该怎样读?
Python 3.11 分析器文档说明了调用次数、自身时间和累计时间。用外层 job 调用 compute、随后休眠的关系理解会更直观。
| 报告对象 | 自身时间的含义 | 累计时间的含义 |
|---|---|---|
| job | 自己组织流程的时间 | 包括 compute 与休眠等子调用 |
| compute | 排除其子调用后的时间 | 包括内部求和等调用 |
| sleep | 该调用在分析器中的计时 | 不能直接当作 CPU 忙碌时间 |
父子累计时间存在包含关系,不能逐行相加作为任务总时长。还要看 ncalls;单次很便宜的操作被反复执行,也可能值得优化。
一个可以实际运行的 Python 例子
这是 Python 标准库 cProfile 专属示例,用休眠演示等待,不连接真实远程接口。
importcProfileimportpstatsfromtimeimportsleepdefcompute():returnsum(i*iforiinrange(10000))defjob():value=compute()sleep(0.03)returnvaluewithcProfile.Profile()asprofiler:result=job()assertresult==333283335000pstats.Stats(profiler).strip_dirs().sort_stats("cumulative").print_stats(8)2026 年 11 月 1 日,在本机 macOS 26.5 arm64、CPython 3.11.0 环境运行,返回值断言通过。报告显示 job 的 cumtime 包含休眠,其 tottime 明显更小;另行读取同一示例的统计结构,也确认了这组包含关系。这里关注字段含义,没有用本机耗时给出通用性能结论。
墙钟时间很长,CPU 为什么可能并不忙?
Python 时间接口文档区分经过时间与进程 CPU 时间。perf_counter 的差值包含休眠等经过时间,process_time 统计当前进程消耗的用户态与系统态 CPU 时间,不包含休眠经过的时间。
因此,调用链耗时高而 CPU 消耗低时,应继续寻找等待对象。真实服务可能在等网络、数据库、锁或任务调度;上面这个 sleep 例子只展示计时区别,不能定位真实服务的等待原因。
多进程时,一个进程的数值不代表所有 worker。异步任务和线程也需要明确观测范围,不能把当前报告扩大为整个系统的时间线。
为什么不能拿分析报告直接宣布快了?
分析器会增加开销。官方文档将执行分析与基准测试区分开,尤其不能忽略不同实现受到分析开销的差别。
改动后应脱离分析器,用同一任务独立比较。固定输入量、冷热状态和依赖条件,检查结果正确,再看多次运行的耗时分布。旧版本冷启动、新版本预热后运行,不是公平比较。
如果真正减少的是远程请求次数,就记录请求量与等待变化;如果减少的是重复计算,就确认缓存命中条件和结果仍然正确。能说清省掉了什么工作,才方便解释收益与适用范围。
本文的标准库例子不构成接口压测或性能优化效果实验。完整排查方法见 Python 程序运行慢怎么排查?cProfile 如何区分热点函数和等待时间?。