Logging, Tracing, and Performance Metrics

At 03:12 an enterprise customer emails: "your assistant has been hanging for us all evening — sometimes eight or nine seconds before anything appears." The on-call engineer opens the dashboard. There is one latency panel on it, labelled Average response time, and it reads 495 ms, flat, green, all night.

Both parties are telling the truth. Here is the traffic from that hour, 1,000 requests:

950 requests at  100 ms 50 requests at 8000 msmean = (950 x 100 + 50 x 8000) / 1000     = (95,000 + 400,000) / 1000     = 495 ms

The average is exactly 495 ms and not a single request took 495 ms. The median request took 100 ms. The p99 request took 8,000 ms. The mean sits in an empty valley between two peaks, describing nobody's experience, and it is the only number on the dashboard.

That gap — between a system that is instrumented and a system you can actually reason about — is what the three pillars are for. Logs, metrics, and traces are not three tools to install. They are three resolutions of the same underlying stream of events, each with a different cost curve and a different blind spot, and getting real value out of them depends almost entirely on decisions that look boringly small at instrumentation time.

Structured logging: the event, not the sentence

Most logging starts as English sentences with values glued in:

log.info(f"Processed request for user {user_id} in {elapsed:.2f}s using {model}")

This is fine for a human reading one line and useless for anything else. To answer "what is p95 latency for model B among enterprise users on mobile?" you would have to write a regular expression against prose that a teammate will rephrase next sprint, and the regex will break silently. There is no way to filter, group, or aggregate a sentence.

A structured log emits the same information as a machine-readable object:

1import json, logging, time, uuid2from pythonjsonlogger.json import JsonFormatter   # python-json-logger 3+34handler = logging.StreamHandler()5handler.setFormatter(JsonFormatter(6    "%(asctime)s %(levelname)s %(name)s %(message)s",7    rename_fields={"levelname": "level", "asctime": "ts"},8))9log = logging.getLogger("assistant")10log.addHandler(handler)11log.setLevel(logging.INFO)1213log.info("inference_complete", extra={14    "event": "inference_complete",15    "request_id": "9f2c1a7e-...",16    "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736",17    "user_tier": "enterprise",18    "client": "mobile",19    "model": "assistant-v4",20    "model_version": "4.2.1",21    "latency_ms": 8143,22    "input_tokens": 1180,23    "output_tokens": 402,24    "cache_hit": False,25    "retry_count": 2,26    "finish_reason": "length",27})

Now the question is a query, not an archaeology project. Two properties matter more than the JSON itself.

One event per unit of work, with everything you might slice by

The rule of thumb: emit one rich, wide event per request rather than eight thin ones. Wide events are cheap to store and trivially sliceable; scattered narrow events force you to reconstruct state by joining log lines, which is exactly the work you were trying to avoid.

Every dimension you might one day want to group by has to be a field at write time. This is the constraint people underestimate. If locale is not on the event, then when the Spanish-language bug appears you cannot investigate it — you can only ship a change and wait a week for new data. You cannot add a dimension retroactively to logs already written.

Log levels mean something specific

The double-logging mistake in the ERROR row is worth calling out because it corrupts your metrics as well as your logs. If each layer catches, logs, and re-raises, one failed request produces four ERROR lines, and any alert built on "error log rate" is now off by a factor of four in a way that varies with which layer failed. Log the exception once, at the boundary where it is handled, and let it propagate silently elsewhere.

What a log line costs, and what to do about the prompt

At 500,000 requests a day with six lines per request at 800 bytes each:

500,000 x 6 = 3,000,000 lines/day3,000,000 x 800 B = 2.4 GB/day = 72 GB/month

At an ingest-and-index price around 2 dollars per GB, that is roughly 144 dollars a month — fine. Now turn DEBUG on globally, taking you to 60 lines per request:

500,000 x 60 x 800 B = 24 GB/day = 720 GB/month  ->  ~1,440/month

And now log the full prompt and completion, averaging about 6.2 KB of text per request:

