Hierchical profiling

Links: notebook, html, PDF, python, slides, GitHub

pyinstrument has a nice rendering when it comes to display the profiling of a function in a notebook. Let’s see how to get the same with this library.

from jyquickhelper import add_notebook_menu
add_notebook_menu()

The code to profile

import time

def f0(t):
    time.sleep(t)

def f1(t):
    time.sleep(t)

def f2():
    f1(0.1)
    f1(0.01)

def f3():
    f0(0.2)
    f1(0.5)

def f4():
    f2()
    f3()
from pyquickhelper.pycode.profiling import profile
stat, text = profile(f4)

This is the default rendering for module cProfile.

print(text)
      12 function calls in 0.829 seconds
Ordered by: cumulative time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.829    0.829 <ipython-input-2-61d7d6b6a99d>:17(f4)
     4    0.829    0.207    0.829    0.207 {built-in method time.sleep}
     1    0.000    0.000    0.711    0.711 <ipython-input-2-61d7d6b6a99d>:13(f3)
     3    0.000    0.000    0.622    0.207 <ipython-input-2-61d7d6b6a99d>:6(f1)
     1    0.000    0.000    0.207    0.207 <ipython-input-2-61d7d6b6a99d>:3(f0)
     1    0.000    0.000    0.118    0.118 <ipython-input-2-61d7d6b6a99d>:9(f2)
     1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Renders a profile as a dataframe

from pyquickhelper.pycode.profiling import profile2df

df = profile2df(stat)
df
fct file ncalls1 ncalls2 tin cum_tin tall cum_tall
0 f4 <ipython-input-2-61d7d6b6a99d>:17 1 1 0.000026 0.000026 0.828829 0.828829
1 <built-in method time.sleep> ~:0 4 4 0.828624 0.828624 0.828624 0.828624
2 f3 <ipython-input-2-61d7d6b6a99d>:13 1 1 0.000030 0.000030 0.711066 0.711066
3 f1 <ipython-input-2-61d7d6b6a99d>:6 3 3 0.000113 0.000113 0.621887 0.621887
4 f0 <ipython-input-2-61d7d6b6a99d>:3 1 1 0.000014 0.000014 0.206864 0.206864
5 f2 <ipython-input-2-61d7d6b6a99d>:9 1 1 0.000022 0.000022 0.117736 0.117736
6 <method 'disable' of '_lsprof.Profiler' objects> ~:0 1 1 0.000004 0.000004 0.000004 0.000004

Renders a profile as indented text

from pyquickhelper.pycode.profiling import profile2graph

gr = profile2graph(stat)
print(gr[0].to_text(fct_width=20))
<built-in...e.sleep> --  4  4 -- 0.82862 0.82862 -- ~:0:<built-in method time.sleep> (<built-in method time.sleep>)
f1                   --  3  3 -- 0.00011 0.62189 -- <ipython-input-2-61d7d6b6a99d>:6 (f1)
    <built-...sleep> --  3  3 -- 0.62177 0.62177 -- ~:0:<built-in method time.sleep> (<built-in method time.sleep>) +++
f4                   --  1  1 -- 0.00003 0.82883 -- <ipython-input-2-61d7d6b6a99d>:17 (f4)
    f2               --  1  1 -- 0.00002 0.11774 -- <ipython-input-2-61d7d6b6a99d>:9 (f2)
        f1           --  2  2 -- 0.00007 0.11771 -- <ipython-input-2-61d7d6b6a99d>:6 (f1) +++
    f3               --  1  1 -- 0.00003 0.71107 -- <ipython-input-2-61d7d6b6a99d>:13 (f3)
        f0           --  1  1 -- 0.00001 0.20686 -- <ipython-input-2-61d7d6b6a99d>:3 (f0)
            <bu...p> --  1  1 -- 0.20685 0.20685 -- ~:0:<built-in method time.sleep> (<built-in method time.sleep>) +++
        f1           --  1  1 -- 0.00004 0.50417 -- <ipython-input-2-61d7d6b6a99d>:6 (f1) +++

Renders a profile as json

from pyquickhelper.pycode.profiling import profile2graph

