Python Testing & Debugging Beyond unittestAdvanced Python testing playbooks
Debugging & Performance

Profiling Async Code with yappi

Profiling asyncio code with cProfile produces numbers that look precise and mean little. Every time a coroutine awaits something that suspends, cProfile sees the function return; when the event loop resumes it, cProfile sees a new call. A handler that awaits a database query three times shows up as four calls with fragmented timings, and the time spent suspended is attributed unpredictably. Summed across thousands of requests, the report points at the wrong functions.

yappi — Yet Another Python Profiler — understands coroutines. It tracks a coroutine across suspensions as a single call, can exclude suspended time from the coroutine's own cost, and lets you choose between CPU time (what the code actually computed) and wall time (how long it took end to end). It also profiles every thread, not just the one that started it, and can break results down per asyncio task. For an async web service or worker, that is the difference between a profile you can act on and one that sends you chasing awaits.

Prerequisites

Solution

Python
# profile_worker.py
import asyncio
import yappi

from app.worker import main

yappi.set_clock_type("cpu")        # what blocks the event loop?
yappi.start()
asyncio.run(main(iterations=2_000))
yappi.stop()

stats = yappi.get_func_stats(filter_callback=lambda f: "app/" in f.module)
stats.sort("ttot", "desc").print_all(
    columns={0: ("name", 60), 1: ("ncall", 8), 2: ("ttot", 8), 3: ("tsub", 8), 4: ("tavg", 8)}
)

stats.save("worker.pstat", type="pstat")     # snakeviz worker.pstat
Python
# The same workload, wall clock, broken down per task.
yappi.set_clock_type("wall")
yappi.start()
asyncio.run(main(iterations=200))
yappi.stop()

for task in yappi.get_task_stats():
    print(f"{task.name:<30} {task.ttot:8.3f}s")
Plain text
Clock type: CPU
name                                              ncall    ttot     tsub     tavg
app/worker.py:78 Worker.handle_message            2000     4.812    0.041    0.0024
app/codec.py:22 decode_payload                    2000     3.906    3.702    0.0020
app/rules.py:51 evaluate                          2000     0.771    0.644    0.0004
app/db.py:40 Repo.save                            2000     0.089    0.021    0.0000
How cProfile and yappi see one coroutine A timeline shows a handler coroutine that runs, awaits a database call, resumes, awaits again and finishes. cProfile records three separate calls with fragments of time. yappi records one call; with the CPU clock it counts only the running segments, and with the wall clock it counts the full elapsed time including the waits. One coroutine, two very different reports timeline await db await db cProfile 3 calls, fragmented times, suspension attributed unpredictably yappi cpu 1 call · green segments only → what blocks the loop yappi wall 1 call · whole span incl. waits → where latency goes
Choosing the clock is choosing the question: CPU for "what hogs the loop", wall for "where does a request spend its time".

Why this works

yappi hooks the interpreter's profiling callbacks like cProfile does, but it keeps per-coroutine state. When a coroutine suspends, yappi notes that it is paused rather than finished; when it resumes, the same call continues. With the CPU clock, the time between suspension and resumption is not counted, because the thread was doing other work — running other coroutines — during it. With the wall clock, it is counted, because from the request's point of view that time elapsed.

In the example output, ttot is total time including callees and tsub is time in the function itself. decode_payload has almost all of its time in tsub, meaning the cost is in its own body — pure Python parsing on every message — and at about two milliseconds of CPU per call, it holds the event loop for that long each time. Every other coroutine waits. That is the actionable finding: move decoding to a faster library or into a thread pool, and the whole worker's latency improves.

get_task_stats aggregates by asyncio task, which helps when a service runs several long-lived tasks — a consumer, a heartbeat, a flusher — and you need to know which one is consuming the loop. With the wall clock, a task's total is roughly its lifetime; with CPU, it is the work it actually did.

CPU clock for blocking, wall clock for latency

The two clocks answer different questions, and running both is usually worthwhile.

The CPU profile finds code that blocks the event loop. In asyncio, any synchronous work in a coroutine prevents every other coroutine from running until it finishes. A function with high CPU tsub and many calls — JSON parsing, regex matching, Pydantic validation of large payloads — is a direct cause of tail latency under load, even if each call looks fast in isolation. These are the functions to optimise, offload with asyncio.to_thread, or split with occasional await asyncio.sleep(0).

The wall profile shows where elapsed time goes, including waits. It tends to be dominated by I/O — database round trips, HTTP calls — and that is information rather than a bug: the fix is often concurrency (gather independent calls instead of awaiting them sequentially), batching, or caching, not faster code. A coroutine with high wall ttot but low CPU ttot is waiting, not working.

