
程序刚启动就慢,给 import json 前后套一层计时,拿到的却是整个依赖导入链的时间。CPython 自带的 -X importtime 把这条链拆成两列:self 看当前模块,cumulative 把它导入的下游也算进去。字段名相近,统计边界不同。
同一份输出,两种范围
本机用 python3 -X importtime -c 'import json' 跑了一次。系统里的 python3 是 3.9.6;下表数字来自这次 stderr 输出,单位是微秒。
| 模块 | self | cumulative | 读法 |
|---|---|---|---|
_json |
366 | 366 | C 扩展模块没有在此处再列出子导入 |
json.decoder |
353 | 6024 | 自己用 353,连同下游共 6024 |
json.encoder |
376 | 376 | 两列一致 |
json |
514 | 6914 | 模块本身 514,整条导入链 6914 |
python3 tools/verify-py-importtime-tree.py 2> tools/verify-py-importtime-tree.log
import time: 366 | 366 | _json
import time: 353 | 6024 | json.decoder
import time: 376 | 376 | json.encoder
import time: 514 | 6914 | json
json.decoder 的累计值已经覆盖了它导入的模块;json 的累计值又覆盖整棵树。把 6024 和 6914 再相加,会把同一批下游重复记账。self 则更适合找模块自身的初始化成本,但它不等于进程启动总耗时。
作为排查入口时,先用原项目的启动命令运行带开关的解释器,再沿累计值检查分支。-c 'import json' 只是一个小型复现实验,说明这里演示的是标准库的导入,不代表任何具体应用的启动耗时。若入口需要脚本参数,保留原有参数,避免把参数解析路径也换掉。
按累计值往下找
排序时先看根模块的 cumulative,再沿缩进往下找累计值较大的分支。表格里 json.decoder 占了 json 累计值的大头,是这次输出里值得继续看的位置;这并不等于 decoder 自己执行了 7182 微秒。它自身只占 393 微秒,其余落在下游导入上。
这种读法也能帮助判断「换包」值不值得做。若某个子模块的累计值大,却自身 self 很小,优化对象可能在它依赖的另一层;若 self 高、累计值只略高一点,才更像模块自己的初始化工作。表里的 json.encoder 两列都是 373,正好是个范围相同的例子。不能因此推断所有模块都会两列相等,只能说这行没有列出额外的累计导入时间。
显示的缩进是导入关系,不是调用栈。对同名模块多次导入时,缓存也会影响后续观察;一次跟踪适合定位候选,不适合当成稳定的启动基准。需要比较改动时,保持解释器和运行环境不变,分开记录每次结果,再单独测完整进程启动时间。文件系统缓存、机器负载都可能让单次微秒值浮动,不能把某一轮的差异直接当成优化收益。
默认跟踪信息写到标准错误,程序正常结果仍能留在标准输出;把两条流分开保存,定位时不必将诊断行和应用输出混在一起。这里的脚本把 stderr 重定向到 log,打开文件便能对照模块名和数字。记录的微秒是该次运行的证据,不是下次运行的承诺。
另一个容易误判的地方是把 self 当作「纯 Python 代码执行时间」。这项统计的是该模块自身导入阶段的时间,不会替程序后续执行计时。-X importtime 只回答导入阶段的问题;如果慢点在配置读取、网络访问或应用初始化,输出里不会替这些阶段背书。
我会先用它缩小导入链的范围,不会只看一轮输出就据此删依赖。这个开关的价值是指出哪里值得继续测,不是把一列微秒直接换算成应用的冷启动成绩。