pstats renderer total time
sbalian opened this issue · 4 comments
The sum of tottime
for all functions from the pstats output correctly matches the total time displayed in the header of print_stats()
when using the pstats
module. However, this does not match the duration shown in the HTML output (it is about twice longer). Is this expected? How much should I trust tottime
in a pstats output? I tested with both async mode on and off.
Hm, it does look like a bug in the pstats renderer. My recreation is like so:
$ pyinstrument examples/busy_wait.py
_ ._ __/__ _ _ _ _ _/_ Recorded: 15:37:52 Samples: 250
/_//_/// /_\ / //_// / //_'/ // Duration: 0.251 CPU time: 0.251
/ _/ v4.6.0
Program: /Users/joerick/Projects/pyinstrument/env/bin/pyinstrument examples/busy_wait.py
0.250 <module> busy_wait.py:1
└─ 0.250 main busy_wait.py:12
├─ 0.137 [self] busy_wait.py
├─ 0.042 function_2 busy_wait.py:8
├─ 0.036 time <built-in>
└─ 0.035 function_1 busy_wait.py:4
To view this report with different options, run:
pyinstrument --load-prev 2024-01-06T15-37-52 [options]
$ pyinstrument -o test.pstats -r pstats examples/busy_wait.py
$ python -c "import pstats; pstats.Stats('test.pstats').print_stats()"
Sat Jan 6 15:37:59 2024 test.pstats
-6 function calls in 0.391 seconds
Random listing order was used
ncalls tottime percall cumtime percall filename:lineno(function)
-1 0.000 -0.000 0.250 -0.250 examples/busy_wait.py:1(<module>)
-1 0.141 -0.141 0.250 -0.250 examples/busy_wait.py:12(main)
-1 0.141 -0.141 0.141 -0.141 :0([self])
-1 0.040 -0.040 0.040 -0.040 examples/busy_wait.py:4(function_1)
-1 0.037 -0.037 0.037 -0.037 <built-in>:0(time)
-1 0.032 -0.032 0.032 -0.032 examples/busy_wait.py:8(function_2)
$ python -c 'print(0.141 + 0.141 + 0.040 + 0.037 + 0.032)'
0.3909999999999999
That should be 0.250.
I think the problem is probably the [self]
frame, which shouldn't be printed here, as it's an implementation detail of pyinstrument that doesn't exist in the pstats format. It should be simple to just exclude synthetic frames from the algorithm.
That's weird, it does that already.
So why is it appearing here I wonder...
Ah, that line should read if not child.is_synthetic:
, it's testing the wrong thing.
Thanks for looking into this! When do you think you'll make a new release that includes this fix? Happy to use it from the repo in the meantime.