Logs, metrics and traces.

This is the craft of making a running program keep a diary, so that when something goes wrong you can work out what happened afterwards, without having been there and without reading the code.

You need it because the code is the same for every request and the behavior isn’t. Your server on the Spark will one day be slow for some requests and fine for others, and the source file will look exactly like it did yesterday. The only evidence is what the program wrote down while it was happening. It’s the difference between a teammate saying “the agent feels slow sometimes” and you answering with which step, which requests, and since when. It’s also how you’d back up any claim about your server against Fireworks.

It builds on p99 and load testing, where the slowest few requests turned out to matter more than the average, and on the streaming server from Baseline: my Spark vs Fireworks. After this, every change you make to that server, starting with Batching and continuous batching, is something you can watch working or failing.

Today

• Say what each of the three kinds of record answers (a line per event, running counts and timings, and the timed path of one request), what each one costs, and why you need all three, plus a tool that shows which line of code is busy, to debug a live system.
• Make your inference server write all three yourself: one searchable line per request stamped with a request ID, running counts and timing tallies in the format Prometheus (the standard collector) reads, and a record that follows one request across two separate programs, using OpenTelemetry (the standard way to produce them).
• Read a dashboard built on a three-number recipe (how many requests, how many failed, how long they took), and know why you must never break a metric down per user.
• Find a slowdown someone else planted, on 5% of requests, using only what the server wrote down. No reading the code.
• Write a reliability target for time to first token (like “99% of requests start answering within 250 ms”), work out how much failure it allows and how fast you’re using that allowance up, and explain why that, not a busy CPU, is what should wake someone at 3am.

You’ll want p99 and load testing first (histograms, percentiles, and load that keeps arriving whether or not the server keeps up), plus the streaming server from Baseline: my Spark vs Fireworks, where you met time to first token and the gap between tokens. Everything runs on a stand-in server on your Mac first, so the Spark only matters for the last task. Budget two evenings.

The Problem

Your Spark is serving Llama to an agent harness a teammate wrote. One morning there is a message: “the agent sometimes stalls for a second or so before it starts answering. Not always. Started last night maybe?”

You look at what you have. The benchmark harness from the baseline lesson says p50 TTFT is fine. You run five requests by hand: all fast. You open the server’s terminal and scroll through forty thousand lines of got request and done, with no way to tell which done belongs to which got request, or which ones were slow. You read the code. It looks exactly like it did last week, because it is exactly the same code.

That last point is the whole lesson. You can’t debug production by reading code, because the code is the same for every request and the behavior isn’t. What changed is everything around the code: the inputs (one customer started sending prompts with code blocks), the load (a batch job runs at 2am now), the dependencies (one database shard is sick), and the timing between requests (two of them grabbing the same lock at once). None of that is in the source file. It only exists in the running system, and the running system forgets everything the moment it happens, unless you made it write things down.

Making it write the right things down, in a form you can search and add up later, is observabilityobservabilityHow well you can figure out what a running system is doing, and why, from the outside, using only what it reports about itself. The word comes from control theory.. The three classic forms of “writing things down” are logs, metrics and traces. By the end of this lesson you will have all three on your server, and you will use them to find a fault you don’t know the location of.

The Idea

Three ways to write things down

Think of a restaurant on a busy night. There are three ways to find out why table 12 waited forty minutes.

• The order slips. Every event is written down as it happens: “19:02 table 12 ordered”, “19:31 grill fired table 12”. Detailed, and you can read any one of them. But a busy night makes thousands, and to answer “were we slow tonight?” you’d have to read them all.
• The tally board. A few numbers kept running all night: orders taken, orders sent back, how many tickets are on the rail right now, how long dishes took, bucketed. Tiny, cheap, great for “are we slow?”, and useless for “why was table 12 slow?”, because the tally doesn’t remember tables.
• Following one ticket. Staple a timestamp to the ticket at every station it passes: waiter, grill, plating, pass. For one order you see exactly where the forty minutes went: twenty-eight of them sat on the grill rail.

Those are logs, metrics and traces.

• A loglogA timestamped record of one event, written by the program as it happens. One line per event: “request 7f3a finished in 1.2 s”. answers what happened, in detail, for this one event?
• A metricmetricA number tracked over time, usually aggregated: a count of requests, the current queue length, a histogram of latencies. Cheap because it doesn’t keep per-request detail. answers how much, how often, how fast, across everything, over time?
• A tracetraceThe full path of one request through a system, recorded as a tree of timed steps (spans), possibly across many processes and machines. answers where did the time go inside this one request?

