PidokuInfra
09CPU and Python Profiling
On this page

CPU and Python Profiling

Advanced Intermediate 1h Difficulty 3/5 Topic 09 of 11

Prerequisites II.13, 08

1. Why this matters for GPU workloads#

Because a substantial fraction of inference performance problems are on the CPU:

CPU-side work in an inference server:
  HTTP parsing, JSON decoding
  tokenization / detokenization
  scheduler bookkeeping (per step, scales with batch)
  input tensor preparation (per step)
  sampling parameter marshalling
  kernel launches (if not using CUDA graphs)
  SSE framing and socket writes (per token)
  metrics, logging

At batch 256, prepare_inputs alone can be 3-5 ms of a 12 ms step. The GPU sits idle while Python builds tensors.

2. The tools#

py-spy         sampling profiler for Python. NO code changes, NO restart.
               ~1-2% overhead. THE tool for production.
               
perf           system-wide sampling. Sees C/C++/kernel time.
               Needs frame pointers or DWARF for good stacks.
               
cProfile       instrumenting profiler. 2-10x slowdown. Development only.

torch.profiler PyTorch operators with CPU and GPU time. Good middle ground.

bpftrace/eBPF  custom measurements in production, ~1% overhead.

Learn py-spy properly. It is the single most useful tool for a Python inference server, and it works on a running production process.

3. py-spy recipes#

Shell
# What is every thread doing RIGHT NOW? (for a hang or a slow moment)
py-spy dump --pid $(pgrep -f vllm) --locals

# Live top-like view
py-spy top --pid $(pgrep -f vllm)

# Flame graph, including time spent BLOCKED (crucial for servers)
py-spy record -o profile.svg --pid $(pgrep -f vllm) --duration 60 --idle

# Native extensions too (shows C/CUDA frames)
py-spy record -o profile.svg --pid <pid> --duration 60 --native

The --idle flag is essential for inference servers. By default py-spy shows only on-CPU time; most of an inference server’s wall time is spent waiting (on the GPU, on locks, on the network), and --idle includes those frames.

The --native flag shows time inside PyTorch’s C++ and CUDA calls, which is where a lot of the time actually is.

4. Reading a flame graph#

Width = time. Height = stack depth. Look for WIDE PLATEAUS.

     ┌───────────────────────────────────────────────────────┐
     │                    engine.step()                       │
     ├──────────────┬─────────────────┬──────────────────────┤
     │ schedule()   │  prepare_inputs │      forward()       │
     ├──────┬───────┼──────┬──────────┼──────────────────────┤
     │can_  │append │build │ torch.   │  cudaGraphLaunch     │
     │alloc │_slots │lists │ tensor() │                      │
     └──────┴───────┴──────┴──────────┴──────────────────────┘
              ↑                ↑
        wide → optimize   wide → optimize

Ignore depth; look at width. A 30-frame-deep stack that’s 2 pixels wide costs nothing.

Common wide plateaus in inference servers:

torch.tensor(python_list)      → building tensors from Python lists is slow.
                                  Preallocate and use in-place fills.
list comprehensions over
  request objects              → at batch 256, per-request Python work adds up.
                                  Use flat arrays / numpy.
json.dumps / json.loads        → use orjson or msgspec (3-10x faster)
tokenizer calls                → ensure the fast (Rust) tokenizer is used
logging.info with f-strings    → f-strings are evaluated even if the log level
                                  filters them out. Use lazy formatting.

5. Recipe — diagnosing a CPU-bound decode loop#

Shell
# 1. Confirm it's CPU-bound
python -c "
import torch
from torch.profiler import profile, ProfilerActivity
with profile(activities=[ProfilerActivity.CPU, ProfilerActivity.CUDA]) as p:
    run_decode_steps(10)
t = p.key_averages()
print('CPU', sum(e.self_cpu_time_total for e in t)/1e3, 'ms')
print('GPU', sum(e.self_device_time_total for e in t)/1e3, 'ms')
"

# 2. If CPU >> GPU, find where
py-spy record -o cpu.svg --pid <pid> --duration 60 --idle --native

# 3. Confirm the fix
# (re-measure after each change)
TYPICAL FINDINGS AND FIXES:

FINDING                                  FIX
prepare_inputs building lists            preallocate numpy arrays, fill in place
per-request Python objects in the        flatten into arrays; avoid attribute
  scheduler hot path                       access in loops
tokenizer called synchronously           move to a thread pool (it releases the GIL)
json serialization                       orjson / msgspec
per-token logging                        sample or remove
sampling params rebuilt per step         cache; only update what changed
Python-level stop-string checking        do it incrementally, not full re-scan

6. The GIL#

