From a Latency Alert to a Root Cause — Traces, Logs, and Metrics in Practice

Part 17’s sizing experiment quietly assumed you can see what the process is actually doing. So this article is about getting hold of that evidence, and about the discipline of not overstating what each piece of it proves.

The investigation below is a labelled fiction built out of the document application. The diagrams are explanatory, and nothing here is a timing export from a running system.

Table of Contents

• The Chart That Cannot Answer the Question
• Which Component Produces Which Signal
• Following One Request Through a Trace
• Correlation IDs Are Not Trace IDs
• Logs That Can Be Joined to a Trace
• Turning Up the Detail Temporarily
• Aggregates Without Unbounded Cardinality
• Memory and Garbage Collection Signals
• CPU Profiles and What They Can Attribute
• The Investigation Resolved
• Further Reading
• What’s Next

The Chart That Cannot Answer the Question

The alert says tail latency on document pages has roughly doubled since this morning. The chart it came from shows one line going up.

That line is consistent with at least four entirely different incidents. The .NET API got slower. The content service got slower. The shared cache is missing more often, so renders that used to be cheap now run the full cascade from Part 9. Or the workers are CPU-saturated and requests are queuing for the event loop, which is Part 17’s failure mode. Each of those has a different fix, and three of the four fixes make one of the others worse.

No amount of averaging that line will produce the answer, because the information was never in it to begin with. What you need is a signal that decomposes one request into its parts, plus enough surrounding evidence to tell whether that request was representative in the first place.

Which Component Produces Which Signal

The most common source of confusion in this whole area is assuming that switching a telemetry feature on means data appears. Producing a signal and collecting it are two separate steps with separate owners.

Three qualifications are needed to keep that diagram honest.

A managed agent routes telemetry that is sent to it. Turning it on doesn’t instrument containers which produce nothing, so a stock cache image doesn’t magically acquire application tracing by sharing an environment with an instrumented Nuxt server. Instrumentation is the application’s job. The agent is transport.

Destinations differ by signal type. A managed agent may happily accept logs and traces for one backend while metrics need a separately chosen path. That asymmetry is worth writing into your infrastructure diagram and your troubleshooting runbook, because discovering it in the middle of an incident is expensive.

And the diagram shows the available paths rather than a recommendation to export everything twice. Duplicate instrumentation double-counts requests and doubles your ingestion cost, which distorts precisely the numbers you’re later going to reason from.

Following One Request Through a Trace

A trace decomposes the request, and two terms carry the whole idea. A span is one timed unit of work with a name, a start, a duration and some attributes: “handle this HTTP request”, “call the content service”. A trace is the tree of spans belonging to one request, linked together by parent-child relationships.

Linking those across process boundaries is the part that needs cooperation. The proxy creates the root span and then sends a traceparent header upstream, which is the W3C Trace Context standard, and its value carries the trace id and the id of the sending span. The Nuxt server reads that header, makes its own span a child of it, and passes the header along when it calls the API. Every participant appends to the same trace instead of starting one of its own, and that’s what makes the whole request visible in a single view:

Two properties of this architecture affect what you’re going to see. In-process gateway execution is not an HTTP hop, so automatic HTTP instrumentation records precisely nothing for it. If you want to know how long composition took, or which subgraph a slow field came from, then resolver-level spans have to be added deliberately. And conversely, where an HTTP client is already instrumented, wrapping manual spans around it produces duplicates that make a dependency look twice as busy as it really is.

Also, trace coverage is a function of sampling. A backend can’t show you every request unless the collection and retention policy actually keeps them all, which at any real volume it usually doesn’t. That’s fine for diagnosing a systematic regression and thoroughly unhelpful for chasing one user’s complaint. Worth knowing which kind of question you’re asking before you promise anybody an answer.

Correlation IDs Are Not Trace IDs

Most applications also carry a request identifier of their own, for support tickets and log searches. It’s genuinely useful, and it is not the trace ID.

That distinction matters because of one specific bug: if a helper generates a fresh trace identifier instead of adopting the incoming context, then your application’s spans form a completely separate trace from the proxy’s. Everything looks beautifully instrumented, and no single trace contains the whole request. So take trace correlation from the active span context, and keep the application’s own identifier as a log field or a span attribute.

Treat an externally supplied identifier as untrusted input, per Part 15: validate its format, bound its length, and never let a correlation header act as authentication.

And before anybody writes “end-to-end tracing” into a status document, go and verify it on a real request. The proxy span, the Nuxt request span, each dependency span and the API’s server span should all be in one trace, with the parent relationships you expect. That check takes about five minutes and it fails rather more often than people assume.

Logs That Can Be Joined to a Trace

A trace tells you where the time went. Logs tell you what the code decided. And they’re only usable together if they share a key, so your log events should carry the current trace and span identifiers.

const log = useLogger('document-browser')

log.debug('Revisions loaded', { count: revisions.length })
log.info('Selection changed', { documentId })
log.warn('Cached result set was stale', { documentId })
log.error('Document load failed', { code: 'UPSTREAM_UNAVAILABLE' })

A module-scoped logger, using the module identity from Part 6, gives every event an owner, and that’s what makes filtering meaningful. Beyond that, two rules keep logs both affordable and safe. Use stable event names and a small documented set of fields, because searchability comes from consistency rather than from sheer volume. And keep request bodies, credentials, cookies, personal data and unfiltered error messages out of them entirely. Prefer route templates like /documents/:id to full URLs, which is both safer and cheaper to aggregate.

The same logger can write to a readable console in development, to structured sinks in production, and to a development-only inspection panel. That panel is worth one caution: a browser-visible view must not carry server-only data. Server and client logging share an API, not a data set and not a permission model.

Turning Up the Detail Temporarily

