2

I am profiling my python code using Spyder IDE.

As you can see in the screenshot below, it took 1.20 min = 80 sec for the _get_loglik_seq function to execute. However, the timing of various functions/procedures that constitutes this function are the following: solve_EV = 29.78s, c_get_gamma = 10.12 sec, norm = 6.57 sec, outer = 4.70 sec, <method dot ...: 2.17 sec, all others: <1 sec.

If one sums up these times, the result will be about 54 s, which is way smaller than 80s.

How is it possible? Is it a profiler bug or did I miss something? Can anyone suggest a good tool for Python code profiling? (I am working on Mac OS)

Thanks, Mikhail

enter image description here

Mikhail Genkin
  • 3,247
  • 4
  • 27
  • 47

1 Answers1

4

The reason is the following:

Total time = execution time of the function, including all the sub-functions.

Local time = execution time of the function without it's sub-functions.

Therefore, if a function p calls subfunctions s1, s2, s3, then:

ToTtime(p)=ToTtime(s1)+ToTtime(s2)+ToTtime(s3)+Localtime(p),

which approximately holds.

Mikhail Genkin
  • 3,247
  • 4
  • 27
  • 47
  • But then how can I know which subfunctions are responsible for the total time, i.e. how do I to find out why the execution time of a function (including all sub-functions) is of a certain duration? – timmey Sep 29 '20 at 12:16
  • 1
    @timmey spyder's profile gives you the running time of all the functions that are called from the script. If you want further insights, you can measure the execution time of each line of your code using lineprofiler https://stackoverflow.com/questions/22328183/python-line-profiler-code-example – Mikhail Genkin Sep 29 '20 at 14:57
  • Thanks! But, and sorry that I am so obtuse, in the above example, the total time of '_get_loglik_seq' 80secs >> 70secs (sum of local time of '_get_loglik_seq' and total time of all sub-functions of '_get_loglik_seq'). Where is the lost time? – timmey Sep 30 '20 at 08:49
  • 1
    I think it should be ToTtime(p)=ToTtime(s1)+ToTtime(s2)+ToTtime(s3)+Localtime(p) (the arguments in the answer are s1, s1,s1 instead of s1,s2,s3) – timmey Sep 30 '20 at 08:50
  • 1
    @timmey thanks, I've fixed these typos. Regarding your previous comment, 1.20 min = 60 s * 1.20 = 72 seconds. Which is almost equal to the sum. The sum is a bit less, though. 1.20 min is not 80 seconds – Mikhail Genkin Oct 01 '20 at 21:28
  • Thanks! Of course 1.20min is not 80s. Rookie mistake. – timmey Oct 02 '20 at 11:44