Logs, Metrics and Traces Are Not Three Pillars. They're One Request.
Aurora Coffee Co. runs a checkout that calls a pricing service and an inventory service. I pointed a load generator at it — 1,000 orders, nothing exotic — and measured what the caller actually waited:
{
"requests": 1000,
"mean_ms": 23.9,
"p50_ms": 4.2,
"p95_ms": 8.7,
"p99_ms": 856.4,
"max_ms": 1758.7
}
The median order took 4.2 milliseconds. One of them took 1.76 seconds — four hundred times longer — and the mean, sitting at 23.9ms, reports neither. It is not the typical request and it is not the bad one. It is a number that describes nothing that happened.
Every service in that run logged happily throughout. Nothing errored, nothing retried, no alert fired. The only person who knew something was wrong was the customer staring at a spinner, and they did not file a ticket, they left.
This post is about the three kinds of telemetry that answer the question nobody in that run could answer — which orders were slow, and why — and about why "the three pillars of observability" is a bad way to think about them. They are not three systems standing side by side. They are three projections of the same events, and what makes them useful is not that you have all three — it is the ID that lets you jump between them.
Monitoring asks a question you already wrote down
The distinction that actually matters is not "logs vs metrics". It is this:
Monitoring answers questions you thought of in advance. Is the CPU above 80%? Is the error rate above 1%? Is the disk filling? Every one of those is a question somebody wrote down, turned into a check, and hung an alert on. That works, and you should have it.
Observability is the ability to answer questions you did not think of in advance — without shipping new code to find out. "Why were exactly twenty requests slow this afternoon, and what did they have in common?" is not a question anyone wrote a check for. If answering it requires adding a log line and redeploying, the system is not observable; it is debuggable, eventually, with permission.
That is the whole bar. Not "do we have a dashboard", but "when something weird happens, can we find out what, from data we already collected?"
The system under test
Three small Node 24 services, so every number in this post is reproducible rather than remembered. Checkout calls pricing, then inventory:
{
"name": "aurora-observability",
"private": true,
"type": "module",
"engines": { "node": ">=24" },
"dependencies": {
"@opentelemetry/api": "^1.9.1",
"@opentelemetry/auto-instrumentations-node": "^0.80.0",
"@opentelemetry/exporter-prometheus": "^0.222.0",
"@opentelemetry/exporter-trace-otlp-http": "^0.222.0",
"@opentelemetry/sdk-node": "^0.222.0",
"pino": "^10.3.1"
}
}
The backing stack is three open-source containers — no account, no API key, no free tier to age out:
# docker-compose.yml
services:
jaeger:
image: jaegertracing/jaeger:2.21.0
container_name: aurora-jaeger
ports:
- "16686:16686" # the trace UI you actually open
- "4318:4318" # OTLP over HTTP — where the services send spans
prometheus:
image: prom/prometheus:v3.15.0
container_name: aurora-prometheus
ports:
- "9090:9090"
volumes:
- ./prometheus.yml:/etc/prometheus/prometheus.yml:ro
extra_hosts:
# Prometheus pulls. The services run on the host, not inside this network.
- "host.docker.internal:host-gateway"
grafana:
image: grafana/grafana:13.2.2
container_name: aurora-grafana
ports:
- "3030:3000"
environment:
GF_AUTH_ANONYMOUS_ENABLED: "true"
GF_AUTH_ANONYMOUS_ORG_ROLE: Admin
depends_on:
- prometheus
- jaeger
# prometheus.yml
global:
scrape_interval: 5s
scrape_configs:
- job_name: aurora
static_configs:
- targets:
- host.docker.internal:9464 # checkout
- host.docker.internal:9465 # pricing
- host.docker.internal:9466 # inventory
docker compose up -d
One file does all the telemetry wiring, and it is loaded with --import so that it runs before any application code:
// telemetry.ts
import { register } from 'node:module';
// Auto-instrumentation rewrites modules as they are imported, and under ESM that
// needs a loader hook. Without this line the SDK still starts and still exports —
// it just never sees node:http, so nothing correlates. More on that below.
register('@opentelemetry/instrumentation/hook.mjs', import.meta.url);
import { NodeSDK } from '@opentelemetry/sdk-node';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { PrometheusExporter } from '@opentelemetry/exporter-prometheus';
const sdk = new NodeSDK({
serviceName: process.env.OTEL_SERVICE_NAME ?? 'unnamed-service',
// Traces are pushed to Jaeger over OTLP.
traceExporter: new OTLPTraceExporter({
url: `${process.env.OTEL_EXPORTER_OTLP_ENDPOINT ?? 'http://localhost:4318'}/v1/traces`,
}),
// Metrics are pulled: this opens /metrics for Prometheus to scrape.
metricReader: new PrometheusExporter({ port: Number(process.env.METRICS_PORT ?? 9464) }),
instrumentations: [getNodeAutoInstrumentations()],
});
sdk.start();
for (const signal of ['SIGINT', 'SIGTERM'] as const) {
process.once(signal, () => {
// Flush whatever is still batched, otherwise the last spans before a deploy —
// often the interesting ones — never leave the process.
void sdk.shutdown().finally(() => process.exit(0));
});
}
OTEL_SERVICE_NAME=pricing METRICS_PORT=9465 node --import ./telemetry.ts pricing.ts
OTEL_SERVICE_NAME=inventory METRICS_PORT=9466 node --import ./telemetry.ts inventory.ts
OTEL_SERVICE_NAME=checkout METRICS_PORT=9464 node --import ./telemetry.ts checkout.ts
Node 24 runs those TypeScript files directly, which is why there is no build step and no tsx anywhere. Note the explicit .ts in --import ./telemetry.ts: Node resolves the real file rather than rewriting the specifier for you.
The interesting part of pricing is that promotions are evaluated per SKU and cached, and the seasonal SKUs carry two hundred times more promotion rules than the house blends:
// pricing.ts (the part that matters)
const cache = new Map<string, number>();
function ruleCountFor(sku: string): number {
return sku.startsWith('seasonal-') ? 2400 : 12;
}
tracer.startActiveSpan('pricing.quote', (span) => {
span.setAttribute('aurora.sku', sku);
const cached = cache.get(sku);
if (cached !== undefined) {
span.setAttribute('aurora.cache_hit', true);
span.end();
respond(cached);
return;
}
span.setAttribute('aurora.cache_hit', false);
const priced = tracer.startActiveSpan('pricing.evaluate_rules', (inner) => {
inner.setAttribute('aurora.rule_count', ruleCountFor(sku));
const value = evaluateRules(sku);
inner.end();
return value;
});
cache.set(sku, priced);
log.warn({ sku, rule_count: ruleCountFor(sku) }, 'priced on a cold cache');
span.end();
respond(priced);
});
Nobody wrote a bug. There is a cache, it works, and 977 of the 1,000 requests hit it. That is the point: the interesting failures in production are usually not bugs, they are distributions.
Logs: what happened, in the words of one process
A log is an event with a timestamp, emitted by one process, describing something it did. It is the oldest signal and still the most detailed one — it is the only place where the reason lives.
The first upgrade has nothing to do with observability tooling, and it is free. Stop formatting sentences and start emitting objects:
// Before: the information exists, but only a human can extract it
console.log(`priced ${sku} on a cold cache with ${rules} rules`);
// After: the same event, queryable
log.warn({ sku, rule_count: rules }, 'priced on a cold cache');
{"level":40,"time":1790347139632,"service":"pricing","sku":"seasonal-19","rule_count":2400,"msg":"priced on a cold cache"}
The difference is not aesthetic. The first version can only be grepped, so "show me cold-cache pricings where the rule count was over a thousand, grouped by SKU" means writing a regex against prose that a teammate is free to reword at any time. The second is a filter over two fields. Pino writes that shape by default; Serilog does the same for .NET.
Now here is what logs cannot do, and it is the reason the other two signals exist. Those three services are producing lines like these, all at once, under load:
{"time":1790347137929,"service":"checkout","sku":"house-blend-1kg","ms":3,"msg":"checkout complete"}
{"time":1790347137934,"service":"checkout","sku":"decaf-250g","ms":4,"msg":"checkout complete"}
{"time":1790347137938,"service":"checkout","sku":"espresso-500g","ms":3,"msg":"checkout complete"}
{"time":1790347139632,"service":"pricing","sku":"seasonal-19","rule_count":2400,"msg":"priced on a cold cache"}
{"time":1790347139695,"service":"checkout","sku":"seasonal-19","ms":1755,"msg":"checkout complete"}
Every line is true. Every line is structured. And there is no reliable way to say that the pricing line and the checkout line below it belong to the same order. They look related because the SKU matches and the timestamps are 63ms apart — but that is a guess, and with real concurrency it is a wrong one. Ten customers ordering the same seasonal blend in the same second produce ten indistinguishable pairs. Logs describe events one process at a time; a request that crosses three processes has no owner in that model.
That is the gap. Not detail — logs have plenty. Identity.
Traces: one request, across every process it touched
A trace is one request's journey. It is made of spans, and a span is a named, timed operation with a parent. The tree that comes out of that is what a trace is: not a list of timestamps, but a causal structure — this call happened because of that one, and inside its lifetime.
Two things make it work across a network boundary. Every span carries the trace's ID, and the HTTP client injects that ID into an outgoing traceparent header, which the next service reads back out. That is the entire mechanism of distributed tracing, and it is why the id is the thing worth caring about.
Here is the slowest request from the 1,000-order run, exactly as its spans came back, rendered as a tree:
trace 4eef76aeccdbd0f961d78dc7e4241092 (8 spans)
GET 1756.1 ms [checkout]
checkout 1755.6 ms [checkout]
GET 1752.2 ms [checkout] -> localhost:3001/price
GET 1692.3 ms [pricing]
pricing.quote 1691.4 ms [pricing]
pricing.evaluate_rules 1690.7 ms [pricing]
GET 1.6 ms [checkout] -> localhost:3002/reserve
GET 0.4 ms [inventory]
Read the numbers down the left. Of 1,756 milliseconds, 1,690.7 were spent inside pricing.evaluate_rules — 96% of the request in a single span, four levels down, in a different process from the one the customer was talking to. Inventory, which is the service everyone suspects first because it touches a database, answered in four tenths of a millisecond.
Nothing in that tree is inferred. Each nested span is inside its parent because the parent's ID was on it, not because the timestamps happen to overlap.
And now the join that the logs could not make on their own, because the SDK stamps the active trace ID onto every line written inside a span:
{"level":40,"time":1790347139632,"service":"pricing","trace_id":"4eef76aeccdbd0f961d78dc7e4241092","sku":"seasonal-19","rule_count":2400,"msg":"priced on a cold cache"}
{"level":30,"time":1790347139695,"service":"checkout","trace_id":"4eef76aeccdbd0f961d78dc7e4241092","sku":"seasonal-19","ms":1755,"msg":"checkout complete"}
Same two lines as before. One extra field, and "these look related" becomes "these are the same request". Paste the trace ID into your log search and you get every line any service wrote about that one order; paste it into Jaeger and you get the tree above. That is the bridge, and it is the reason to care about tracing even if you never open a waterfall UI.
You do not write that field. @opentelemetry/instrumentation-pino, which getNodeAutoInstrumentations() turns on for you, adds trace_id and span_id to every Pino line emitted inside an active span. The logger stays three lines long:
// logger.ts
import pino from 'pino';
export const log = pino({
level: process.env.LOG_LEVEL ?? 'info',
base: { service: process.env.OTEL_SERVICE_NAME ?? 'unnamed-service' },
});
Metrics: how often, and how bad
A trace describes one request. That is its strength and its entire limitation: you cannot look at 1,000 traces and form an opinion, and in production you will not even have them all.
A metric is a number aggregated over time and grouped by a small set of labels. Checkout records one:
const duration = meter.createHistogram('checkout.duration', {
description: 'End-to-end checkout latency',
unit: 'ms',
});
duration.record(elapsed, {
route: '/checkout',
outcome: reservation.reserved ? 'ok' : 'rejected',
});
A histogram does not store your measurements. It stores counts per bucket, which is what makes it cheap enough to keep forever. Here is the real scrape after the run:
checkout_duration_count{route="/checkout",outcome="ok"} 1001
checkout_duration_sum{route="/checkout",outcome="ok"} 22441.0005
checkout_duration_bucket{route="/checkout",outcome="ok",le="5"} 910
checkout_duration_bucket{route="/checkout",outcome="ok",le="10"} 972
checkout_duration_bucket{route="/checkout",outcome="ok",le="25"} 976
checkout_duration_bucket{route="/checkout",outcome="ok",le="100"} 979
checkout_duration_bucket{route="/checkout",outcome="ok",le="500"} 981
checkout_duration_bucket{route="/checkout",outcome="ok",le="750"} 988
checkout_duration_bucket{route="/checkout",outcome="ok",le="1000"} 995
checkout_duration_bucket{route="/checkout",outcome="ok",le="2500"} 1001
Buckets are cumulative, so read them as a staircase. 910 of 1,001 requests finished in 5ms or less. 981 finished within half a second — which means 20 requests, 2% of the traffic, took longer than that, and 6 of them took more than a second. (The count is 1,001 rather than 1,000 because checkout also measured the warm-up request; this is the server's own view of its latency, not the load generator's.)
That single fact is what no trace can give you. A trace proves one request was slow; the histogram says how much of your traffic lives out there, which is the difference between "a customer complained" and "one order in fifty is unusable".
It also shows why sum / count — 22,441 / 1,001, or 22.4ms — is the least useful number on the page. It is the average of 910 requests at 5ms and 20 requests at a second, and it describes neither group. Alert on the mean and you will find out about an outage roughly when your customers stop having the problem.
The trade-off runs the other way too. Ask the histogram which requests were slow and it has nothing: there is no SKU in it, no order ID, no customer. That is deliberate, and the next section is about what happens when you try to fix it.
Putting the three together: the 2% that matters
This is the loop, and the order is not decorative.
Metrics tell you there is a problem, and how big it is. 2% of checkouts over 500ms. That number came from data collected before anyone was looking, and it is cheap enough to keep for a year, so you can also see that it started on Tuesday.
Traces tell you where the time went. Pull a slow one and 96% of it is inside pricing.evaluate_rules. You now know the service, the function, and that the network and inventory are innocent — without reading any code.
Logs tell you why. The log line stamped with that same trace ID says rule_count: 2400 and priced on a cold cache. That is the cause, in the application's own vocabulary: this SKU has 2,400 promotion rules and its cache entry was not there.
Metrics without traces gives you a number you cannot act on. Traces without metrics gives you an anecdote. Either without logs gives you a location with no explanation. And all three without a shared ID gives you three dashboards and a meeting.
The span attributes close it out. pricing.quote carries aurora.cache_hit, so "is this only ever happening on cold caches?" is a filter over spans, not a hypothesis. Across the whole run, warm-up included: 24 cold misses against 977 hits, and every single slow request was a miss.
Three gotchas that cost me an afternoon each
1. Under ESM, the SDK starts fine and correlates nothing
Delete the register(...) line from telemetry.ts and everything still boots. No error, no warning, spans still arrive at Jaeger. Same load, same code, this is what comes out:
with the loader hook without it
-----------------------------------------------------------
checkout 1 trace id checkout its own trace id
pricing same trace id pricing a different trace id
inventory same trace id inventory no spans at all
8 spans in one tree two unrelated fragments
trace_id on every log line no trace_id on any log line
Auto-instrumentation works by rewriting modules as they load. Under CommonJS it hooks require; under ESM it needs a loader hook registered before the first import of anything instrumented. Without it, node:http is never patched, so the server side never reads the incoming traceparent header, every service starts its own trace, and the Pino instrumentation never attaches either — which is exactly the "three disconnected log streams" state from the top of this article, except now you are also paying to store spans.
The manual spans keep working, which is what makes this so quiet. You will only notice by looking at two services and finding two different trace IDs for one request.
2. A field is free on a span and expensive on a metric
aurora.sku as a span attribute costs nothing: a span is one event, it carries its own fields, and the two dozen SKUs in the run were two dozen values sitting on their own spans.
Put the same field on the histogram and it stops being a field. Every distinct combination of labels is a separate time series, and a histogram exposes eighteen lines per series. Measured on the real exporter:
labels series expected actually exposed
--------------------------------------------------------------------------------
route + outcome 6 6 (108 lines)
route + outcome + customer_id (1,000 ids) 6,000 2,000 (36,000 lines)
The scrape went from a couple of kilobytes to 4.4MB. But look at the right-hand column, because the real damage is the part nobody expects: the SDK caps a metric at 2,000 attribute sets and silently folds everything past that into a single series.
checkout_duration_risky_count{otel_metric_overflow="true"} 4001
4,001 of 6,000 recordings landed there. The metric did not get expensive — it got wrong, and the only sign is a label most people have never seen.
The rule that keeps you out of trouble: a metric label must have a small, bounded set of values you could write down today. Route, status, region, outcome. Never a user ID, an order ID, a SKU from an open-ended catalogue, or a URL with an ID in it. High-cardinality context belongs on spans and log lines, which is exactly what they are good at.
3. Traces are the expensive signal, and sampling is not optional
Those 1,000 requests produced seven spans on a cache hit and eight on a miss — 7,032 in total — and shipping them cost:
/v1/traces 19 posts 6,252,907 bytes
/v1/logs 28 posts 166,783 bytes
/v1/metrics 0 posts 0 bytes (Prometheus pulls; nothing is pushed)
Six and a quarter megabytes of span data for a thousand checkouts. That is 889 bytes per span, about 6.2KB per request, and thirty-seven times the log volume for the same traffic. Multiply by production traffic and tracing every request is a budget line, not a default.
The answer is sampling, and the version worth knowing now is: sample whole traces, never individual spans, or you get trees with holes in them. The SDK defaults to keeping everything, and two environment variables change that without touching code:
OTEL_TRACES_SAMPLER=parentbased_traceidratio
OTEL_TRACES_SAMPLER_ARG=0.1
Starting 2,000 spans with the default kept 2,000; with those two variables set it kept 201. The parentbased_ prefix is the load-bearing part: the decision is made once at the front door, travels in traceparent, and every downstream service honours it, so you get 10% of traces whole rather than 10% of spans scattered across all of them.
Metrics stay at 100%, which is the other half of why you want them: your p99 remains exact even when 90% of traces are gone.
When you need all three, and when you don't
Start with structured logs and one latency histogram per entry point. A single service with one database gets most of the value there. A trace of a request that never leaves the process is a flame graph with extra steps, and a profiler does that better.
Add tracing the moment a request crosses a process boundary. Two services and a queue is enough. That is the point where "which one is slow" stops being answerable from logs, and no amount of log discipline fixes it — the missing thing is the ID, not the detail.
Add metrics before you think you need them, because they are the only signal that is cheap to keep at full fidelity for a year. You cannot go back and ask what the p99 was last quarter if nobody was counting.
Leave it alone when the system is a cron job, a CLI, or anything where the run is the unit of work and stdout already tells the whole story. Also leave it alone when nobody is on call: telemetry nobody reads is a cost centre with a dashboard. Instrumenting is the easy half; the hard half is having someone whose job it is to look.
Rule of thumb: you need a trace when the answer to "where did the time go?" lives in a different process than the one holding the request.
Key Takeaways
- Monitoring answers questions you wrote down in advance; observability answers the ones you didn't. If finding out means adding a log line and redeploying, you have logging, not observability.
-
The three signals are one request seen three ways. Metrics say how often and how bad, traces say where, logs say why. The trace ID is what makes them one system instead of three tabs — and under ESM it takes exactly one
register(...)line to lose it silently. - The mean is the least informative number you will compute. A run with a 4.2ms median and an 856ms p99 averages out to 23.9ms, which describes no request that actually happened.
-
Cardinality is free on spans and ruinous on metrics. The OpenTelemetry SDK caps a metric at 2,000 attribute sets and quietly folds the overflow into
otel_metric_overflow, so acustomer_idlabel doesn't just cost money — it makes the metric wrong. - Traces are the expensive signal. 6.2KB per request here, thirty-seven times the logs. Sample whole traces, keep metrics at 100%, and your percentiles stay exact while your bill doesn't.
Coming next in this thread: structured logging in practice — what Pino and Serilog actually cost under load, and why "just log everything as JSON" runs out of road faster than you would like.
Top comments (0)