Latency, Load Testing and Capacity
Profiling inference code
Profiling times every piece of your code separately, so you find out which specific step is actually slow instead of guessing.
- 8 min read
- 3 reading levels
- Published
Read these first
On this page 8
One lesson, three depths. Pick the one that fits you today — you can switch any time.
Beginner — No maths. Plain English.
The short answer
Profiling means timing every piece of your code separately, to find out which piece is actually slow.
The analogy you have already lived
You have cooked a meal and wondered why dinner took so long. Was it the chopping? The waiting for the pan to heat? The actual frying? Timing each step with a stopwatch, one at a time, tells you exactly where the hour went. That beats only knowing "cooking is slow" and guessing at the cause.
Profiling is that same stopwatch, applied to your code.
Why it exists
A slow model server has many moving parts: reading the request, fetching extra data, running the model, formatting a reply. Something in there is slow. Guessing which part, from experience or instinct, is often wrong. People reliably guess "the model," when the real cost was somewhere unglamorous, like a Python loop nobody thought twice about.
A profiler runs your code and records exactly how much time was spent inside every single function, and how many times each one was called. It turns a guess into a measurement.
How it works
handle_request()
|
|-- fetch_features() 0.4ms <- fast
|-- normalize() 0.1ms <- fast
|-- score() 199ms <- HERE. this is where the time went.
|-- format_response() 0.01ms <- fast
Without profiling: "the request feels slow"
With profiling: "score() is 99% of the total time -- fix THAT"A real example you have seen
An app that feels sluggish after an update, followed a few days later by a "performance fix" release, usually reflects exactly this process. Someone profiled it, found the one slow function among hundreds of fast ones, and fixed that specific piece.
The honest part
Profiling tools add their own overhead while measuring, so the numbers they report are never perfectly identical to an unmeasured run. For finding which function dominates, that overhead rarely matters — the slow function is still the slow function. For measuring the exact absolute time of an already-fast piece of code, it can.
Remember this
- Profiling measures where time actually goes, replacing a guess with a fact.
- The slow part of a system is often not the part that looks most complicated.
- A profiler adds some overhead of its own — trust its ranking more than its exact absolute numbers.
What to learn next
- Tuning CPU inference — the next step once profiling points at raw compute rather than one specific slow function.
- Concurrency in a Python inference server — relevant once profiling shows time is lost to waiting, not computing.
- Soak testing and slow memory leaks — profiling memory over time instead of a single call.
Developer — Code and libraries.
Setup
No installation needed — cProfile and pstats ship with Python's standard library.
Profiling a small, deliberately slow pipeline
import cProfile
import pstats
import io
def fetch_features(row):
# Stand-in for pulling and cleaning fields from a request.
return {k: float(v) for k, v in row.items()}
def normalize(features):
total = sum(features.values())
return {k: v / total for k, v in features.items()} if total else features
def score(features):
# Deliberately slow: a hand-written dot product in pure Python, the
# kind of thing that sneaks in before someone reaches for NumPy.
weights = [0.2, 0.5, 0.1, 0.05, 0.15]
keys = list(features.keys())
total = 0.0
for _ in range(2000): # pretend this needs many passes
total = sum(features[keys[i % len(keys)]] * weights[i % len(weights)] for i in range(len(weights)))
return total
def format_response(value):
return {"prediction": round(value, 4)}
def handle_request(row):
features = fetch_features(row)
features = normalize(features)
value = score(features)
return format_response(value)
if __name__ == "__main__":
row = {"income": 60, "years": 7, "age": 34, "loans": 2, "region": 3}
profiler = cProfile.Profile()
profiler.enable()
for _ in range(50):
handle_request(row)
profiler.disable()
stream = io.StringIO()
# strip_dirs(): pstats prints each function's full file path by default --
# this drops the directory part so the report reads as "profiling.py:31"
# instead of your entire local path repeated on every line.
stats = pstats.Stats(profiler, stream=stream).strip_dirs().sort_stats("cumulative")
stats.print_stats(6)
print(stream.getvalue()) 1800651 function calls in 0.184 seconds
Ordered by: cumulative time
List reduced from 15 to 6 due to restriction <6>
ncalls tottime percall cumtime percall filename:lineno(function)
50 0.000 0.000 0.184 0.004 profiling.py:31(handle_request)
50 0.029 0.001 0.184 0.004 profiling.py:16(score)
100050 0.037 0.000 0.151 0.000 {built-in method builtins.sum}
600000 0.083 0.000 0.114 0.000 profiling.py:23(<genexpr>)
1100000 0.034 0.000 0.034 0.000 {built-in method builtins.len}
50 0.000 0.000 0.000 0.000 profiling.py:27(format_response)Real output from this exact script, strip_dirs() included — that call is what turns your full local file path into the short profiling.py shown above. The total wall time and the per-call numbers will vary run to run and machine to machine, since profiling adds its own overhead. The finding to trust is the shape: score accounts for essentially all of the 0.184 seconds, while fetch_features, normalize, and format_response barely register.
Line-by-line walkthrough
cProfile.Profile() plus enable() / disable() wraps exactly the code you want measured — here, 50 calls to handle_request — without profiling anything outside that window.
pstats.Stats(...).sort_stats("cumulative") sorts by cumulative time — a function's own time plus every function it called. That is usually the more useful sort for finding where to focus first, versus tottime, which counts only a function's own code, excluding what it calls.
ncalls for the generator expression inside score reads 600000 — 50 requests × 2000 passes × 6 weights — which is the profiler quietly confirming the loop runs exactly as many times as the code implies.
Common mistakes
Profiling too little code. Profiling one call tells you almost nothing reliable — startup effects and noise dominate. Profile a realistic number of repeated calls, as done here with the loop of 50.
Trusting tottime over cumtime when hunting for the real bottleneck. A function that calls many small helpers might show a tiny tottime of its own while its cumtime reveals it is where all the real cost is concentrated.
Profiling in production without measuring the overhead. cProfile typically adds real overhead — often noticeable, sometimes large, depending on how many small function calls the code makes. Never leave full profiling permanently switched on for live traffic.
Stopping at the first slow-looking line. The line-level detail is not shown in the summary above. Once you know which function is slow, a line-level tool (see the researcher tab) tells you which line inside it.
Try it yourself
Replace score's hand-written loop with a single vectorised call, if you have numpy installed: import numpy as np; return float(np.dot(list(features.values()), weights * (len(features)//len(weights)+1))[:len(features)]) is a rough sketch — the exact vectorised form is left to you. Reprofile, and see how far down the list score falls.
What to learn next
- Tuning CPU inference — the next step once profiling points at raw compute rather than one specific slow function.
- Concurrency in a Python inference server — relevant once profiling shows time is lost to waiting, not computing.
- Soak testing and slow memory leaks — profiling memory over time instead of a single call.
Researcher — Mathematics and papers.
Deterministic versus statistical profilers
cProfile is a deterministic profiler: it instruments every function call and return, guaranteeing an exact call count at the cost of overhead proportional to how many calls the code makes — expensive for code with many small, frequent function calls, as the demo above shows (1.8 million recorded calls for 50 requests).
Statistical (sampling) profilers — py-spy, austin, scalene — instead interrupt the running process periodically (commonly every 1–10ms) and record the current call stack, without instrumenting every call. This gives far lower overhead, closer to production-safe, at the cost of exact call counts and small functions occasionally being under-sampled. py-spy additionally can attach to an already-running process from outside it, without any code change or restart — valuable for profiling a live incident.
Line-level and memory profiling
line_profiler gives per-line timing within a single decorated function, resolving the "which line inside score" question the function-level summary above cannot answer. memory_profiler and tracemalloc (standard library) do the equivalent for memory allocation rather than time, relevant when the bottleneck is allocation churn or an unexpectedly large intermediate object rather than raw compute — see soak testing and memory leaks for tracemalloc used directly.
Profiling GPU-resident code
None of the CPU-side tools above see time spent inside a CUDA kernel — from Python's perspective, a GPU call can look like a fast, near-instant dispatch, with the real work happening asynchronously on the device. torch.profiler and NVIDIA Nsight Systems instrument the CUDA execution timeline directly, and are the correct tools once a bottleneck is confirmed to be GPU-side rather than in the surrounding Python.
Amdahl's law, applied to optimisation effort
If a function accounts for fraction $p$ of total time, optimising it by a factor of $s$ improves the whole program by at most:
$$\text{speedup} = \frac{1}{(1-p) + p/s}$$
For the profile above, $p \approx 0.99$ for score, so even a modest $s$ there dominates total speedup — while an infinite speedup on format_response ($p \approx 0.004$) could never improve the total by more than about 0.4%. This is the formal justification for profiling before optimising: effort spent on a low-$p$ function is capped in its possible payoff, no matter how much faster that function gets.
References
- Python documentation, The Python Profilers — docs.python.org/3/library/profile.html
- Gregg, B., py-spy and sampling profiler design generally — see Gregg's Systems Performance, 2nd ed., 2020, for the deterministic-vs-sampling trade-off in depth.
- Amdahl, G., Validity of the Single Processor Approach to Achieving Large Scale Computing Capabilities, AFIPS 1967 — the original statement of the law used above.
What to learn next
- Tuning CPU inference — the next step once profiling points at raw compute rather than one specific slow function.
- Concurrency in a Python inference server — relevant once profiling shows time is lost to waiting, not computing.
- Soak testing and slow memory leaks — profiling memory over time instead of a single call.