500,000 x 6.2 KB = 3.1 GB/day = 93 GB/month  ->  ~186/month, plus a compliance problem

The compliance problem is the real one. Prompts contain whatever users typed, which routinely includes names, account numbers, medical details, and pasted credentials. Three defences, in order of how much they help:

• Do not log bodies by default. Log a SHA-256 of the prompt (so you can tell whether two requests were identical), its length, its token count, and its language — not its text.
• Redact before serialisation, not after. A redaction step that runs in the log pipeline has already written the raw text to the process's stdout and possibly to a crash dump. Scrub in the application, at the point of construction.
• Separate the sensitive stream. If you genuinely need bodies for debugging, send them to a separate store with a 72-hour retention and stricter access control, keyed by request_id so you can join back.

Treat every prompt as user-submitted personal data, because that is exactly what it is. The cheapest way to avoid leaking it through your observability stack is never to put it there.

Distributed tracing: where the eight seconds went

The customer's 8,143 ms request is one log line. It tells you the total and nothing about the composition. A trace decomposes it.

The data model is small enough to hold in your head:

• A span is one timed operation: a name, a start time, a duration, a status, a bag of key–value attributes, and optionally timestamped events inside it.
• Each span has a span ID and a parent span ID. Following parents upward gives you a tree.
• All spans in one logical request share a trace ID. That is the join key — put it on your log lines too, and a trace and its logs become one artefact.
• Context propagation is how the trace ID and current span ID cross a process boundary. Over HTTP the W3C standard carries them in a traceparent header that looks like 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01: version, trace ID, parent span ID, flags.

Rendered, the slow request looks like this:

POST /chat                                          8143 ms  |==============================|  embed_query                                          41 ms  |=|  vector_search  (k=5)                                187 ms  |=|  rerank                                               96 ms  |=|  llm_call  attempt=1  status=timeout                4000 ms  |=============|  llm_call  attempt=2  status=timeout                3600 ms  |===========|  llm_call  attempt=3  status=ok                      190 ms  |=|  format_response                                      29 ms  |=|

The answer is immediate and would have been essentially impossible to reach from logs alone: two provider timeouts, retried, then a fast success. The model was never slow. The retry policy turned a transient provider problem into an eight-second user-visible hang, and because the third attempt succeeded, the request was counted as a success everywhere — the error-rate panel stayed at 0.02% all night.

That is the characteristic value of tracing: it makes visible the cost of things that ultimately worked.

Instrumenting it

1from opentelemetry import trace2from opentelemetry.trace import Status, StatusCode34tracer = trace.get_tracer("assistant")56def answer(question: str, user):7    with tracer.start_as_current_span("chat.answer") as span:8        span.set_attribute("user.tier", user.tier)9        span.set_attribute("input.chars", len(question))1011        with tracer.start_as_current_span("retrieval.vector_search") as s:12            s.set_attribute("retrieval.k", 5)13            docs = store.search(question, k=5)14            s.set_attribute("retrieval.hits", len(docs))15            s.set_attribute("retrieval.top_score", docs[0].score if docs else 0.0)1617        for attempt in range(1, 4):18            with tracer.start_as_current_span("llm.call") as s:19                s.set_attribute("llm.attempt", attempt)20                s.set_attribute("gen_ai.request.model", "assistant-v4")21                try:22                    out = provider.complete(build_prompt(question, docs), timeout=4.0)23                    s.set_attribute("gen_ai.usage.input_tokens", out.input_tokens)24                    s.set_attribute("gen_ai.usage.output_tokens", out.output_tokens)25                    s.set_attribute("gen_ai.response.finish_reasons", [out.finish_reason])26                    break27                except TimeoutError as exc:28                    s.set_status(Status(StatusCode.ERROR, "provider timeout"))29                    s.record_exception(exc)30        else:31            span.set_status(Status(StatusCode.ERROR, "all attempts failed"))32            raise RuntimeError("llm unavailable")3334        span.set_attribute("llm.attempts_used", attempt)35        return out.text

