Profiling

How do stack sampling and query profiles show where time goes?

Metrics say a system is slow. Profiles say where. (How to attribute time correctly is measurement's method; this page is about leaving it on in production.) A stack sample records which function the program is running (and who called it), many times per second. After many samples, the functions that appear most often are where time goes. A flame graph is a chart of those counts.

Stack sampling is statistically cheap: the error of the estimate falls as 1/√n (n = number of samples). With 10,000 samples the relative error of a fraction is about 1%. So always-on production profiling at a low frequency (such as 100 samples per second) costs about one to two percent of the CPU. It is strictly better than attaching a profiler later to a fault that has already ended.

For data systems, the dominant time is off-CPU time: the program is waiting for I/O, a lock, or a shuffle partner. An ordinary on-CPU flame graph shows the work that is running, which may be only the least interesting 10% of the time.

Query profiling

Query profiling is the database engine's own instrumented version. Its unit is the operator (scan, join, aggregate), not the stack frame, because useful diagnoses can only be expressed in the vocabulary of a query engine: wrong join algorithm, wrong build side, spill to disk, skew, missing partition pruning.

The most under-used field in any query profile is rows estimated vs. rows actual per operator. The query planner chooses a plan using estimates of how many rows each step produces. The ratio between estimate and actual is a direct measurement of cardinality-estimation error. It is the feedback signal that a cost-based optimizer needs and almost never receives. Adaptive execution (a query engine that changes its plan while running) exists because it closes this loop at runtime instead of across separate runs.

One line: sample the stack for where, instrument the operator for why, and watch estimate-versus-actual to learn whether the planner was misled.

Case, resolvedConstructed case · Nadia at Brightcart

One label doubled the monitoring bill

A customer_id label made the metrics bill explode, a dashboard averaged p99s across servers, and nobody could find which order broke a job. Where it started: Emission →

The label. She removes customer_id from the metric (bounded labels only) and puts it in the structured log line instead. Series count falls from a billion back to a few thousand. Customer-level debugging is still possible, through logs.
The panel. She replaces the "average of p99" with a merged histogram, and sets the top bucket well above the slowest acceptable request. The honest p99 is 2.8 s, not 500 ms.
The broken row. The job now writes structured log lines with order_id and reason for every rejected row, and a histogram exemplar links the slow bucket to a sample trace. She finds the broken row in minutes.

She now understands that each signal has an answer to one kind of question and a blind spot for another.