tqdm干扰cProfile输出的原因及兼容可视化进度的性能分析方案咨询
tqdm干扰cProfile输出的原因及兼容可视化进度的性能分析方案咨询
最近用cProfile分析Python代码时快愁死了——我本来想盯着自己写的核心函数的性能开销,结果cProfile的输出里排最前面的全是threading.py:637(wait)这类线程相关的函数,而我真正关心的test函数,本该占绝大多数运行时间,结果统计出来的时间少得离谱。
后来反复测试才发现,问题出在我用来监控程序整体进度的tqdm上。下面是我复现这个问题的最小示例:
测试代码(test.py)
from tqdm.auto import tqdm def test(): for i in tqdm(range(100000)): for j in range(10000): pass test()
执行性能分析的命令及输出
在终端里执行这条命令:
python3 -m cProfile test.py | head -n 20
得到的输出是:
100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 100000/100000 [00:24<00:00, 4027.92it/s] 358918 function calls (357823 primitive calls) in 25.003 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 3/2 0.000 0.000 20.019 10.009 threading.py:637(wait) 3/2 0.000 0.000 20.019 10.009 threading.py:323(wait) 18/12 19.885 1.105 20.018 1.668 {method 'acquire' of '_thread.lock' objects} 79/1 0.001 0.000 4.811 4.811 {built-in method builtins.exec} 2/1 0.000 0.000 4.811 4.811 test.py:1(<module>) 2/1 4.785 2.392 4.811 4.811 test.py:3(test) 104/5 0.001 0.000 0.172 0.034 <frozen importlib._bootstrap>:1349(_find_and_load) 104/5 0.001 0.000 0.171 0.034 <frozen importlib._bootstrap>:1304(_find_and_load_unlocked) 103/6 0.001 0.000 0.170 0.028 <frozen importlib._bootstrap>:911(_load_unlocked) 77/5 0.001 0.000 0.168 0.034 <frozen importlib._bootstrap_external>:988(exec_module) 256/12 0.001 0.000 0.168 0.014 <frozen importlib._bootstrap>:480(_call_with_frames_removed) 100001 0.054 0.000 0.157 0.000 std.py:1161(__iter__) 6 0.000 0.000 0.153 0.025 __init__.py:1(<module>) 238 0.003 0.000 0.100 0.000 std.py:1199(update) 1 0.000 0.000 0.097 0.097 auto.py:1(<module>)
从输出里能清楚看到,线程相关的函数占了近20秒的累计时间,而我的核心test函数只被统计到了不到5秒,这明显不符合实际情况。
我现在有两个问题想请教各位:
- 为什么tqdm会导致cProfile的统计结果失真?我听说Python 3.12改动了profiling的实现逻辑,这个问题是Python 3.12特有的吗?
- 有没有什么办法能两全其美——既能保留tqdm的可视化进度条,又能得到准确的性能分析结果?
备注:内容来源于stack exchange,提问作者Imperishable Night
相关产品推荐
相关产品推荐