Two details that separate useful traces from decorative ones. First, llm.attempts_used is set on the parent span, so you can filter whole traces by "requests that needed a retry" without inspecting children. Attributes that describe the request as a whole belong on the root; attributes that describe one operation belong on that operation. Second, span status is set explicitly on the failed attempts. A span with no error status is assumed successful, and a trace where the retries look like ordinary fast operations tells you nothing.

Sampling, and the trap in the obvious approach

Traces are the most expensive pillar. At 8 spans per trace and roughly 1.5 KB per span:

8 x 1.5 KB = 12 KB per trace500,000 traces/day x 12 KB = 6,000,000 KB = 6 GB/day = 180 GB/month

So people sample. The obvious approach is head sampling: at the start of a request, roll a die, and if it comes up 1-in-100, record the whole trace. Cheap, stateless, and it decides before it knows anything.

That last clause is the problem. With a 0.5% error rate you have 2,500 failing requests a day, and 1% head sampling keeps 25 of them. If those errors split across five distinct causes, you have roughly five examples of each per day. A bug affecting 20 requests a day gives you an expected 0.2 traces — you will see an example about once every five days, which is not a debugging loop.

Tail sampling buffers spans until the trace finishes, then decides using what actually happened. Keep everything interesting, sample the boring remainder:

errors      2,500 traces  (100%)      x 12 KB =  30.0 MBslow (>p99) 5,000 traces  (100%)      x 12 KB =  60.0 MBrest      492,500 traces  ( 1% = 4,925) x 12 KB =  59.1 MB                                        total  = 149.1 MB/day149.1 MB / 6,000 MB = 2.49% of the raw volume, 100% of the failures

2.5% of the storage cost, and every error and every slow request retained. The price is that a tail sampler must hold all spans of an in-flight trace in memory until it completes, which means a stateful collector and a decision window long enough to cover your slowest requests.

Performance metrics: cheap numbers that answer "since when"

Metrics are pre-aggregated, so a year of them costs less than an hour of raw logs, and their queries return in milliseconds. In exchange, they cannot tell you about any individual request. Three instrument types cover nearly everything.

The counter rule catches people. A counter's raw value is meaningless — it depends on how long the process has been up — and it drops to zero on every deploy. Always ask for a rate:

1-- error rate as a fraction, over 5-minute windows2sum(rate(llm_requests_total{status="error"}[5m]))3  / sum(rate(llm_requests_total[5m]))45-- p95 latency from a histogram, aggregated across all instances6histogram_quantile(0.95,7  sum by (le) (rate(llm_latency_seconds_bucket[5m])))89-- tokens per request, the metric that catches silent cost regressions10sum(rate(llm_tokens_total_sum{direction="in"}[5m]))11  / sum(rate(llm_tokens_total_count{direction="in"}[5m]))

Percentiles, and two ways they mislead you

Return to the opening numbers. Mean 495 ms, p50 100 ms, p99 8,000 ms. The mean is nearly five times the median, which is the signature of a right-skewed distribution — and latency is always right-skewed, because there is a floor at zero and no ceiling. This is why percentiles are the standard and averages are a mistake for latency specifically.

But percentiles have their own two failure modes, and both bite in production.

They cannot be averaged. If instance A reports p95 of 400 ms and instance B reports p95 of 600 ms, the fleet p95 is not 500 ms. It could be anything between them, and if A is serving 100x the traffic, it is essentially 400 ms. The only correct way to combine percentiles across instances is to sum the underlying bucket counts first and compute the quantile from the total — which is exactly what sum by (le) inside histogram_quantile is doing above. Any dashboard that averages a pre-computed p95 across pods is displaying a number with no defined meaning.

They are noisy at low volume. The empirical p99 in a window of $n$ requests is determined by the handful of observations in the top 1%. The count above the true 99th percentile follows a binomial distribution with mean $0.01n$ and standard deviation $\sqrt{n \cdot 0.01 \cdot 0.99}$.

n = 1,000     mean above p99 = 10     sd = sqrt(9.9)  = 3.15   -> relative sd 31%n = 100,000   mean above p99 = 1,000  sd = sqrt(990)  = 31.5   -> relative sd  3.1%

