Profile Script with profiling.tracing in Python 3.15

A function can be fast but still slow down a program if it runs many times. Timing the whole script won't show this because each individual call is quick. Since Python 3.15, the profiling package provides the profiling.tracing module, which tracks how often each function runs and how long it takes. It is the new place of cProfile, which stays available under its old name.

The following script applies a tax rate to a list of orders:

def tax_rate(country):
    rates = {'us': 0.07, 'de': 0.19, 'fr': 0.20}
    return rates[country]


def total_price(orders):
    total = 0
    for country, amount in orders:
        total += amount * (1 + tax_rate(country))
    return total


orders = [('us', 10.0) for _ in range(1000000)]
print(round(total_price(orders), 2))

The -s option sorts the report, and tottime puts the functions that spent the most time running their own code at the top:

python -m profiling.tracing -s tottime main.py

10700000.0
         1000006 function calls in 0.378 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.203    0.203    0.359    0.359 main.py:6(total_price)
  1000000    0.155    0.000    0.155    0.000 main.py:1(tax_rate)
        1    0.019    0.019    0.378    0.378 main.py:1(<module>)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.round}
        1    0.000    0.000    0.378    0.378 {built-in method builtins.exec}

The script runs normally and prints its result, then the profiler prints the report.

The ncalls column counts how often each function ran, and tax_rate ran 1,000,000 times, once per order. The tottime column holds the time spent inside the function itself, while cumtime adds the time spent in the functions it called. The percall column next to tottime is 0.000, so no single call is slow. The cost comes from the number of calls, because tax_rate builds the rates dictionary again every time.

Moving the dictionary out of the function builds it once:

RATES = {'us': 0.07, 'de': 0.19, 'fr': 0.20}


def tax_rate(country):
    return RATES[country]


def total_price(orders):
    total = 0
    for country, amount in orders:
        total += amount * (1 + tax_rate(country))
    return total


orders = [('us', 10.0) for _ in range(1000000)]
print(round(total_price(orders), 2))

Run the command again:

python -m profiling.tracing -s tottime main.py

10700000.0
         1000006 function calls in 0.255 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.165    0.165    0.237    0.237 main.py:8(total_price)
  1000000    0.072    0.000    0.072    0.000 main.py:4(tax_rate)
        1    0.018    0.018    0.255    0.255 main.py:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.round}
        1    0.000    0.000    0.255    0.255 {built-in method builtins.exec}

The tottime value for tax_rate decreases from 0.155 to 0.072 seconds, and the whole run drops from 0.378 to 0.255 seconds. The ncalls column still reads 1,000,000, because the function is called just as often as before. What changed is the work it does on each call.