Warm-up · Activity 1 of 7
// A4.2 · ~30 min · Advanced
Profiling with cProfile
After this lesson you can profile a program with cProfile, read ncalls, tottime and cumtime, sort and trim the report with pstats, and find and confirm the fix for the function that makes it slow.
Predict · Activity 2 of 7
Predict before you read on: fib calls itself. What does the profile record as its ncalls?
import cProfile import pstats def fib(n): return n if n < 2 else fib(n - 1) + fib(n - 2) with cProfile.Profile() as profiler: fib(5) rows = pstats.Stats(profiler).get_stats_profile().func_profiles print(rows["fib"].ncalls)Practice · Activity 3 of 7
outer calls light 50 times and heavy once; heavy runs a long loop. Fill in the key so that the function with the most time in its own code comes first.
stats.sort_stats(SortKey.____)stats.sort_stats(SortKey.)Practice · Activity 4 of 7
Here is a real report. Which function spends the most time in its own code, not counting the functions it calls?
9005 function calls in 0.257 seconds Ordered by: cumulative time List reduced from 7 to 5 due to restriction <5> ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.257 0.257 main.py:20(report) 1 0.003 0.003 0.257 0.257 {built-in method builtins.sum} 3001 0.016 0.000 0.254 0.000 main.py:21(<genexpr>) 3000 0.005 0.000 0.239 0.000 main.py:16(line_total) 3000 0.234 0.000 0.234 0.000 main.py:9(find_price)Practice · Activity 5 of 7
Match each part of a profile row to its meaning.
Brain teaser · Activity 6 of 7
Brain teaser. The list comprehension keeps the allowed items. How often does the profile say get_allowed was called?
import cProfile import pstats def get_allowed(): return {"a", "b"} items = ["a", "b", "c", "d"] * 25 with cProfile.Profile() as profiler: kept = [x for x in items if x in get_allowed()] rows = pstats.Stats(profiler).get_stats_profile().func_profiles print(rows["get_allowed"].ncalls)Apply · Activity 7 of 7
Mini-task, on your own computer. Take a script of yours that feels slow, or the worked example below. Run python -m cProfile -s cumulative script.py and note the most expensive high-level step. Then profile it with -s tottime and name the hot function. Fix it, profile again, and write down its ncalls and tottime before and after.
Check your work against this list
Build it yourself
Read the worked example, then write the exercises. Your code runs in your browser or on your computer and is never uploaded.
Worked example
Finding the hot function in a report
report adds up 3000 orders; line_total looks each price up with find_price, which searches a list of 2000 pairs. The program profiles one run and reads the numbers with get_stats_profile() instead of printing the full table, because the seconds change on every run while the call counts and the winner do not. Run it on your computer, then add stats.print_stats(5) to see the table itself.
main.py
import cProfile
import pstats
from pstats import SortKey
PRICES = [(f"item{i}", i * 0.5) for i in range(2000)]
def find_price(name: str) -> float:
for key, price in PRICES: # a linear search: suspicious
if key == name:
return price
raise KeyError(name)
def line_total(name: str, quantity: int) -> float:
return find_price(name) * quantity
def report(orders: list[tuple[str, int]]) -> float:
return sum(line_total(name, quantity) for name, quantity in orders)
orders = [(f"item{i % 2000}", 1 + i % 3) for i in range(3000)]
with cProfile.Profile() as profiler:
total = report(orders)
print(f"total: {total:.1f}")
stats = pstats.Stats(profiler).strip_dirs().sort_stats(SortKey.TIME)
# stats.print_stats(5) # the full table; its seconds differ on every run
profile = stats.get_stats_profile()
rows = profile.func_profiles
hottest = max(rows, key=lambda name: rows[name].tottime)
print("hottest:", hottest)
print("over half of all time:", rows[hottest].tottime > profile.total_tt / 2)
for name in ("report", "line_total", "find_price"):
print(f"{name}: {rows[name].ncalls} calls")
Run it with
python main.pyOutput
total: 2498500.0
hottest: find_price
over half of all time: True
report: 1 calls
line_total: 3000 calls
find_price: 3000 calls- find_price has the highest tottime: the loop over PRICES is where the work happens.
- line_total and report have a high cumtime too, but only because find_price runs below them.
- find_price runs 3000 times and scans up to 2000 pairs each time; a dict built once removes the scan.
- ncalls is a string in get_stats_profile(), because a recursive function reports it as "15/1".
Exercises
Exercise 1 of 2
Counting calls with a profile
Complete profile_calls(func, *args). Run func(*args) inside with cProfile.Profile() as profiler:, then use pstats.Stats(profiler).get_stats_profile() and return a dict from each function name to its number of calls, as an int. For a recursive function, ncalls looks like "25/1": count the first number. Run the tests, then try it on your own functions on your computer.
This exercise needs Python on your computer (the browser version cannot run it). The files and commands are below.
Hints
Hint 1
Put func(*args) inside with cProfile.Profile() as profiler:, so only that call is recorded.
Hint 2
get_stats_profile().func_profiles maps each function name to an object with an ncalls attribute, a string.
Hint 3
int(row.ncalls.split("/")[0]) turns both "3" and "25/1" into a number.
Show a solution
One way to solve it. Yours can look different and still pass the checks.
import cProfile
import pstats
from collections.abc import Callable
def profile_calls(func: Callable[..., object], *args: object) -> dict[str, int]:
with cProfile.Profile() as profiler:
func(*args)
profile = pstats.Stats(profiler).get_stats_profile()
return {name: int(row.ncalls.split("/")[0]) for name, row in profile.func_profiles.items()}
Run it on your computer
Install Python 3.14 or newer. Save these files in one folder, open a terminal in that folder, and run the commands below.
main.py
import cProfile
import pstats
from collections.abc import Callable
def profile_calls(func: Callable[..., object], *args: object) -> dict[str, int]:
# Run func(*args) under cProfile.Profile, then return {function name: number of calls}.
# A recursive function's ncalls looks like "15/1": count the first number.
func(*args)
return {}
test_main.py
from main import profile_calls
def fib(n):
return n if n < 2 else fib(n - 1) + fib(n - 2)
def helper(x):
return x * 2
def three_helpers():
return helper(1) + helper(2) + helper(3)
def test_counts_calls():
"""three_helpers runs once and calls helper 3 times"""
calls = profile_calls(three_helpers)
got = calls.get("three_helpers"), calls.get("helper")
assert got == (1, 3), f"got {got!r} for three_helpers and helper, expected (1, 3)"
def test_recursion():
"""fib(6) makes 25 calls in all, counted from ncalls 25/1"""
calls = profile_calls(fib, 6)
assert calls.get("fib") == 25, f"calls['fib'] is {calls.get('fib')!r}, expected 25: take the number before the slash"
def test_values_are_ints():
"""Every count is an int"""
calls = profile_calls(three_helpers)
bad = {name: n for name, n in calls.items() if not isinstance(n, int)}
assert calls and not bad, f"these counts are not ints: {bad!r}" if bad else "the dict is empty"
On macOS and Linux, type python3 wherever these commands say python, as in the first lesson.
Run the program:
python main.pyRun the checks (needs learnrun.py in the same folder):
python learnrun.py testExercise 2 of 2
Fixing the hot spot
count_known counts the words that appear in a vocabulary, ignoring case and spaces. On your computer, run python main.py: the profile, sorted by call count, shows normalise called hundreds of thousands of times. Fix count_known so that it normalises each vocabulary entry once, before the loop, and each word once. The answer must not change; a test profiles your version and counts the calls to normalise.
This exercise needs Python on your computer (the browser version cannot run it). The files and commands are below.
Hints
Hint 1
The list comprehension inside the if runs again for every word: that is where the calls come from.
Hint 2
Build known = {normalise(v) for v in vocabulary} once, before the for loop.
Hint 3
Then the test is just normalise(word) in known, and a set lookup does not scan the vocabulary.
Show a solution
One way to solve it. Yours can look different and still pass the checks.
def normalise(word: str) -> str:
return word.strip().lower()
def count_known(words: list[str], vocabulary: list[str]) -> int:
known = {normalise(v) for v in vocabulary}
count = 0
for word in words:
if normalise(word) in known:
count += 1
return count
if __name__ == "__main__":
import cProfile
words = ["Apple", "pear ", "kiwi", "PLUM"] * 500
vocabulary = [f"fruit{i}" for i in range(300)] + ["apple", "pear", "plum"]
cProfile.run("print(count_known(words, vocabulary))", sort="ncalls")
Run it on your computer
Install Python 3.14 or newer. Save these files in one folder, open a terminal in that folder, and run the commands below.
main.py
def normalise(word: str) -> str:
return word.strip().lower()
def count_known(words: list[str], vocabulary: list[str]) -> int:
count = 0
for word in words:
if normalise(word) in [normalise(v) for v in vocabulary]:
count += 1
return count
if __name__ == "__main__":
import cProfile
words = ["Apple", "pear ", "kiwi", "PLUM"] * 500
vocabulary = [f"fruit{i}" for i in range(300)] + ["apple", "pear", "plum"]
cProfile.run("print(count_known(words, vocabulary))", sort="ncalls")
test_main.py
import cProfile
import pstats
from main import count_known
WORDS = ["Apple", "pear ", "kiwi", "PLUM"] * 50
VOCABULARY = [f"fruit{i}" for i in range(30)] + ["apple", " Pear", "plum"]
def normalise_calls(words, vocabulary):
with cProfile.Profile() as profiler:
result = count_known(words, vocabulary)
rows = pstats.Stats(profiler).get_stats_profile().func_profiles
return result, int(rows["normalise"].ncalls) if "normalise" in rows else 0
def test_same_answer():
"""150 of the 200 words are known"""
got = count_known(WORDS, VOCABULARY)
assert got == 150, f"count_known returned {got!r}, expected 150"
def test_normalises_each_word_once():
"""normalise runs once per word and once per vocabulary entry"""
result, calls = normalise_calls(WORDS, VOCABULARY)
expected = len(WORDS) + len(VOCABULARY)
assert calls == expected, f"normalise was called {calls} times, expected {expected}: normalise the vocabulary once, before the loop"
def test_empty_words():
"""No words: the answer is 0"""
got = count_known([], VOCABULARY)
assert got == 0, f"count_known([], ...) returned {got!r}, expected 0"
On macOS and Linux, type python3 wherever these commands say python, as in the first lesson.
Run the program:
python main.pyRun the checks (needs learnrun.py in the same folder):
python learnrun.py testCommon mistakes
A sort key that does not exist
import cProfile
import pstats
with cProfile.Profile() as profiler:
sum(range(1000))
pstats.Stats(profiler).sort_stats("speed").print_stats(5)
What Python prints
KeyError: 'speed'Why, and the fix
sort_stats accepts only the documented keys, such as "calls", "cumulative", "tottime" and "name", or their SortKey members. An abbreviation works only when it is unambiguous: "cum" matches both "cumulative" and "cumtime" and fails the same way. Prefer SortKey.CUMULATIVE: mypy catches a misspelt enum member, but not a misspelt string.
Mixing up the string key and the enum name
import cProfile
import pstats
from pstats import SortKey
with cProfile.Profile() as profiler:
sum(range(1000))
pstats.Stats(profiler).sort_stats(SortKey.TOTTIME).print_stats(5)
What Python prints
AttributeError: type object 'SortKey' has no attribute 'TOTTIME'Why, and the fix
The column is called tottime, and the string "tottime" is a valid key, but the enum member for internal time is SortKey.TIME. Likewise "cumtime" has no member of its own: use SortKey.CUMULATIVE.
Python in the browser: Pyodide 314.0.7, MPL-2.0. Licence and source
Exit ticket
5 questions, no hints. Score 80% or more to complete the lesson.
Finish every activity above to unlock the exit ticket.