Statistical Profiling in Python, Part 1: Time

17 Sep 2019 in Performance on Python, Profiling, Pprof

I was working on a profiling system at work and became jealous of Go. The Go runtime has CPU and heap profilers built into the language. You can attach to a running production service, pull a profile over HTTP, and explore it with go tool pprof — flame graphs, call trees, diffs between two snapshots — without restarting anything or deciding in advance that today was the day you would need a profile.

Python’s tools answered the same questions exactly, and were expensive enough that nobody left them running. Closing that gap meant understanding why, which is worth setting out properly before any code.

This is the first of three posts about it. Here I will look at profiling time — where a Python program’s CPU and wall-clock seconds actually go. Part 2 is about sampling the heap, and Part 3 puts both behind HTTP endpoints so that Go’s tooling can read them.

Instrumentation: count everything

A profiler shows you where an application spends time. There are two approaches for doing this.

The direct approach is to measure it all. Insert a hook at every function entry and exit, note the time, and accumulate. This is what cProfile does, what gprof did with compiler support, and what most language-level profilers reach for first.

What you get is exact: precise call counts, a complete call graph, and a guarantee that nothing was missed. If you need to know that parse_row was called 4,182,113 times, this is the only way to find out.

What you pay is per-call overhead on every call. Note the shape of that cost — it is proportional to the number of calls, not to the amount of work, so it falls hardest on exactly the small hot functions that a profile is meant to find. A function that takes 200 nanoseconds and is called ten million times gets a bookkeeping hook of a comparable size, and its measured share of runtime inflates accordingly. The tool distorts the thing it is measuring, and it distorts it most where you are looking hardest.

For a benchmark, on a workload you control, this is ok. For a service under real load it is not, and the overhead is usually enough that turning it on changes the behavior you were trying to explain.

Sampling: ask occasionally

The other approach is to stop asking the program anything and periodically interrupt it instead. Every few milliseconds, freeze, walk the call stack, record it, and resume. After a while you have a large collection of stacks, and the fraction of samples containing a function estimates the fraction of time spent in it.

The result is an estimate rather than a census. You do not learn how many times anything was called — a function called once and holding for a second, and one called a million times for a microsecond each, look identical. Rare events may never be sampled at all, and everything has error bars based on how long you sampled.

In exchange, the cost is decoupled from the program entirely. Overhead is proportional to the sampling rate, which you choose, and not to the call rate. A program making a billion calls a second and one making a thousand cost the same to profile. That single property is what makes it possible to leave a profiler switched on in production forever — and profiling in production is the entire game, because the interesting performance problems are the ones that only appear under real traffic, at real scale, with real data.

	Instrumentation	Sampling
Call counts	Exact	Unavailable
Overhead	Per call, unbounded	Per sample, chosen
Distortion	Worst on hot small functions	Roughly uniform
Rare events	Always caught	Often missed
Safe in production	No	Yes

How sampling is usually built

The classic implementation is an interval timer plus a signal, and UNIX has supplied the parts for decades.

setitimer() arms one of three timers, and the choice of timer is the choice of what you are measuring:

• ITIMER_REAL counts wall-clock time and raises SIGALRM.
• ITIMER_VIRTUAL counts time the process spends executing in user mode and raises SIGVTALRM.
• ITIMER_PROF counts user plus system CPU time and raises SIGPROF.

Arm ITIMER_PROF for 10 ms, and the kernel delivers SIGPROF every 10 ms of consumed processor time. A process blocked on a socket consumes none, so its timer does not advance and it generates no samples — the accounting falls out of the timer choice for free. Arm ITIMER_REAL instead and the samples keep coming while it waits, which is precisely the difference between a CPU profile and a wall-clock one.

The signal handler is where the work happens, and … here be dragons. A signal can arrive between any two instructions, so the handler may only call async-signal-safe functions — no malloc, no locks, nothing the interrupted code might already hold. Deadlocking a production process from inside a profiler is a very poor outcome. So a well-built handler does the minimum: walk the stack, copy frame pointers into a preallocated buffer, and get out. All the interpretation happens later, on a normal thread.

There is a third approach that is gaining steam, which is to step outside the process altogether: perf on Linux samples from the kernel, and eBPF can do it with almost no cooperation from the target. That avoids the signal-handler problem completely, but you only see native stack frames.

Which is exactly where a language runtime makes everything harder. A native stack walk of a CPython process shows you _PyEval_EvalFrameDefault several hundred times, because that is literally true and completely useless. Getting Python frames — this function, in this file, at this line — means walking the interpreter’s own frame objects, from inside a signal handler, without calling anything unsafe, while the interpreter is halfway through something.

Standing on Google’s shoulders

Google Cloud Profiler’s Python agent was the best Python sampling profiler I could find at the time I started working on this, although Pypy’s vmprof gets an honorable mention.

zprofile is a fork of Google Cloud Profiler with the cloud removed and a few additional features, including macOS and Python 2.7 support (which is unfortunately still used at work).

Python 2.7, or: how to read memory you are not allowed to read

Unfortunately PyGILState_GetThisThreadState uses CPython’s own homegrown thread-local storage, which takes a mutex. Calling it from a signal handler can deadlock against the thread you just interrupted.

There is no safe alternative. The interpreter does keep a linked list of every thread state, but walking it requires a lock (HEAD_LOCK) that is not exposed through the C API. The vmprof authors worked out the only option left, which is to read it anyway and arrange to survive being wrong:

// The API functions we use are inherently unsafe because they require holding
// a lock (HEAD_LOCK) that is not exposed. As a result, we install a segfault
// handler before doing our racy reads. If we're unable to find the thread state
// then the sample will be skipped.
//
// This hack is courtesy of the very clever authors of vmprof.
PyThreadState *UnsafeGetThisThreadState() {
  while (spinlock.test_and_set(std::memory_order_acquire));
  auto prevhandler = std::signal(SIGSEGV, &SegfaultHandler);
  int fault_code = setjmp(restore_point);
  if (fault_code == 0) {
    result = FindThreadState();
  } else {
    result = nullptr;
  }
  std::signal(SIGSEGV, prevhandler);
  spinlock.clear(std::memory_order_release);
  return result;
}

Install a SIGSEGV handler, setjmp a restore point, walk the thread list looking for a matching thread id, and if the list changes underneath you and you follow a dangling pointer into nothing, longjmp back out and drop the sample. A dropped sample costs almost nothing in a statistical profiler. A crashed production process costs quite a lot.

Obviously this is a hack. Fortunately it is fixed in Python 3.

Small things that make it portable

macOS has no clock_nanosleep, which the sampling loop uses to wake at an absolute time. Emulating it with clock_gettime plus a relative nanosleep is a few lines, adapted from PosixMachTiming, and it accepts a little drift in exchange for existing at all.

And the profiler emits a gzipped pprof Profile protobuf: which lets you load it with the standard pprof tooling:

from zprofile.cpu_profiler import CPUProfiler

p = CPUProfiler()
pprof = p.profile(30)  # seconds
with open("profile.pprof", "wb") as f:
    f.write(pprof)

$ go tool pprof -http localhost:8080 profile.pprof

Next: sampling the heap, where there is no signal to hang the design on and the sampling has to be built from scratch.