In March the monthly cost of logs, traces and metrics for our main API passed the cost of the machines it runs on. That is a strange milestone. The thing that tells you whether the service is healthy costs more than the service.

The first reaction from finance was to cut, and the first reaction from engineering was to defend, and both were wrong in the way that both sides of a budget fight usually are. Cutting telemetry blindly makes the next incident longer. Defending it as-is means paying for gigabytes that nobody will ever query. What we ended up doing was neither. We changed the shape of what we emit, and the shape change is what cut the bill.

Where the money was going#

The bill broke down roughly as: 60 percent logs, 30 percent traces, 10 percent metrics. Within logs, a single service accounted for half, and within that service, three log statements accounted for most of its volume. One was a "request received" line with the method and path. One was a "request completed" line with the status and duration. One was inside a loop that processed items in a batch, one line per item.

Every request produced at least two log lines that said almost nothing, plus one trace with eight spans that said everything the two lines said and more. The batch loop produced 200 lines per request that each said "processed item N", which nobody had ever queried, because when something goes wrong with a batch you want the batch, not the items.

Traces were sampled at 10 percent, head-based, meaning the decision was made at the start of the request by a coin flip. That meant 90 percent of errors had no trace, because errors are rare and the coin does not know a request is going to fail when it flips. So engineers relied on logs for errors, which is why the logs had so much in them.

This is a common shape and I think most teams over about ten engineers have it. Logs that duplicate traces, traces that miss the requests you care about, and everything retained for the same 30 days regardless of whether it will ever be read.

One wide event per request#

The change that did the most is the one that sounds least like a cost cut. For each request, instead of emitting several narrow log lines during the request, the service accumulates fields into one structure and emits it once at the end. One event, wide, with everything: the route, the user, the tenant, the status, the duration, the database query count and time, the cache hit rate, the feature flags that 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 became two fields on the request's event: how many items and how many failed. When you need the item level detail, it is in the trace, and the trace is now kept for every failing request, which is the next change.

The volume effect is large. Two hundred and two narrow lines became one wide line. The bytes went down by about 85 percent for that service, because most of a narrow log line is the timestamp, the level, the service name, the request id, repeated on every line, and the wide event carries each of those once.

The debugging effect is the surprising part. 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 against wide events with a where clause. Against narrow logs it is a join across lines by request id that most log backends cannot do at all, and that engineers would give up on and guess instead. The wide event made the questions answerable that the narrow lines had made everyone stop asking.

Sample at the tail, keep every error#

The second change is to sampling. Head-based sampling at 10 percent keeps 10 percent of everything, which is 10 percent of the boring successes and 10 percent of the interesting failures. Tail-based sampling makes the decision at the end of the request, when you know how it went.

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 for a small list of tenants that are being watched, usually because they reported something. Keep 2 percent of everything else, chosen by a hash of the trace id so that a whole trace is either kept or dropped and you never get half a tree.

That rule, implemented in the OpenTelemetry collector's tail sampling processor, cut the trace volume by about 70 percent and increased the share of errors that had a trace from about 10 percent to 100 percent. The on-call engineers noticed the second part before anyone noticed the first.

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 was about 1.5 GB per collector. That is a real cost and it is a small fraction of what it replaced.

Retention by usefulness#

The third change is that not everything is worth keeping for 30 days. Wide events for successful requests are queried within the first week if they are 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 are queried for longer, because they are what incidents and post-mortems look at.

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 had before. The 90 day tier is small, because errors are rare, and it holds exactly the data that a post-mortem three weeks later needs.

Metrics were the one thing we did not touch. They are 10 percent of the bill and they are the cheapest way to know something is wrong. Cutting them would be saving money on the smoke detector.

The result#

The bill went down 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 which are queryable, and every request that failed or was slow has a full trace for 90 days.

Time to diagnosis in incidents got shorter, not longer, and I want to be clear that this is not a coincidence or a happy side effect. The old telemetry was expensive because it was unstructured, and it was hard to debug with because it was unstructured. Fixing the structure fixed both. The instinct that says cost and observability trade off against each other is only true when the telemetry is badly designed, and most telemetry is badly designed because it grew from console.log calls added one at a time over years.

How we moved without going blind#

The risk in a change like this is the fortnight where the old telemetry is gone and the new telemetry is not trusted yet. An incident in that fortnight is worse than an incident before or after. So the migration was staged to never have that fortnight.

For two weeks each service emitted both: the old narrow log lines and the new wide event. The bill went up during those two weeks, which finance did not love and which I had warned them about. In exchange, every dashboard and every alert was rebuilt against the wide events while the old ones still worked, and each rebuilt panel was checked against its predecessor on the same time range. Where they disagreed, the wide event was usually right, because the narrow lines had been sampled by the head-based rule and the wide events had not.

The alerts were the part that needed the most care. An alert on "error rate above 1 percent" had been computed from the "request completed" log line's status field. It became a query over wide events with the same threshold, and for a week both alerts were live and any time one fired without the other was investigated. There were two of those. One was a route that the old line had never logged because of a middleware ordering bug, which the wide event caught because it is emitted in a finally. The other was a timezone bug in the new query. Both were worth finding before the old alert was turned off.

Then the old lines were removed, service by service, starting with the one that produced the most volume, because that is where the bill was and because a problem there would show up fastest.

Libraries that log were the one thing this did not cover. The database client logs slow queries, the HTTP client logs retries, the framework logs its own startup. Those stayed as narrow lines, at a warning level or above, and they are a small fraction of the volume. The rule is that application code emits wide events and libraries emit what they emit, and nobody spends a week trying to make a third party logger conform.

What we got wrong#

Three things, all fixable, all things I would tell someone to avoid.

The decision_wait on the tail sampler was set to 5 seconds at first, which is the number in most examples. Requests that took longer than 5 seconds, which are exactly the requests you want traces for, were being decided on before they finished, and 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, then to 30 for the service with the batch endpoints. The cost is memory on the collector, and the memory is cheap compared to the trace you needed and did not have.

The wide event did not have the tenant id on it for the first version, because the middleware that emitted the event ran before the middleware that resolved the tenant. That meant a full week of events that could not be filtered by tenant, which is the single 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 of those fields is a free text error message with a unique request id embedded in it is a hundred thousand distinct values a day, and the backend's indexing cost for that one field exceeded the savings from removing the narrow lines. The error message is now a stable code, and the free text goes on the trace span, which is not indexed. Look at the distinct value count for every field in the first week. Anything that grows with traffic is a field that wants to be a span attribute instead.

If your bill has crossed the line#

Find the three log statements that produce most of the volume. There will be three. They will 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. Check the query logs to find out. The answer is almost always "a week for successes, longer for failures".

Leave metrics alone.

That was about three weeks of work for one engineer, spread across two months, and it paid for itself in the first month.