Each pillar is cheap where another is expensive, which is why you want all three and why they are wired together by one shared thing: an ID.

Logs: events, made searchable

A print("done") is a log, a bad one. Three upgrades turn it into something you can debug with.

Structure. Write each event as one JSON object per line, not a sentence. "request done in 1067 ms for user-0412" is readable but you can only grep it. {"msg": "request done", "dur_ms": 1067, "user": "user-0412"} you can filter (dur_ms > 1000), group (by user), and count, with jq on your laptop or a log store at work. This is a structured logstructured logA log line written as machine-readable key-value fields (usually one JSON object per line) instead of free text, so tools can filter and aggregate on the fields..

A request id on every line. A server handling 16 requests at once interleaves their log lines. Without an ID you can’t tell which lines belong together. Generate an ID when the request arrives (or take the one the caller sent in an X-Request-ID header), stash it somewhere every function can reach without passing it by hand, and have the log formatter stamp it on every line. In async Python that “somewhere” is a contextvarcontextvarA variable from Python’s contextvars module whose value is private to the current task or thread, so concurrent requests each see their own value. The async-safe version of a global.. Return the same ID to the caller in a response header, so when your teammate says “request 7f3a was slow”, you can find every line it wrote.

Levels. Each line gets a severity: DEBUG (chatter for developers), INFO (normal events worth keeping), WARNING (something odd that recovered), ERROR (a request failed). In production you usually keep INFO and above.

Then the cost, which is the thing nobody tells you. Say 1,000 requests a second, ten log lines per request, 500 bytes per line. That’s 5 MB a second, which is 432 GB a day. Log stores charge by the gigabyte ingested and stored. So big systems samplinglog samplingKeeping only a fraction of events, for example every error but 1% of successful requests, to cut storage cost while keeping the interesting cases.: keep every error and every slow request, and maybe 1% of the boring successful ones. On your one server you can keep everything. Your company can’t.

The other cost is time. A JSON log line formatted in Python cost about 4 µs on my Mac (writing to memory, Python 3.14). Nothing next to a 500 ms request, a lot inside a loop that runs per token.

Metrics: numbers you can add up

A metric throws away the details on purpose so it can be kept forever and summed across machines. There are three kinds, and Prometheus (the standard open-source metrics system) names them like this:

• A countercounterA number that only goes up: total requests, total errors, total tokens generated. You look at how fast it climbs, not its value.. Total requests served. Its value is meaningless (it resets when the process restarts); its rate is everything. “Requests per second over the last minute” is the counter’s slope.
• A gaugegaugeA number that can go up and down and is read as-is: requests in flight right now, queue length, memory used, KV cache fraction in use.. Requests in flight right now. Queue depth. Memory in use.
• A histogramhistogramIn metrics, a set of counters, one per latency range (“bucket”), plus a total count and sum. Each observation increments the bucket it falls in. Percentiles are estimated from the bucket counts later.. Each latency increments one bucket counter. You met the idea in the tail latency lesson as the HDR histogram. Prometheus histograms are the same idea with buckets you choose.

Prometheus histograms are cumulative bucketscumulative bucketsEach bucket counts all observations less than or equal to its upper bound (le = “less or equal”), so the counts only grow from bucket to bucket and the last one, le=“+Inf”, equals the total.. Here’s what my instrumented stand-in server printed for its end-to-end latency after 300 requests:

llm_request_duration_seconds_bucket{le="0.25"} 0.0
llm_request_duration_seconds_bucket{le="0.5"} 102.0
llm_request_duration_seconds_bucket{le="0.75"} 298.0
llm_request_duration_seconds_bucket{le="1.0"} 300.0
... (every bucket after this also says 300)
llm_request_duration_seconds_bucket{le="+Inf"} 300.0
llm_request_duration_seconds_count 300.0
llm_request_duration_seconds_sum 167.57

Read it as: 102 requests took at most 0.5 s, 298 at most 0.75 s, all 300 at most 1 s, and together they took 167.6 s (so the mean was 559 ms). That’s the whole histogram: a dozen numbers, however many requests it has seen. Recording one observation took about 0.4 µs on my Mac.

Which metrics? Two recipes cover almost everything:

