Understanding Pycharm's profiler's results vs. cProfile results and how to get more detail on standard library functions

Question

I am working on driving down the execution time on a program I've refactored, and I'm having trouble understanding the profiler output in PyCharm and how it relates to the output I would get if I run cProfile directly. (My output is shown below, with two lines of interest highlighted that I want to be sure I understand correctly before attempting to make fixes.) In particular, what do the Time and Own Time columns represent? I am guessing Own Time is the time consumed by the function, minus the time of any other calls made within that function, and time is the total time spent in each function (i.e. they just renamed tottime and cumtime, respectively), but I can't find anything that documents that clearly.

Also, what can I do to find more information about a particularly costly function using either PyCharm's profiler or vanilla cProfile? For example, _strptime seems to be costing me a lot of time, but I know it is being used in four different functions in my code. I'd like to see a breakdown of how those 2 million calls are spread across my various functions. I'm guessing there's a disproportionate number in the calc_near_geo_size_and_latency function, but I'd like more proof of that before I go rewriting code. (I realize that I could just profile the functions individually and compare, but I'm hoping for something more concise.)

I'm using Python 3.6 and PyCharm Professional 2018.3.

Arriola

For the second part (breakdown of how the calls are spread across the various functions), I've had good results with the pyinstrument package, since it records the entire call stack and shows the profiling output in an easy to use format. – Splice

Answer 1

In particular, what do the Time and Own Time columns represent? I am guessing Own Time is the time consumed by the function, minus the time of any other calls made within that function, and time is the total time spent in each function (i.e. they just renamed tottime and cumtime, respectively), but I can't find anything that documents that clearly.

You can see definitions of own time and time here: https://www.jetbrains.com/help/profiler/Reference__Dialog_Boxes__Properties.html

Own time - Own execution time of the chosen function. The percentage of own time spent in this call related to overall time spent in this call in the parentheses.

Time - Execution time of the chosen function plus all time taken by functions called by this function. The percentage of time spent in this call related to time spent in all calls in the parentheses.

This is also confirmed by a small test:

Also, what can I do to find more information about a particularly costly function using either PyCharm's profiler or vanilla cProfile?

By default pycharm does use cProfile as a profiler. Perhaps you're asking about using cProfile on the command line? There are plenty of examples of doing so here: https://docs.python.org/3.6/library/profile.html

For example, _strptime seems to be costing me a lot of time, but I know it is being used in four different functions in my code. I'd like to see a breakdown of how those 2 million calls are spread across my various functions.

Note that the act of measuring something will have an impact on the measurement retrieved. For a function or method that is called many times, especially 2 million, the profiler itself will have a significant impact on the measured value.

Prospector

Thank you this was quite helpful, but just to clarify "own time" it simply means how much time was spent inside takes_one_second() vs. how much time takes_one_second() took calling takes_two_seconds()? – Leannleanna

The sentences which describe what Own Time is vs Time are ambiguous. I can only have an idea of what it means, but because the meaning of the sentence is so open, I must keep researching to be sure. – Molloy