Running at debug level permanently is unaffordable and mostly noise anyway, so the genuinely useful capability is raising the level for one module, briefly, in production.

The control endpoint is an operator capability, so it needs authentication, authorization, an audit trail and an expiry. An override that never resets itself is a log bill and a data-protection question that nobody remembers creating.

And here’s a scoping detail that wastes an enormous amount of incident time: with several workers per container and several replicas, an override applied through one HTTP request reaches one process. Unless you distribute it deliberately, “debug is on” really means “debug is on in one worker, which may well not be the one serving the request you care about”.

Aggregates Without Unbounded Cardinality

Traces are sampled and logs are per event, so the steady-state questions, meaning how many requests, how slow and what status, belong to aggregated metrics.

Counters and running aggregates keep your storage independent of request count, because a million requests still only increment a number. Percentiles need a bit more than that: a histogram, which counts how many requests fell into each duration bucket. From those counts a backend can estimate the value below which 95% of requests completed, the p95, and that’s the statistic describing the experience of your slowest visitors rather than your typical one. An average and a maximum can’t produce it, because the average hides the tail by construction and the maximum is a single outlier.

The claim to be careful about here is “constant memory”. It’s constant per bucket. Label with a full URL, a document id or a user id and your bucket count grows without limit, which is the classic cardinality incident: the metrics system falls over, rather than the application. Bounded label sets are a design decision, not a detail. And instrumentation costs CPU on every request, so constant storage is not the same as constant overhead.

One architecture-specific note: with the in-process gateway, SSR doesn’t issue an HTTP request to itself, so page views don’t get double-counted. If a deployment ever uses a loopback path instead, label the internal calls separately or the same page render turns up twice in your traffic figures.

Memory and Garbage Collection Signals

Node.js exposes GC activity and heap-space statistics, and that’s exactly what Part 17’s experiment consumes.

Interpretation needs comparable windows: a rising slope during cache warm-up is entirely normal, and the same slope sustained across two similar traffic periods is not.

Heap snapshots need handling rules, because they’re the most invasive tool in this article. Taking one can pause a worker and temporarily increase its memory substantially, so triggering one automatically when memory is already near the limit is a fine way to convert a warning into the very outage it was warning you about. A snapshot also contains whatever happened to be in memory, credentials and request bodies included, no matter how carefully your logger redacts. So treat captures as sensitive artefacts with restricted access, bounded retention and no casual sharing. And rate-limit any automatic capture, or one threshold flap leaves you with a pile of multi-gigabyte files.

CPU Profiles and What They Can Attribute

A CPU profile tells rendering work apart from response parsing apart from serialization, which is exactly what you want when the trace shows time being spent inside the Nuxt span rather than in a dependency. It says nothing whatsoever about time spent waiting, because waiting isn’t CPU.

Two attribution limits decide how strongly you’re entitled to phrase a conclusion. A profile started after a request became slow can’t possibly contain the work that happened before the trigger fired. And a Node.js worker handles concurrent requests, so the captured profile includes all of them. A profile is process-level evidence for a time window, and attributing it to one request means correlating with traces and load rather than simply asserting it.

The same caution applies to capacity arithmetic. There is a useful estimate available here: arrival rate multiplied by average duration approximates the number of requests in flight at any given moment, so fifty requests per second at an average duration of a fifth of a second implies roughly ten concurrent renders, which is the number Part 17’s memory model actually cares about. Treat it as an order of magnitude, because it assumes a steady arrival rate, and a burst or a slow dependency invalidates the average it rests on. The second figure in that calculation is less trustworthy still. Per-request memory is not the observed heap delta divided by the request count, because caches filling up, GC timing and overlapping request lifetimes are all sitting inside that delta. Which is why Part 19’s load test exists instead of a spreadsheet.

The Investigation Resolved

So, back to our doubled tail latency. The path through the signals above goes like this:

1. Which route class and which release? Metrics with bounded route labels, split by release, which either implicates this morning’s deployment or lets it off the hook.
2. Waiting or executing? One trace of a slow request. If the time sits in a dependency span then the application is waiting. If it sits inside the Nuxt span with no child covering it, the application is working.
3. What changed in the process? Platform metrics and Part 17’s signals: replica count, restarts, memory, event-loop delay. A capacity problem looks quite different from a dependency problem.
4. What did the code decide? Redacted logs joined by trace id, showing retries, timeouts and cache outcomes. This is where “the cache is missing more often” becomes visible as a cause rather than a guess.
5. Is a profile or a snapshot justified? Only if the previous four left the question open, and only with the handling rules above.

In our fictional case, the trace puts the added time in content-service dependency spans, the logs show cache misses where there used to be hits, and the platform metrics are entirely unremarkable. Which points at an invalidation that cleared rather more than intended, not at a slow dependency and not at capacity. The fix lives in the cache identity, and no amount of scaling anything would have found it.

There’s one evidence-handling habit worth keeping from this: don’t discard client-aborted requests wholesale. Sometimes they’re ordinary navigation and sometimes they’re the signature of responses so slow that users give up and leave, and those two look absolutely identical unless you kept enough to tell them apart.

And the rule is this: every signal answers one question. Traces say where, logs say what was decided, metrics say how often and how bad, profiles say what the CPU did, and platform metrics say what the process was given. An observability stack is finished when each one of those questions has a signal that answers it, not when it’s ingesting an impressive quantity of data.

Further Reading

• Managed OpenTelemetry agents in Azure Container Apps

What’s Next

• Part 19: Load Testing an SSR Migration — Producing comparable numbers, and reporting only what they support.
• Part 20: The Full Picture — Whether the whole arrangement was worth owning.

Munir Husseini is a software architect specializing in full-stack TypeScript, .NET, and cloud-native architectures.