[Python] Why does tqdm mess up cProfile output?

When profiling some Python code, I've been frustrated by functions like threading.py:637(wait) appearing high in cProfile output instead of the hot functions I want to see. After some tests I realized that the problem is that I've been using tqdm to monitor the overall progress of the program. Here is a minimal example:

test.py:

from tqdm.auto import tqdm

def test():
for i in tqdm(range(100000)):
for j in range(10000):
pass

test()


In the shell:

% 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>)


As can be seen, some threading-related functions are appearing high, and my main function test didn't get credited for all the time it has taken.

My questions are:

1. Why does this happen? I've read that Python 3.12 has changed how profiling works, so is this problem new in Python 3.12?
2. Is there a workaround that still allows me to visually see the progress while profiling?

Continue reading...