[Python] Discrete Profiling that Counts dict, list and tuple creation calls

Overview


I'd like to perform discrete profiling on our testing suite: instead of measuring time (which is noisy and aggregates many different kinds of operations) I want to count the number of times a few basic operations - such as dict, tuple and list creation - are executed in different parts of the code.

The problem is, these basic operations are not accounted for by cProfile (see demo below).

• is there an off-the-shelf tool that can count these type of function calls?
• if not, is there some existing patching framework that does this in pytest?

If nothing exists, I suppose I can write a patching framework myself:

• any suggestions how to go about this with minimal overhead?

Demo


import cProfile
import pstats
from contextlib import contextmanager
from time import perf_counter


@contextmanager
def profiled():
pr = cProfile.Profile()
t1 = t2 = perf_counter()
pr.enable()
try:
yield lambda: (pstats.Stats(pr), t2 - t1)
finally:
pr.disable()
t2 = perf_counter()

if __name__ == '__main__':
with profiled() as get_append_stats:
l = []
for i in range(10000000):
l.append({'hello': i, 'world': i+1})

with profiled() as get_comprehension_stats:
l = [{'hello': i, 'world': i + 1} for i in range(10000000)]


stats_obj, tot = get_append_stats()
print("=== list APPEND ===")
print("\nProfile stats sorted by cumulative time:")
stats_obj.sort_stats('cumulative').print_stats(10)
print(f"\n>>> Wall clock elapsed time: {tot:.2f}s")
print()
print()
stats_obj, tot = get_comprehension_stats()
print("=== list COMPREHENSION ===")
print("\nProfile stats sorted by cumulative time:")
stats_obj.sort_stats('cumulative').print_stats(10)
print(f"\n>>> Wall clock elapsed time: {tot:.2f}s")


Output


=== list APPEND ===

Profile stats sorted by cumulative time:
10000004 function calls in 0.177 seconds

Ordered by: cumulative time

ncalls tottime percall cumtime percall filename:lineno(function)
10000000 0.177 0.000 0.177 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 /XXX/.pyenv/versions/3.9.8/lib/python3.9/contextlib.py:123(__exit__)
1 0.000 0.000 0.000 0.000 {built-in method builtins.next}
1 0.000 0.000 0.000 0.000 /Users/XXX:7(profiled)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}



>>> Wall clock elapsed time: 1.18s


=== list COMPREHENSION ===

Profile stats sorted by cumulative time:
5 function calls in 0.573 seconds

Ordered by: cumulative time

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.573 0.573 0.573 0.573 XXX:25(<listcomp>)
1 0.000 0.000 0.000 0.000 XXX/.pyenv/versions/3.9.8/lib/python3.9/contextlib.py:123(__exit__)
1 0.000 0.000 0.000 0.000 {built-in method builtins.next}
1 0.000 0.000 0.000 0.000 XXX:7(profiled)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}



>>> Wall clock elapsed time: 0.89s

Analysis

• in the first run, we at least see the 'append' impressive call count
• in the second run, none of the counts reflects the large amount of work being done
• in both cases, we don't see the dict creation (which accounts for much of the runtime)

Motivation


I believe this kind of profiling should allow to use our existing pytest suite (which is quite extensive with good coverage) to perform a kind of regression profiling "meta test" that would automatically detect emerging hotspots. Since counts are more stable this should be quite sensitive (allow us to detect even minor deterimental changes) and robust (do not fail "at random"), without increasing the ci runtime by much (just adding the profiling overhead to the existing suite).

Continue reading...