• The RED methodRED methodTom Wilkie’s recipe for request-driven services: track Rate (requests per second), Errors (failed requests per second) and Duration (a latency histogram), per service or endpoint., for things that serve requests: Rate, Errors, Duration. This is what your users feel.
• The USE methodUSE methodBrendan Gregg’s recipe for resources (CPU, memory, disks, GPU, a lock, a queue): for each, check Utilization (how busy), Saturation (how much work is waiting) and Errors., for resources: Utilization, Saturation, Errors. For your server: GPU utilization, and saturation is the queue of requests waiting for the GPU lock.

The Google SRE book’s “four golden signals” (latency, traffic, errors, saturation) are the same idea, the two recipes merged.

Labels, and the explosion

Metrics get dimensions through labellabelA key-value tag on a metric, like status=“error” or endpoint=“/v1/chat”. Every distinct combination of label values creates a separate time series that is stored on its own.s. llm_requests_total{status="ok"} and llm_requests_total{status="error"} are two separate counters, two time seriestime seriesOne stream of (timestamp, value) points for one metric with one exact set of label values. The unit Prometheus stores, indexes and charges memory for..

The trap is in the multiplication. One histogram with 12 buckets, labelled by endpoint (5 values) and status (3 values), is about 12 × 5 × 3 = 180 series. Fine. Now someone adds user_id as a label “so we can see per-user latency”. With 100,000 users that’s 18 million series. Each active series costs memory in Prometheus (on the order of kilobytes), so this is tens of gigabytes, and it happens silently the day traffic grows. This is a cardinality explosioncardinality explosionWhen a metric’s label values have so many possible combinations that the number of time series blows up, eating memory and slowing every query. Classic culprits: user ids, request ids, full URLs, raw prompts., and it is one of the most common ways people take down their own monitoring.

The rule: metric labels must come from a small, fixed set (status code, endpoint, model name, region). Anything unbounded (user id, request id, prompt text) goes in logs and trace attributes, which are stored per event and built for it.

Percentiles come from buckets, not from averages

The dashboard most people build first plots average latency. Play with this and you’ll see why that’s a mistake.

Two lessons from that figure.

Percentiles are estimated from buckets. Prometheus’s histogram_quantile() finds the bucket that the 99th-percentile request falls in and assumes requests are spread evenly inside it. With a wide bucket the estimate drifts: set 5% and +1000 ms, and p99 lands in the 1 to 1.25 s bucket, where the estimate is off by almost 100 ms. So put bucket edges where your decisions are. If your goal is “TTFT under 250 ms”, have an edge at exactly 0.25, so “how many were under 250 ms” is an exact count, not a guess.

You cannot average percentiles. The p99 of the fleet is not the average of each machine’s p99. In fleet mode at 5% and +1000 ms, one sick server out of four pushes the true fleet p99 to about 1.2 s, while the average of the four p99s says 730 ms. Counts add up, percentiles don’t. Prometheus histograms are counters, so you add them first and estimate once:

# right: sum the bucket rates across all instances, then estimate p99
histogram_quantile(0.99, sum by (le) (rate(llm_request_duration_seconds_bucket[5m])))

# wrong: a p99 per instance, then averaged
avg(histogram_quantile(0.99, rate(llm_request_duration_seconds_bucket[5m])))

This is the same rule the tail latency lesson gave for HDR histograms, now in the language your dashboards speak. (Prometheus also has “summaries”, which compute percentiles inside each process. Those can’t be added across machines at all, which is why histograms are usually the better choice.)

Traces: where the time went in one request

A metric told you p99 got worse. It can’t tell you why, because it has forgotten every individual request. A trace keeps one request whole.

A trace is a tree of spanspanOne timed step inside a trace: a name, a start time, a duration, a parent, and key-value attributes. “tokenize took 2 ms”, “database query took 400 ms”.s. The first span, the root spanroot spanThe top span of a trace, with no parent. Usually “the whole request as the first service saw it”., covers the whole request. Each step inside it is a child span; steps inside those are grandchildren. Every span records which span is its parent, and every span in the tree shares one trace idtrace idA random 128-bit number shared by every span of one request, across every service. It is how the collector knows which spans belong together..

Drawn on a timeline, a trace is a waterfall. Here is one streaming request to an inference server, through a gateway, a quota database check, the server, and the model. Plant a fault and see which span grows.

Things to notice while you click:

• Slow DB happens in the gateway, before the server is even called. The server’s metrics would be perfect while users suffer. Only something measuring the whole request (the trace’s root span, or the gateway’s own metrics) sees it.
• Cache lock is a span whose own work takes microseconds but whose duration is 300 ms: it was waiting. A CPU profiler would say that code is idle. The trace says it’s the problem.
• GPU queue grows on every request at once, which is how you tell “overloaded” from “broken”.
• Slow decode doesn’t touch TTFT at all. A TTFT-only dashboard says all is well while every answer takes 70% longer.

