In March the monthly cost of logs, traces and metrics for our main API went past the cost of the machines it runs on. That's an odd milestone: the thing that tells you whether the service is healthy cost more than the service.
Finance's first reaction was to cut, and engineering's was to defend, and both were wrong in the way both sides of a budget fight usually are. Cutting telemetry blindly makes the next incident longer. Defending it as it was means paying for gigabytes nobody will ever query. We did neither. We changed the shape of what we emit, and the new shape is what cut the bill.
Where the money was going
Roughly, the bill was 60 percent logs, 30 percent traces and 10 percent metrics. Half the logs came from a single service, and most of that service's volume came from three log statements. One was a "request received" line with the method and path. One was a "request completed" line with the status and duration. The third sat inside a loop that processed the items in a batch, one line per item.
Every request produced at least two log lines that said almost nothing, plus a trace with eight spans that said everything those two lines said and more. The batch loop added 200 lines per request, each saying "processed item N". Nobody had ever queried them, because when a batch goes wrong you want the batch, not the items.
Traces were sampled at 10 percent, head-based, which means a coin flip at the start of the request decided whether to keep it. So 90 percent of errors had no trace, because errors are rare and the coin doesn't know a request is going to fail when it's flipped. Engineers leaned on logs for errors instead, which is why the logs had so much in them.
I think most teams with more than about ten engineers look like this: logs that duplicate traces, traces that miss the requests you care about, and everything kept for the same 30 days whether anyone will read it or not.
One wide event per request
The change that did the most is the one that sounds least like a cost cut. Instead of emitting several narrow log lines during a request, the service collects fields into one structure and emits it once at the end. It's one wide event with everything in it: the route, the user, the tenant, the status, the duration, the database query count and time, the cache hit rate, which feature flags were on, the version, the errors, and any business fields the handler wanted to add.
// One per request. Handlers add fields; middleware emits at the end.
app.use(async (ctx, next) => {
const ev: Record<string, unknown> = {
route: ctx.route, method: ctx.method, tenant: ctx.tenant.id,
user: ctx.user?.id, version: VERSION, flags: activeFlags(ctx),
};
ctx.event = ev;
const t0 = performance.now();
try {
await next();
ev.status = ctx.status;
} catch (err) {
ev.status = 500; ev.error = describe(err); throw err;
} finally {
ev.duration_ms = performance.now() - t0;
ev.db = ctx.db.stats(); // { queries: 4, ms: 12.3 }
emit(ev);
}
});
// In a handler:
ctx.event.batch_size = items.length;
ctx.event.items_failed = failures.length;
The batch loop's 200 lines turned into two fields on the request's event: how many items, and how many failed. When you need item level detail it's in the trace, and every failing request now keeps its trace, which is the next change.
The effect on volume is large. Two hundred and two narrow lines became one wide line, and for that service the bytes dropped by about 85 percent.1
The effect on debugging surprised me more. A question like "which tenants had slow requests with more than ten database queries on version 4.2 with the new pricing flag on" is one query with a where clause against wide events. Against narrow logs it's a join across lines by request id, which most log backends can't do at all, so engineers gave up and guessed. The narrow lines had made everyone stop asking those questions, and the wide event made them answerable again.
Sample at the tail, keep every error
The second change was sampling. Head-based sampling at 10 percent keeps 10 percent of everything, meaning 10 percent of the boring successes and 10 percent of the interesting failures. Tail-based sampling decides at the end of the request, once you know how it went.
This is the rule we settled on. Keep 100 percent of requests with an error or a status of 500 or above. Keep 100 percent of requests slower than the route's p99. Keep 100 percent of requests from a short list of tenants we're watching, usually because they reported something. Keep 2 percent of everything else, chosen by a hash of the trace id so a whole trace is either kept or dropped and you never end up with half a tree.
Implemented in the OpenTelemetry collector's tail sampling processor, that rule cut trace volume by about 70 percent and took the share of errors with a trace from about 10 percent to 100 percent.2
processors:
tail_sampling:
decision_wait: 10s
policies:
- name: errors
type: status_code
status_code: { status_codes: [ERROR] }
- name: slow
type: latency
latency: { threshold_ms: 800 }
- name: watched-tenants
type: string_attribute
string_attribute: { key: tenant.id, values: ["t_4f1", "t_9a0"] }
- name: baseline
type: probabilistic
probabilistic: { sampling_percentage: 2 }
The collector needs enough memory to hold ten seconds of in-flight traces while it waits for them to finish, which for this service came to about 1.5 GB per collector. That's a real cost, and a small fraction of what it replaced.
Retention by usefulness
The third change was accepting that not everything is worth keeping for 30 days. Wide events for successful requests get queried in the first week if they get queried at all. We checked the backend's query logs, and 96 percent of queries touched data less than seven days old. Errors and slow requests get queried for longer, because incidents and post-mortems look at them.
So there are two tiers. The baseline sample and the successful wide events go to a seven day tier. Errors, slow requests and watched tenants go to a 90 day tier, which is longer than we kept anything before. That tier is small, because errors are rare, and it holds exactly the data a post-mortem three weeks later needs.
We didn't touch metrics. They're 10 percent of the bill and the cheapest way to find out something's wrong, and cutting them would be like saving money on the smoke detector.
The result
The bill dropped by about two thirds, from a bit more than the compute bill to a bit under a third of it. The service emits far fewer bytes, all of them queryable, and every request that failed or was slow has a full trace for 90 days.
Time to diagnosis in incidents got shorter, and I don't think that was luck or a happy side effect. The old telemetry was expensive because it was unstructured, and it was hard to debug with for the same reason, so fixing the structure fixed both. Cost and observability only trade off against each other when the telemetry is badly designed, and most telemetry is badly designed because it grew out of console.log calls added one at a time over years.
How we moved without going blind
The risk with a change like this is the fortnight where the old telemetry is gone and nobody trusts the new telemetry yet. An incident during that fortnight is worse than one before or after it. So we staged the migration to never have that fortnight.
For two weeks each service emitted both the old narrow lines and the new wide event.3 In return, every dashboard and alert was rebuilt against the wide events while the old ones still worked, and each rebuilt panel was checked against the old one over the same time range. Where they disagreed, the wide event was usually right, because the head-based rule had sampled the narrow lines and nothing had sampled the wide events.
The alerts needed the most care. An alert on "error rate above 1 percent" had been computed from the status field of the "request completed" line. It became a query over wide events with the same threshold, and for a week both alerts were live, and we looked into every case where one fired without the other. There were two. One was a route the old line had never logged because of a middleware ordering bug, which the wide event caught because it's emitted in a finally. The other was a timezone bug in the new query. Both were worth finding before the old alert was switched off.
Then the old lines came out, service by service, starting with the one that produced the most volume, because that's where the bill was and where a problem would show up fastest.
Libraries that log were the one thing this didn't cover. The database client logs slow queries, the HTTP client logs retries, the framework logs its own startup. Those stayed as narrow lines at warning level or above, and they're a small slice of the volume. Application code emits wide events, libraries emit whatever they emit, and nobody spends a week trying to bend a third party logger into shape.
What we got wrong
Three things, all fixable, and I'd tell anyone to avoid all three.
At first the tail sampler's decision_wait was 5 seconds, the number in most examples. Requests that took longer than 5 seconds, exactly the ones you want traces for, got decided before they finished. The decision was "this is not slow yet", so they were dropped at the 2 percent baseline rate. Nobody noticed for a week, because the slow requests that did get kept looked normal. It went to 10 seconds, and then to 30 for the service with the batch endpoints. The cost is memory on the collector, and memory is cheap next to the trace you needed and didn't have.
The first version of the wide event had no tenant id, because the middleware that emitted the event ran before the middleware that resolved the tenant. That gave us a full week of events we couldn't filter by tenant, the most common filter in any incident. Middleware order is a boring bug, and it cost more than any clever one.
And field cardinality. A wide event with a hundred fields is fine. A wide event where one field is a free text error message with a unique request id in it has a hundred thousand distinct values a day, and indexing that one field cost the backend more than removing the narrow lines saved. The error message is a stable code now, and the free text goes on the trace span, which isn't indexed. In the first week, look at the distinct value count for every field. Anything that grows with traffic probably belongs on a span attribute.
If your bill has crossed the line
Find the three log statements that produce most of the volume. There will be three, and they'll be per-request lines that duplicate the trace, or per-item lines inside a loop.
Replace per-request logging with one wide event per request, and put the loop's information in fields on that event.
Switch trace sampling from head to tail, keep every error and every slow request, and sample the rest at a low rate by trace id.
Split retention by whether anyone will read it, and check the query logs to find out. The answer is almost always "a week for successes, longer for failures".
Leave metrics alone.
For us that was about three weeks of work for one engineer, spread across two months, and it paid for itself in the first month.
Originally published at zeybek.dev.
-
Most of a narrow log line is the timestamp, level, service name and request id, repeated on every line, and the wide event carries each of those once. ↩
-
The on-call engineers noticed the second part before anyone noticed the first. ↩
-
The bill went up for those two weeks, which finance didn't love and which I'd warned them about. ↩
Top comments (0)