Internal timings are not correctly attributed to the function call statements

[dshivashankar1994]

Notice that the function calls a() (line 8) or b() (line 10) doesn't take into account the correct time.
Ideally they should include the sleep time as well which isn't happening.

I'm running with

> cat sample2.py
import time

def a():
   time.sleep(0.5)

def b():
    time.sleep(0.5)
    a()

b()

> pprofile --threads 0 sample2.py > /var/tmp/sa
:> cat /var/tmp/sa
Command line: sample2.py
Total duration: 1.00046s
File: sample2.py
File duration: 1.0004s (99.99%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         1|  1.28746e-05|  1.28746e-05|  0.00%|import time
     2|         0|            0|            0|  0.00%|
     3|         2|   1.0252e-05|    5.126e-06|  0.00%|def a():
     4|         1|     0.500129|     0.500129| 49.99%|   time.sleep(0.5)
     5|         0|            0|            0|  0.00%|
     6|         2|  4.52995e-06|  2.26498e-06|  0.00%|def b():
     7|         1|     0.500155|     0.500155| 49.99%|    time.sleep(0.5)
     8|         1|  7.22408e-05|  7.22408e-05|  0.01%|    a()
(call)|         1|     0.500135|     0.500135| 49.99%|# sample2.py:3 a
     9|         0|            0|            0|  0.00%|
    10|         1|  1.35899e-05|  1.35899e-05|  0.00%|b()
(call)|         1|      1.00036|      1.00036| 99.99%|# sample2.py:6 b

[vpelletier]

Hello.

The time is accounted for on the (call) lines in the output:

(call)|         1|     0.500135|     0.500135| 49.99%|# sample2.py:3 a

this call to a() took .5s and

(call)|         1|      1.00036|      1.00036| 99.99%|# sample2.py:6 b

this call to b() took 1s, including the .5s from a().

The reason why these lines exist is that pprofile bases itself on events from the interpreter, which trigger:

• when the current interpreted line number changes
• when a call happens

For example, a line containing a function call could contain multiple slow expressions, whose time would be accounted for on the "normal" (with line number) output line, whereas the time taken during the call is accounted for on the extra (call) output line.

[dshivashankar1994]

At times I noticed the hits are not self explanatory. Some class declaration had 3 hits but the class variable had only one hit. Why would that be the case

[vpelletier]

In the abstract, all I can respond is, again, that pprofile bases itself on events triggered by the interpreter. If the interpreter decides to trigger the line event on a given line 3 times, then pprofile will give a hit count of 3.