gr = profile2graph(stat)
js = gr[0].to_json(indent=4)
print(js)
{
    "profile": {
        "4-0.82862:::<built-in method time.sleep>": {
            "details": {
                "fct": "<built-in method time.sleep>",
                "where": "~:0:<built-in method time.sleep>",
                "nc1": 4,
                "nc2": 4,
                "tin": 0.8286236,
                "tall": 0.8286236,
                "indent": 0,
                "ncalls": 0
            }
        },
        "3-0.62189:::f1": {
            "details": {
                "fct": "f1",
                "where": "<ipython-input-2-61d7d6b6a99d>:6",
                "nc1": 3,
                "nc2": 3,
                "tin": 0.00011260000000000001,
                "tall": 0.6218869,
                "indent": 0,
                "ncalls": 1
            },
            "calls": {
                "3-0.62177:<built-in method time.sleep>": {
                    "details": {
                        "fct": "<built-in method time.sleep>",
                        "where": "~:0:<built-in method time.sleep>",
                        "nc1": 3,
                        "nc2": 3,
                        "tin": 0.6217743,
                        "tall": 0.6217743,
                        "indent": 0,
                        "ncalls": 1
                    }
                }
            }
        },
        "1-0.82883:::f4": {
            "details": {
                "fct": "f4",
                "where": "<ipython-input-2-61d7d6b6a99d>:17",
                "nc1": 1,
                "nc2": 1,
                "tin": 2.6300000000000002e-05,
                "tall": 0.8288287000000001,
                "indent": 0,
                "ncalls": 2
            },
            "calls": {
                "1-0.11774:f2": {
                    "details": {
                        "fct": "f2",
                        "where": "<ipython-input-2-61d7d6b6a99d>:9",
                        "nc1": 1,
                        "nc2": 1,
                        "tin": 2.19e-05,
                        "tall": 0.1177363,
                        "indent": 1,
                        "ncalls": 1
                    },
                    "calls": {
                        "2-0.11771:f1": {
                            "details": {
                                "fct": "f1",
                                "where": "<ipython-input-2-61d7d6b6a99d>:6",
                                "nc1": 2,
                                "nc2": 2,
                                "tin": 7.25e-05,
                                "tall": 0.11771440000000001,
                                "indent": 1,
                                "ncalls": 1
                            }
                        }
                    }
                },
                "1-0.71107:f3": {
                    "details": {
                        "fct": "f3",
                        "where": "<ipython-input-2-61d7d6b6a99d>:13",
                        "nc1": 1,
                        "nc2": 1,
                        "tin": 3.0100000000000003e-05,
                        "tall": 0.7110661,
                        "indent": 1,
                        "ncalls": 2
                    },
                    "calls": {
                        "1-0.20686:f0": {
                            "details": {
                                "fct": "f0",
                                "where": "<ipython-input-2-61d7d6b6a99d>:3",
                                "nc1": 1,
                                "nc2": 1,
                                "tin": 1.4200000000000001e-05,
                                "tall": 0.2068635,
                                "indent": 2,
                                "ncalls": 1
                            },
                            "calls": {
                                "1-0.20685:<built-in method time.sleep>": {
                                    "details": {
                                        "fct": "<built-in method time.sleep>",
                                        "where": "~:0:<built-in method time.sleep>",
                                        "nc1": 1,
                                        "nc2": 1,
                                        "tin": 0.2068493,
                                        "tall": 0.2068493,
                                        "indent": 2,
                                        "ncalls": 1
                                    }
                                }
                            }
                        },
                        "1-0.50417:f1": {
                            "details": {
                                "fct": "f1",
                                "where": "<ipython-input-2-61d7d6b6a99d>:6",
                                "nc1": 1,
                                "nc2": 1,
                                "tin": 4.0100000000000006e-05,
                                "tall": 0.5041725,
                                "indent": 1,
                                "ncalls": 2
                            }
                        }
                    }
                }
            }
        }
    }
}

Or in a better way:

import json
from pstats import SortKey
from jyquickhelper import JSONJS

JSONJS(gr[0].to_json(as_str=False, sort_key=SortKey.CUMULATIVE))