Why is pstats.print_callers() ignores the restriction argument?

Question

I'm trying to profile my python script using cProfile and displaying the results with pstats. In particular, I'm trying to use the pstats function p.sort_stats('time').print_callers(20) to print only the top 20 functions by time, as decribed in the documentation.

I expect to get only the top 20 results (functions profiled and their calling functions ordered by time), instead, I get a seemingly unfiltered list of over 1000 functions that completely saturates my terminal (hence I'm estimating over a 1000 functions).

Why is my restriction argument (i.e. 20) being ignored by print_callers() and how can I fix this?

I've tried looking up an answer and couldn't find one. And I tried to create a minimal reproducible example, but when I do, I can't reproduce the problem (i.e. it works fine).

my profiling code is:

import cProfile
import pstats

if __name__ == '__main__':
    cProfile.run('main()', 'mystats')
    p = pstats.Stats('mystats')
    p.sort_stats('time').print_callers(20)

I'm trying to avoid having to post my full code, so if someone else has encountered this issue before, and can answer without seeing my full code, that would be great.

Thank you very much in advance.

Edit 1: Partial output:

  Ordered by: internal time
   List reduced from 1430 to 1 due to restriction <1>

Function                               was called by...
                                           ncalls  tottime  cumtime
{built-in method builtins.isinstance}  <-    2237    0.000    0.000  <frozen importlib._bootstrap>:997(_handle_fromlist)
                                                9    0.000    0.000  <frozen importlib._bootstrap_external>:485(_compile_bytecode)
                                               44    0.000    0.000  <frozen importlib._bootstrap_external>:1117(_get_spec)
                                             4872    0.001    0.001  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\_strptime.py:321(_strptime)
                                                5    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\abc.py:196(__subclasscheck__)
                                               26    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\calendar.py:58(__getitem__)
                                               14    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\calendar.py:77(__getitem__)
                                                2    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\distutils\version.py:331(_cmp)
                                               20    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\enum.py:797(__or__)
                                              362    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\enum.py:803(__and__)
                                                1    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\inspect.py:73(isclass)
                                               30    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\json\encoder.py:182(encode)
                                                2    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\ntpath.py:34(_get_bothseps)
                                                1    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\ntpath.py:75(join)
                                                4    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\ntpath.py:122(splitdrive)
                                                3    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\ntpath.py:309(expanduser)
                                                4    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\os.py:728(check_str)
                                               44    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\re.py:249(escape)
                                                4    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\re.py:286(_compile)
                                              609    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\dateutil\parser\_parser.py:62(__init__)
                                             1222    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\numpy\core\_methods.py:48(_count_reduce_items)
                                             1222    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\numpy\core\_methods.py:58(_mean)
                                                1    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\numpy\core\arrayprint.py:834(__init__)
                                             1393    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\numpy\core\fromnumeric.py:1583(ravel)
                                             1239    0.000    0.000  C:\Users\rafael.natan\AppData\Local\Continuum\anaconda3\lib\site-packages\numpy\core\fromnumeric.py:1966(sum)
...

@kkawabat, I've added the output. But I think I figured it out. I'll add it in an answer. But thank you very much for your time. — Elegant Code, Nov 15 '19 at 18:45

score 4 · Accepted Answer · answered Nov 15 '19 at 18:58

I figured out the issue. As usual, the Python Library does not have a bug, rather, I misunderstood the output of the function call.

I'm elaborating it here as an answer in case it helps anyone clear up this misunderstanding in the future.

When I asked the question, I didn't understand why p.print_callers(20) prints out to terminal over a thousand lines, even though I am restricting it to the top 20 function calls (by time).

What is actually happening is that my restriction of printing the top 20 "most time consuming functions", restricts the list to the top 20 functions, but then prints a list of all the functions that called each of the top twenty functions.

Since each of the top 20 functions was called (on average) by about 100 different functions each one of the top functions, had about 100 lines associated with it. so 20*100=2000, and so p.print_callers(20) printed well over a 1000 lines and saturated my terminal.

I hope this saves someone some time and debugging headache :)

So what's the proper way to limit the output to 20 heaviest hitters? — Marcin, Mar 06 '23 at 23:22
Hi @Marcin, It's been a long while since I did this so I don't remember. But my best advice now, would be to start with perhaps `p.print_callers(5)` and just be aware of how to read the output, to know which line represents the top calling functions and which is not. — Elegant Code, Mar 09 '23 at 15:46

Why is pstats.print_callers() ignores the restriction argument?

1 Answers1