Interpreting CPU and wall results together A two-by-two grid classifies functions. High CPU and high wall means compute-bound code that blocks the loop. Low CPU and high wall means waiting on I/O, fixed by concurrency or batching. High CPU and low wall is rare and usually means measurement across threads. Low on both means not worth attention. Read the two profiles side by side high CPU · high wall blocks the loop — optimise or offload low CPU · high wall waiting — gather, batch, cache high CPU · low wall rare — check thread attribution low · low leave alone
Only the top-left quadrant is a problem profiling-driven optimisation fixes; the top-right is an architecture question.

A worked case: offloading the decoder

Acting on the example report shows how the two clocks work together. The CPU profile put decode_payload at about 80% of the worker's CPU time, almost all of it in the function's own body. The wall profile for the same workload showed the average message taking 14 ms end to end, of which only 2 ms was CPU; the rest was waiting on the database and on other coroutines — including, crucially, waiting for other messages' decoding to release the loop.

The fix had two parts. The payload format was JSON, and swapping the standard library parser for orjson cut decoding CPU by roughly five times. The remaining cost was still synchronous, so large payloads were moved off the loop with await asyncio.to_thread(decode_payload, raw) above a size threshold, keeping small messages inline where the thread hand-off would cost more than it saved.

Re-profiling confirmed both effects. The CPU profile's top entry was now the rules evaluation, at a much lower absolute level. The wall profile showed average message latency down to about 6 ms and, more importantly, the 99th percentile down far more, because a single large message no longer stalled every other coroutine behind it. That tail improvement is the characteristic signature of removing event-loop blocking, and it is exactly what a function-level CPU report for async code should lead to.

Latency before and after offloading decoding Bars compare average and 99th percentile message latency. Before the fix, average latency was 14 milliseconds and p99 was 120 milliseconds. After switching to orjson and offloading large payloads to a thread, average fell to 6 milliseconds and p99 to 18 milliseconds, the larger relative gain coming from removing event-loop blocking. Unblocking the loop fixes the tail most average 14 ms before 6 ms after p99 120 ms before 18 ms after
The average improved about twofold; the p99 about sixfold, because large messages stopped stalling everything behind them.

Profiling an async test or a single request

A whole-worker profile is useful for a first look at a busy service, but the fastest feedback loop is often a profile of one scenario in a test. yappi works inside pytest as long as it is started before the event loop runs the code of interest. With pytest-asyncio, a fixture that starts yappi, yields, stops it and prints filtered stats gives a per-test profile:

Python
@pytest.fixture
def yappi_cpu():
    yappi.clear_stats()
    yappi.set_clock_type("cpu")
    yappi.start()
    yield
    yappi.stop()
    yappi.get_func_stats(filter_callback=lambda f: "app/" in f.module) \
         .sort("tsub", "desc").print_all()

Request one test with it — pytest -s -k test_large_order_checkout with the fixture added to that test — and the top of the table is the synchronous work that request does on the loop. That is a convenient way to check a suspected hot path in isolation, to compare two implementations under identical conditions, or to confirm that an offload to a thread really did remove the work from the loop: after the change, the function should disappear from the CPU table of the loop thread and reappear under the worker thread in get_thread_stats().

Keep such fixtures strictly opt-in, never autouse, and never enabled in CI. Profiling overhead makes timing-sensitive tests flaky, and a fixture that silently profiles every test slows the suite for everyone. Adding it explicitly to the one or two tests under investigation, and removing it once the question is answered, keeps the profile focused and the rest of the suite untouched.

Edge cases and failure modes

  • Overhead. yappi is a deterministic profiler and slows code substantially. Profile representative workloads, not the full production load, and compare relative numbers.
  • Forgetting to clear. Stats accumulate across start/stop pairs. Call yappi.clear_stats() between separate measurements.
  • uvloop. yappi works with uvloop, but time inside the loop's C implementation is not attributed to Python functions.
  • Threads started before yappi. yappi profiles threads created after start() by default; for existing threads, pass profile_threads=True and start early.
  • Greenlets. gevent-based code needs yappi.set_context_backend("greenlet") to attribute time per greenlet correctly.

Frequently Asked Questions

Why is cProfile misleading for asyncio code? cProfile records a coroutine's time as ending each time it suspends at an await and starting again when resumed, and it counts each resume as a call. Coroutines that wait on I/O show inflated call counts and misleading time. yappi is coroutine-aware and aggregates the whole coroutine.

Should I use wall clock or CPU clock with yappi? Use CPU clock to find code that burns the processor and blocks the event loop. Use wall clock to find where requests spend elapsed time, including waiting on I/O — but remember that waiting is often not something profiling can fix.

Can yappi profile a running server? Yes, start and stop it from inside the process, for example from an admin endpoint or a signal handler, and write stats to a file. It adds overhead, so enable it briefly rather than permanently.

← Back to CPU Profiling with cProfile and py-spy