Python threads do not run Python bytecode in parallel (Section II.05).
For an inference server this means:

  ✓ Tokenization in a thread pool works (Rust tokenizer releases the GIL)
  ✓ CUDA calls release the GIL
  ✓ I/O releases the GIL
  ✗ Scheduler bookkeeping does NOT parallelize across threads
  ✗ A CPU-heavy Python callback BLOCKS the engine loop

→ separate the API process from the engine process (Section VIII.01)
→ keep the engine loop's Python work minimal

Diagnosing GIL contention:

Shell
py-spy dump --pid <pid>
# If several threads show "waiting for GIL" or are stuck in Python frames
# while one thread runs, you have contention.

py-spy top --pid <pid>
# Look at the %Own column per thread.

7. perf for the native side#

Shell
# What is the process doing at the C/C++ level?
perf record -F 99 -g --call-graph dwarf -p <pid> -- sleep 30
perf report --stdio --sort=dso,symbol | head -40

# Hardware counters — classify the workload
perf stat -e cycles,instructions,cache-misses,branch-misses -p <pid> -- sleep 10
IPC < 1.0 with high cache-misses  → memory-bound CPU work (pointer chasing)
IPC < 1.0 with high branch-misses → branchy (interpreter, tokenizer)
IPC > 2.5                         → well-optimized numeric code

For an inference server’s engine process, expect IPC around 0.8-1.5 (Python-dominated). If you’re at 0.3, something is pathologically cache-hostile.

8. Off-CPU analysis — where servers actually spend time#

Shell
# What is the process BLOCKED on?
py-spy record -o offcpu.svg --pid <pid> --duration 60 --idle

# Or with bpftrace: stack traces at every context switch
bpftrace -e '
  kprobe:finish_task_switch /pid == PID/ { @[kstack, ustack] = count(); }
' -c "sleep 30"
Typical blocked time in an inference server:
  cudaStreamSynchronize     waiting for the GPU (normal, if brief)
  epoll_wait                waiting for requests (normal)
  futex                     waiting for a lock (investigate if large)
  read/write                network I/O
  sem_wait                  IPC between API and engine processes

A large futex share means lock contention — usually the scheduler’s data structures being accessed from multiple threads. Reduce the critical section or restructure.

9. Production implications#

  • Ship py-spy in your production image. The time to install tools is the time the incident is ongoing.
  • Use continuous profiling (Pyroscope, Parca, Grafana Phlare) so you have the profile from before the incident.
  • Profile the engine process and the API process separately. They have different bottlenecks.
  • Watch CPU per GPU. 8-16 cores per GPU is the guidance (Section II.01); verify you have it and that you’re not throttled (Section II.12).
  • The engine loop’s Python cost scales with batch size. Profile at your maximum batch, not at batch 1.
  • Never leave cProfile enabled.

10. Common mistakes#

Profiling without --idle. Misses most of a server’s wall time.

Using cProfile on a server. Changes what you’re measuring.

Assuming the GPU is the bottleneck. At batch 1 and for small models, it often isn’t.

Profiling at batch 1 when production runs at batch 128. Different bottlenecks.

Not profiling the API process. It’s a separate process with separate problems.

Ignoring lock contention.

Optimizing a wide plateau in a background thread that isn’t on the critical path.

11. Hands-on exercise#

A. Learn py-spy. On a running inference server, run py-spy dump, py-spy top, and py-spy record --idle --native. Identify: the engine loop thread, the API threads, and where time goes in each.

B. Find the CPU/GPU split. Measure self_cpu_time_total and self_device_time_total for a decode step at batch 1, 32, and 256. At which batch does CPU become significant?

C. Optimize a plateau. Find the widest CPU plateau in the engine loop. Optimize it (likely prepare_inputs). Measure the end-to-end improvement. Was it worth it? (Apply Amdahl first.)

D. Demonstrate GIL contention. Add a CPU-heavy Python callback to the decode loop. Measure the ITL impact. Confirm with py-spy top that threads are contending.

E. Off-CPU. Profile with --idle and identify what the process blocks on and for how long. Is any of it unexpected?

12. Interview questions#

  1. Why does CPU profiling matter for a GPU workload?
  2. What does py-spy --idle show that the default doesn’t, and why does it matter for servers?
  3. How do you determine whether an inference step is CPU-bound or GPU-bound?
  4. What is GIL contention and how would you detect it in a running server?
  5. Why does the engine loop’s CPU cost scale with batch size?
  6. What does a low IPC tell you about a workload?
  7. How would you profile a production server without restarting it?

13. Further reading#

  • [REFERENCE] py-spy documentation
  • [FUNDAMENTAL] Brendan Gregg, flame graphs and off-CPU analysis
  • [REFERENCE] PyTorch Profiler documentation
  • [REFERENCE] Pyroscope / Parca for continuous profiling
  • Next: 10 — Metrics, Prometheus, Grafana
esc

↑↓ navigate↵ openesc close