joerick/pyinstrument

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.

if not frame.is_synthetic:

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.