At 1,000 requests a window, a typical two-sigma swing puts the number of tail observations anywhere from about 4 to about 16 — the reported p99 will jump around dramatically with nothing changing underneath. Noise falls as $\sqrt{n}$, so getting ten times steadier requires a hundred times more data. The practical consequence: do not alert on p99 in one-minute windows on a low-traffic service. Either widen the window until you have tens of thousands of observations, or alert on p95, or alert on a count of requests exceeding a fixed threshold — which is a binomial quantity and far better behaved.

Bucket boundaries decide your accuracy

A Prometheus-style histogram does not store values; it stores counts per bucket. histogram_quantile then interpolates linearly inside whichever bucket contains the target rank, assuming values are spread evenly within it. So your worst-case quantile error is the width of the bucket the answer falls in.

With the Prometheus client's default boundaries (…, 1, 2.5, 5, 7.5, 10) seconds, a true p99 of 2.6 s lands in the (2.5, 5] bucket. That bucket is 2.5 s wide, so the reported figure can be off by up to 2.5 s — an error larger than the value you are trying to measure. Add boundaries where your traffic actually lives:

buckets = (0.1, 0.25, 0.5, 0.75, 1, 1.5, 2, 3, 4, 6, 8, 12, 20)

Now 2.6 s falls in (2, 3], a 1 s-wide bucket, and interpolation puts it near 2.6. The rule: bucket boundaries should be dense where your distribution is dense and where your thresholds are. If your SLO is "p95 under 2 seconds", you need a boundary at exactly 2, or you cannot measure compliance without interpolation error.

Cardinality is the metric killer

Every unique combination of label values is a separate stored time series. This multiplies:

llm_requests_total{model, endpoint, status}  4 models x 12 endpoints x 5 statuses            =        240 series   fineadd user_id (50,000 users)  240 x 50,000                                    = 12,000,000 series  at ~3.5 KB of memory per active series          =      42 GB RAM      deadadd prompt_hash                                   =   unbounded         dead faster

High-cardinality identifiers belong on log events and span attributes, where storage grows linearly with the number of events, not multiplicatively with the number of distinct values. A metric label must have a small, bounded set of possible values that you can name in advance.

Metrics scale with cardinality, logs scale with volume, traces scale with span count. Every observability cost disaster is one of those three growing without anyone deciding it should.

Choosing a pillar for the question in front of you

Named failure modes

What this means for the code you write

The three pillars work as a system, and the thing that makes them a system rather than three parallel silos is one field: the trace ID has to appear on every span, every log line, and — where cardinality allows via exemplars — attached to metric samples. Wire that once, at the request boundary, and the debugging path becomes mechanical: metric shows a spike at 14:05, click through to an exemplar trace, see which span is fat, pull the logs for that trace ID, read the attributes. Skip it, and every incident starts with fifteen minutes of trying to guess which log lines belong to the slow request.

1import logging2from opentelemetry import trace34class TraceContextFilter(logging.Filter):5    def filter(self, record):6        ctx = trace.get_current_span().get_span_context()7        record.trace_id = format(ctx.trace_id, "032x") if ctx.is_valid else None8        record.span_id = format(ctx.span_id, "016x") if ctx.is_valid else None9        return True1011logging.getLogger().addFilter(TraceContextFilter())

Beyond that, three decisions made at instrumentation time set the ceiling on everything you can learn later, and none of them can be fixed retroactively:

• Which dimensions you record. The bug will be in one locale, one client type, one model version, one customer tier. If the field is not on the event, the investigation does not happen.
• Where your histogram buckets sit. Choose them around your SLO thresholds and the shape of your real traffic, not the library defaults.
• What your sampler keeps. A sampler that discards errors is a sampler that removes the only data anyone will ever look for.

The team in the opening scenario had all three pillars installed. What they lacked was a percentile panel, a trace ID on their logs, and a sampler that kept slow requests. Three configuration decisions stood between "flat green all night" and "two provider timeouts, here is the retry policy that turned them into an eight-second hang".