Spans also carry attributespan attributeA key-value pair attached to a span, like user=“user-0412” or prompt_chars=176. Unlike metric labels, these can have unbounded values, because they are stored per span.s: the user, the prompt length, the model, the number of output tokens. This is where the high-cardinality detail that’s banned from metrics lives. When you find the slow traces, their attributes tell you what they have in common.

Context propagation: one trace, many processes

Within one process, the tracing library keeps track of “the current span” in a contextvar, so any new span automatically becomes its child. Across processes there’s no shared memory, so the parent has to travel with the request. That’s context propagationcontext propagationPassing the trace id and current span id from one service to the next inside the request itself (usually an HTTP header), so the receiving service’s spans join the same trace., and on HTTP it’s one header defined by the W3C Trace ContextTrace ContextThe W3C standard that defines the traceparent header (and tracestate) so tracing works across services written in different languages with different tracing libraries. standard: traceparent.

The last field carries the sampling decisionhead samplingDeciding at the very start of a request whether to record its trace (say, 1 in 100), and passing that decision downstream in the traceparent flags so every service agrees.. If the gateway decided not to record this request, every service downstream skips it too, so you never get half a trace. The alternative is tail samplingtail samplingDeciding whether to keep a trace after it finishes, so you can keep every slow or failed one and only a few fast ones. Needs a collector that buffers all spans of a trace until it completes., which keeps all the slow and broken traces and drops most of the boring ones. When I ran the current Python SDK, it printed flags 03: the extra bit is a newer Trace Context addition that marks the trace id as random. Your version may differ.

OpenTelemetry, Prometheus, Jaeger, Grafana

OpenTelemetryOpenTelemetryAn open standard plus SDKs (for most languages) for producing traces, metrics and logs, and a wire protocol (OTLP) for shipping them. Vendor neutral: you instrument once and send the data anywhere. Often shortened to OTel. (OTel) is the standard way to produce telemetry. You write against its API (tracer.start_as_current_span(...)), and an exporter ships the data over OTLPOTLPOpenTelemetry Protocol: the wire format for sending spans, metrics and logs to a backend, over gRPC (port 4317) or HTTP (port 4318). to whatever backend you choose. Before OTel, switching tracing vendors meant re-instrumenting every service. Now it means changing an endpoint.

The backends you’ll run:

• PrometheusPrometheusAn open-source metrics system: it scrapes /metrics endpoints on a schedule, stores the numbers as time series, and answers queries in its language, PromQL. uses a pull model: your server only keeps counters in memory and serves them as text at /metrics; Prometheus visits every few seconds and records them. Pulling is pleasantly robust. A dead server shows up as a failed scrape (the built-in up metric goes to 0), and your app never blocks because the monitoring system is slow.
• Jaeger stores traces and lets you search them (“show me traces over 1 s”) and view the waterfall.
• Grafana draws dashboards from Prometheus queries.

Recent FastAPI releases have started shipping optional built-in OpenTelemetry support, and there are auto-instrumentation packages for most frameworks. They’re worth using at work. Today you’ll write the spans by hand, so you know what those packages do.

SLIs, SLOs and error budgets

Dashboards are for looking. At 3am nobody is looking, so something has to decide when to wake you. The Google SRE book’s answer starts with three terms:

• An SLISLIService level indicator: a measured fraction of good events. “Fraction of requests whose first token arrived within 250 ms.” is a measurement of how users experience the service, as a ratio: good events over all events.
• An SLOSLOService level objective: a target for an SLI over a window. “99% of requests get their first token within 250 ms, measured over 30 days.” is the target for it: “99% of requests get their first token within 250 ms, over 30 days.”
• The error budgeterror budgetThe amount of badness the SLO allows: 1 minus the target. With a 99% SLO, 1% of requests may be bad. It’s a budget you can spend on deploys, experiments and incidents. is everything the SLO lets you get wrong: 1% of requests. If you serve a million requests a month, 10,000 can be slow and you’ve still met your goal.

Why not aim for 100%? Because the last nines are wildly expensive, users can’t tell 99.99% from 100% through their own flaky Wi-Fi, and a team that may never break anything never ships anything. The budget turns “is it reliable enough?” from an argument into arithmetic: budget left means ship; budget gone means slow down and fix things.

