3

I'm having issues interpreting cProfile data. To show you my problem I created this simple script.

The function D calls B and C, which both call A.
Function A clearly takes up 1 sec (+overhead).
If we look at the snakeviz results then you can see that the reporting is a bit weird. I understand that in total 2 sec has been spent by function A, but inside function C, function A has spent only 1 sec, and that's what I am interested in. Does anybody know if there is a setting (or a different viewer) where I do not have this issue?

import time
import cProfile

def A():
    time.sleep(1)

def B():
    A()

def C():
    A()

def D():
    B()
    C()

cProfile.run('D()','profileResults.prf')

snakeviz results

Nico Schlömer
  • 53,797
  • 27
  • 201
  • 249
  • As you are profiling function `D()`, where function `A()` is called indirectly 2 times, that's why it is showing 2 seconds. Function `C()` is called only once from `D()`. From function `C()`, function `A()` is also called only once. Therefore function `C()` time should be 1 second. If you profile function `C()` alone, you will get 1 second everywhere. – Soumendra May 20 '18 at 16:42
  • Thanks for your answer. It's not showing wrong information indeed, and in this case one could just profile function C or D separately. However in more complex projects this is not possible. Once you're multiple levels deep in your code, it becomes impossible to determine how much time was spent in a function. I have found something which does it slightly better: https://ymichael.com/2014/03/08/profiling-python-with-cprofile.html – Matthias Baert May 20 '18 at 17:26

1 Answers1

5

Unfortunately, the Python profile does not store the entire call tree. (This would be too expensive.) I've documented the problem here and as a snakeviz issue.

I recently created tuna for visualizing Python profiles to work around some of these problems. tuna cannot show the entire call tree, but at least it doesn't show wrong info either.

Install with

pip3 install tuna

Create a runtime profile

python -m cProfile -o program.prof yourfile.py

and just run tuna on the file

tuna program.prof

enter image description here

Matiiss
  • 5,970
  • 2
  • 12
  • 29
Nico Schlömer
  • 53,797
  • 27
  • 201
  • 249