Then the burn rateburn rateHow fast you’re spending the error budget, relative to spending it exactly evenly over the window. Burn rate = (bad fraction right now) / (1 − SLO target). 1 means “on track to use exactly all of it”; 10 means “gone in a tenth of the window”.:

burn rate = (fraction of bad requests, recently) / (1 − SLO)

With a 99% SLO, 1% bad is burn rate 1: you’ll use exactly the whole budget by day 30. 6% bad is burn rate 6: the budget is gone in 5 days.

Alert on symptoms, not causes

There are two kinds of alerts. A symptom is something users feel: errors, slowness, the SLO burning. A cause is something you guess might lead to that: CPU at 90%, one replica down, a disk 80% full, GPU memory high.

Page on symptoms. A cause alert fires when nothing is wrong (the GPU at 100% is the GPU doing its job; one replica down while the others absorb the load is fine) and stays silent when something is (the slow-DB fault raises no CPU, no memory, nothing). Every page that turns out not to matter teaches the person on call that pages don’t matter. That’s alert fatiguealert fatigueWhen people get so many alerts that don’t need action that they start ignoring or muting them, including the real ones., and it’s how real incidents get slept through. Rob Ewaschuk’s rule of thumb from Google: every page should be urgent, actionable, and about something users notice. Causes belong on dashboards, for the human who got paged to look at next.

Burn rate is the symptom alert done well. “14.4x over the last hour” means you’ll lose 2% of the month’s budget in that hour, which is worth a page. Requiring a short window (say 5 minutes) to also be burning makes the alert stop as soon as the problem stops.

The fourth pillar: profiles

A trace says which span is slow. It doesn’t say which line of code inside the span is burning the time. That’s a profilerprofilerA tool that measures where a program spends its time, by function and line. A sampling profiler looks at the call stack many times a second and counts what it sees.’s job, and you used one, py-spy, in Why is Python slow?. The production version is continuous profilingcontinuous profilingRunning a low-overhead sampling profiler all the time on every production machine and storing the results, so you can ask “what was this service doing at 3:12am?” after the fact.: a sampler runs always, at low rate, on every machine, so you can ask what the code was doing at 3:12am after the fact. Google described doing this fleet-wide in 2010 (Google-Wide Profiling); open-source tools like Pyroscope and Parca do it today, and OpenTelemetry is adding profiles as a fourth signal.

One subtlety the cache-lock fault teaches: a normal CPU profile only counts threads that are running. A thread stuck waiting for a lock isn’t running, so it’s invisible. You need a wall-clock profilewall-clock profileA profile that samples every thread whether it is running or waiting, so time spent blocked on locks, I/O or sleep shows up. py-spy’s —idle flag includes idle threads., or py-spy dump, which prints every thread’s current stack, waiting or not.

Observing an LLM server

Everything above applies, with a few numbers that only LLM serving has. Most come straight from the baseline lesson:

vLLM and SGLang already expose most of these on a /metrics endpoint in Prometheus format. The names change between versions, so curl it and look rather than trusting a blog post.

For agents, the trace is the natural unit. One agent run is one trace; each model call and each tool call is a span, with attributes for the model, input and output tokens, the tool name and whether it errored. The waterfall then answers questions that are otherwise miserable: “why did this run take 4 minutes?” (eleven sequential tool calls, one of them a 90 s web fetch), “where do the tokens go?” (the context re-sent on every step). OpenTelemetry has draft conventions for these attribute names (the gen_ai.* attributes); most LLM tracing products are this idea with a nice UI.

Build It

You’ll instrument a stand-in server that has the same shape as server_naive.py (a FastAPI app streaming SSE, a limit on concurrent “GPU” work, prefill then decode) but fakes the model with sleeps, so it runs anywhere and the numbers are repeatable. Then you’ll port the instrumentation to the real one on the Spark.

obs/
  deps.py          # fake dependencies, with one hidden fault (don't read the bottom)
  fakellm.py       # the server you instrument
  loadgen.py       # open-loop load
  docker-compose.yml, prometheus.yml, grafana/   # the backends
  app.log          # your JSON logs

mkdir -p ~/workbench/obs && cd ~/workbench/obs
python3 -m venv .venv && source .venv/bin/activate
pip install fastapi uvicorn httpx prometheus_client \
  opentelemetry-sdk opentelemetry-exporter-otlp-proto-http

# deps.py: the "dependencies" of the fake inference server.
# One of three faults is switched on at startup, chosen from FAULT_SEED.
# Don't read past this comment until you've found it with telemetry.
import asyncio, hashlib, os, random, threading, time

_rng = random.Random(os.environ.get("FAULT_SEED", "0"))
_FAULT = _rng.choice(["cache_lock", "slow_quota", "tokenizer"])
if os.environ.get("NO_FAULT"):
    _FAULT = "none"
_cache_lock = threading.Lock()
_cache: dict[str, bool] = {}


def reveal() -> str:
    return _FAULT


async def quota_check(user_id: str) -> bool:
    """Pretend database call: is this user under their rate limit?"""
    await asyncio.sleep(0.003)
    if _FAULT == "slow_quota" and int(hashlib.md5(user_id.encode()).hexdigest(), 16) % 20 == 0:
        await asyncio.sleep(0.4)  # this tenant's row lives on a sick shard
    return True


def tokenize(prompt: str) -> list[int]:
    """Pretend tokenizer. ~1 token per 4 chars."""
    time.sleep(0.0005 + len(prompt) * 2e-7)
    if _FAULT == "tokenizer" and "```" in prompt:
        time.sleep(0.25)  # pathological regex on code fences
    return list(range(max(1, len(prompt) // 4)))


def cache_lookup(prefix_key: str) -> bool:
    """Pretend prefix cache. Shared by every request, guarded by a lock."""
    with _cache_lock:
        if _FAULT == "cache_lock" and random.random() < 0.05:
            time.sleep(0.3)  # "compaction" while holding the lock
        hit = prefix_key in _cache
        _cache[prefix_key] = True
        return hit

# fakellm.py: a stand-in for server_naive.py with the same shape and fake timings.
import asyncio, json, random, time, uuid

from fastapi import FastAPI
from fastapi.responses import StreamingResponse
from pydantic import BaseModel

import deps

app = FastAPI()
gpu = asyncio.Semaphore(4)       # 4 "batch slots"; the rest queue
PREFILL_S_PER_TOKEN = 0.0004     # 400 µs per prompt token
ITL_S = 0.02                     # 20 ms per output token (50 tok/s)


class ChatRequest(BaseModel):
    messages: list[dict]
    max_tokens: int = 64
    user: str = "anon"


@app.get("/health")
async def health():
    return {"ok": True}


@app.post("/v1/chat/completions")
async def chat(req: ChatRequest):
    rid = f"chatcmpl-{uuid.uuid4().hex[:12]}"
    prompt = "\n".join(m.get("content", "") for m in req.messages)

    async def events():
        await deps.quota_check(req.user)
        ids = await asyncio.to_thread(deps.tokenize, prompt)
        await asyncio.to_thread(deps.cache_lookup, prompt[:64])
        async with gpu:
            await asyncio.sleep(len(ids) * PREFILL_S_PER_TOKEN)        # prefill
            n = random.randint(req.max_tokens // 2, req.max_tokens)
            for i in range(n):                                          # decode
                yield f"data: {json.dumps({'id': rid, 'choices': [{'delta': {'content': f'tok{i} '}}]})}\n\n"
                await asyncio.sleep(ITL_S)
        usage = {"prompt_tokens": len(ids), "completion_tokens": n}
        yield f"data: {json.dumps({'id': rid, 'choices': [{'delta': {}, 'finish_reason': 'length'}], 'usage': usage})}\n\n"
        yield "data: [DONE]\n\n"

    return StreamingResponse(events(), media_type="text/event-stream")

# loadgen.py: open-loop load at a fixed rate.  usage: python loadgen.py RATE SECONDS
import asyncio, random, sys, time
import httpx

URL = "http://127.0.0.1:8000/v1/chat/completions"
RATE = float(sys.argv[1]) if len(sys.argv) > 1 else 5.0
DURATION = float(sys.argv[2]) if len(sys.argv) > 2 else 60.0
USERS = [f"user-{i:04d}" for i in range(500)]
PROMPTS = [
    "Summarize this page about solar panels." * 8,
    "Rank these five documents for the query 'cheap flights'." * 12,
    "Explain this code:\n```python\nprint('hi')\n```" * 4,
    "Write a haiku about latency.",
]
WEIGHTS = [50, 30, 5, 15]


async def one(client: httpx.AsyncClient):
    body = {"messages": [{"role": "user", "content": random.choices(PROMPTS, WEIGHTS)[0]}],
            "max_tokens": 32, "user": random.choice(USERS)}
    try:
        async with client.stream("POST", URL, json=body) as r:
            async for _ in r.aiter_lines():
                pass
    except httpx.HTTPError as e:
        print("error:", type(e).__name__)


async def main():
    async with httpx.AsyncClient(timeout=30, limits=httpx.Limits(max_connections=500)) as client:
        tasks, t0, i = [], time.perf_counter(), 0
        while time.perf_counter() - t0 < DURATION:
            tasks.append(asyncio.create_task(one(client)))
            i += 1
            await asyncio.sleep(max(0, i / RATE - (time.perf_counter() - t0)))
        await asyncio.gather(*tasks)
        print(f"sent {i} requests")

asyncio.run(main())

# docker-compose.yml
services:
  jaeger:
    image: jaegertracing/jaeger:latest      # Jaeger v2; UI on 16686, OTLP on 4317/4318
    ports: ["16686:16686", "4317:4317", "4318:4318"]
  prometheus:
    image: prom/prometheus:latest
    ports: ["9090:9090"]
    volumes: ["./prometheus.yml:/etc/prometheus/prometheus.yml:ro"]
    extra_hosts: ["host.docker.internal:host-gateway"]   # needed on Linux (the Spark)
  grafana:
    image: grafana/grafana:latest
    ports: ["3000:3000"]
    environment:
      GF_AUTH_ANONYMOUS_ENABLED: "true"
      GF_AUTH_ANONYMOUS_ORG_ROLE: Admin
    volumes: ["./grafana/datasources.yml:/etc/grafana/provisioning/datasources/datasources.yml:ro"]

# prometheus.yml
global:
  scrape_interval: 5s
scrape_configs:
  - job_name: fakellm
    static_configs:
      - targets: ["host.docker.internal:8000"]

# grafana/datasources.yml
apiVersion: 1
datasources:
  - name: Prometheus
    type: prometheus
    url: http://prometheus:9090
    isDefault: true

import contextvars, json, logging, uuid

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")

class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        """Return one JSON line: ts, level, msg, request_id, plus any extra fields."""
        ...

log = logging.getLogger("fakellm")
# a handler writing to app.log with your formatter; level INFO

from prometheus_client import Counter, Gauge, Histogram, generate_latest, CONTENT_TYPE_LATEST
from fastapi import Response

TTFT = Histogram("llm_ttft_seconds", "Time to first token", buckets=(...))  # choose them

@app.get("/metrics")
def metrics():
    return Response(generate_latest(), media_type=CONTENT_TYPE_LATEST)

from opentelemetry import propagate, trace
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

provider = TracerProvider(resource=Resource.create({"service.name": "fakellm"}))
provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter(endpoint="http://localhost:4318/v1/traces")))
trace.set_tracer_provider(provider)
tracer = trace.get_tracer("fakellm")

ctx = propagate.extract(request.headers)        # the caller's trace, if any
with tracer.start_as_current_span("chat", context=ctx, attributes={...}) as root:
    with tracer.start_as_current_span("quota_check"):
        ...
    # tokenize, cache_lookup, queue_wait (just the wait for the semaphore), prefill, decode

# Rate: requests per second
sum(rate(llm_requests_total[1m]))

# Errors: fraction of requests failing
sum(rate(llm_requests_total{status="error"}[1m])) / sum(rate(llm_requests_total[1m]))

FAULT_SEED=$RANDOM uvicorn fakellm:app --port 8000      # don't echo the seed
python loadgen.py 5 600

Measure

Run each configuration at 5 requests per second for 10 minutes. Fill in your numbers.

What I measured on a Mac with the stand-in, one minute (300 requests) per run, so the p99s are rough (300 samples is thin for a p99):

(Not labelled, on purpose.) What the numbers should teach you:

• The mean moved by 2-6%. p50 barely moved at all. Every fault was nearly invisible on an average dashboard and obvious on a p99 one. TTFT p99 moved 4-6x.
• Burn rate is about 5 for every fault. Each fault hurts about 5% of requests, so that’s no coincidence. A 5x burn uses up a 30-day budget in about 6 days. It would fire the slow (6x over 6 h) alert or come close, not the fast page. That’s the right answer: a real but slow problem, a ticket for the morning, not a 3am page.
• Overload looks different from all three: queue_wait grows on every request, in-flight climbs, and the bad fraction keeps rising over the run instead of sitting flat.
• Instrumentation cost on my Mac: ~0.4 µs per histogram observation, ~0.5 µs per labelled counter increment, ~8 µs per span, ~4 µs per JSON log line. Measure yours with a 100,000-iteration loop. Against a 550 ms request, all of it rounds to zero.

Break It

1. Add user as a metric label. Put labelnames=["user"] on the duration histogram, run load for a minute, and count lines: curl -s localhost:8000/metrics | wc -l. With 500 users and ~15 lines per histogram, expect several thousand lines where there were a few dozen. Now imagine 100,000 users and 50 servers, and Prometheus’s memory. Take it out and put user on the span instead.
2. Forget to extract the context. Remove context=ctx from the root span. Jaeger now shows two separate traces per request, one from loadgen and one from the server, with nothing joining them. This is what a single service that doesn’t propagate headers does to a whole company’s traces: a hole in the middle of every request.
3. Make telemetry the outage. Swap BatchSpanProcessor for SimpleSpanProcessor (exports synchronously, on every span end) and point the exporter at an address that never answers, such as http://192.0.2.1:4318/v1/traces. Watch your p99. Each span end now waits for a network timeout inside the request. Lesson: telemetry must never block the work, and its failure must not be your failure. (Check how long the exporter’s default timeout is in your version.)
4. Average the p99s. Run two copies of the server on ports 8000 and 8001, plant the fault in only one, send load to both, and add a Grafana panel with the “wrong” query from The Idea next to the right one. Measure the gap. Then write a cause alert, “CPU above 80%”, and check it against your runs: it fires for none of the three faults, because every one of them is time spent waiting, not computing. On the Spark, the equivalent “GPU above 90%” would fire on every healthy benchmark, because a busy inference server is supposed to be busy. Missed real problems plus constant false alarms: that’s alert fatigue in one panel.

Explain It Back

Answer out loud, in plain words, as if in an interview. Then check.

Go Deeper

• Benjamin H. Sigelman et al., “Dapper, a Large-Scale Distributed Systems Tracing Infrastructure” (Google technical report, 2010). The paper every tracing system descends from. Short, and the sections on sampling and overhead are still the best argument for why tracing can be always-on.
• Betsy Beyer, Chris Jones, Jennifer Petoff, Niall Richard Murphy (eds.), Site Reliability Engineering (O’Reilly, 2016), free at sre.google/books. Read “Service Level Objectives”, “Monitoring Distributed Systems” (the four golden signals) and “Embracing Risk” (error budgets). Then the companion Site Reliability Workbook chapter “Alerting on SLOs”, which derives the multi-window burn-rate alerts step by step.
• Rob Ewaschuk, “My Philosophy on Alerting” (2013, a Google doc widely linked from the SRE book). The source of “page on symptoms, not causes”. Ten minutes, and it will change what you alert on.
• Brendan Gregg, “The USE Method” (brendangregg.com/usemethod.html), and Tom Wilkie, “The RED Method: key metrics for microservices architecture” (Weaveworks / Grafana Labs blog and talks). The two checklists, from the people who coined them.
• Prometheus docs, “Histograms and summaries” (prometheus.io/docs/practices/histograms). Exactly how histogram_quantile interpolates, why summaries can’t be aggregated, and how to choose buckets. Also “Metric and label naming” in the same section for the cardinality rules.
• OpenTelemetry documentation (opentelemetry.io/docs), the Python getting-started page and the concepts pages on signals, context propagation and sampling. Check the GenAI semantic conventions page for the current state of LLM attributes.
• W3C, “Trace Context” (w3.org/TR/trace-context). The traceparent spec. Short and readable; it’s where the field layout in Figure 4 comes from.
• Charity Majors, Liz Fong-Jones, George Miranda, Observability Engineering (O’Reilly, 2022). The argument for wide structured events and high-cardinality debugging, from the people who pushed the word “observability” into software. Read it after you’ve built the three pillars, as the counterpoint.

Connections

This lesson stands on p99 and load testing (histograms, why percentiles don’t average, open-loop load) and uses the TTFT and ITL definitions from Baseline: my Spark vs Fireworks. The profiling pillar is the same py-spy from Why is Python slow?, and the cache-lock fault is the lock from Processes, threads and the GIL seen from outside. Saturation metrics are the queue from Queues and logs and Rate limits and backpressure, measured.

Next, it pays off everywhere you change the server. Batching and continuous batching should shrink the queue_wait span you just watched dominate; Paged attention and prefix caching gives you the KV-utilization and hit-rate gauges to watch; and Inside an agent harness is where one trace per agent run becomes the main debugging tool. Every one of those lessons is now a before-and-after on a dashboard instead of a guess.