Reading Load Test Results with Distributed Tracing

A team we worked with had 500s that did not exist. Their k6 test was modest - 10 virtual users for about ten minutes with one-minute ramps, hitting one PATCH endpoint rotated across a handful of record IDs - and it kept returning intermittent 500s. Those 500s appeared in no APM trace. They appeared in no origin log. As far as the backend was concerned, nothing had failed at all.

Both tools were telling the truth. The load generator sits at one end of the path and the origin’s telemetry sits at the other, and the thing that was actually failing was in the middle, where neither one was looking.

A load test can tell you that p99 degraded or that some percentage of requests came back 500s. What it usually can’t tell you is where, because every number the generator reports rolls the whole chain in front of your origin - DNS, load balancers, CDNs, gateways - into one total. The last post covered testing through those intermediary layers. This one is about what to do after the run, when the generator and your own telemetry flatly disagree.

Get a viewpoint in the middle of the path

In that team’s case, the answer had been sitting in the gateway’s logs the whole time. The origin’s serverless container platform was returning 502s and a generic “server is overloaded” 500 page. Those requests died in an infrastructure layer in front of the application, before reaching any code the APM or the origin logs could ever have seen. Nobody was going to find that by staring harder at either end.

One viewpoint can’t localize anything, and every layer that logs is another one: a CDN’s request logs, a load balancer’s access logs, the origin’s own telemetry. A gateway is useful here because it sits mid-path and records both the status it got from upstream and the status it returned downstream. Nothing about the approach is gateway-specific though - use whatever layers you already have.

Walk the path with the attribution rule

With two or more viewpoints, most cross-layer confusion reduces to one rule: a 5xx in an intermediary’s logs came from behind it, and a 5xx the load tool saw that no intermediary logged came from in front of it. Apply that at each layer from generator toward origin and the search space collapses to the segment between the last layer with the error and the first without it.

In the story above, the bracket closes between the gateway, which logged 502s coming back from upstream, and the application, whose logs and APM were clean. Everything in between those two points is the container platform, and that is where the failures were. The whole investigation is one comparison once you have a viewpoint in the middle.

The rule assumes you’ve segmented results by status code, so you’re attributing specific errors, not an undifferentiated failure rate. It assumes you can tell an intermediary’s own error (a load balancer timing out with its own 502) from one it passed along; gateway and LB logs usually record enough to tell. And it assumes the timestamps you’re comparing across layers mean what you think they mean - a mistake worth its own section.

Measure each hop from one clock

Attribution tells you which layer to suspect. The next instinct is to measure each hop, and there is a subtle way to get that badly wrong. A team running compute-heavy workloads on their own cluster was measuring the gateway-to-cluster hop as transit = (gateway timestamp + gateway duration) - proxy timestamp. Two machines’ clocks, joined by subtraction. That transit time normally sat near 200ms, and during incident windows it held sustained stretches around 600ms. Tripled network transit is a serious finding, and it sent the investigation straight at the network path.

Measured from one clock, the same hop was fine. Time to establish a connection to the origin, timed start to end on the gateway’s own side, held steady at roughly 150ms median through every single incident window. Connection establishment isn’t request transit, but it crosses the same network path, so if transit had really tripled this would have moved too. It didn’t. The 600ms was the gap between two clocks plus everything unaccounted for between the two instrumentation points, and neither of those is the network.

Watch for that pattern: a two-clock hop metric that degrades while every single-clock measurement of the same hop stays flat. It is a measurement artifact, and it will happily eat a week.

Serverless edge runtimes add a compounding gotcha: clocks only advance on I/O. Inside a request the clock freezes while code executes, so CPU work between two I/O operations reads as taking no time. That’s standard for isolate-based multi-tenant runtimes - Cloudflare Workers documents it and Zuplo’s runtime does the same - and it’s a security measure: a clock that advanced during computation would let code time itself precisely enough for timing side-channel attacks. So a gateway’s self-reported duration under-reports CPU time systematically, and the shortfall lands in whatever residual you computed by subtraction. Measure each hop from one viewpoint’s clock, and treat cross-machine timestamp subtraction as suspect by default.

Decompose latency with span waterfalls

Logs get you attribution, but when the question shifts from “which layer failed” to “where inside a layer did the time go,” you want tracing. Distributed tracing is the systematic version of everything above: every hop and unit of work becomes a span timed on its own clock, the spans nest into one trace, and the trace renders as a waterfall you read top to bottom.

The tracing views we shipped in June were built for this kind of investigation. Setup is adding the OpenTelemetry plugin to zuplo.runtime.ts, the runtime extensions file in your modules folder (create it if you don’t have one). Its exported runtimeInit runs once when a gateway instance starts, not per request:

import { OpenTelemetryPlugin } from "@zuplo/otel";
import { RuntimeExtensions } from "@zuplo/runtime";

export function runtimeInit(runtime: RuntimeExtensions) {
  runtime.addPlugin(new OpenTelemetryPlugin());
}

Every request then becomes a waterfall of the full lifecycle: inbound policies in aggregate and individually, the handler, outbound policies, and any fetch subrequests your custom code makes, each with its own latency, status, and attributes. Traces are searchable in the portal’s Observability section, with no collector or backend to run; see the OpenTelemetry docs for configuration and plan availability.

During a load test it’s a filter-and-read loop: search the traces in the test window, filter to the slow or failed ones, read the waterfalls. The answer tends to be pretty mundane and specific. Above, of a 116ms request traced across 17 spans, 68ms went to inbound policies, 41ms of that to one rate-limit policy, and 45ms to the handler’s upstream call. The authorization check took another 26ms, split between a 12ms API key validation and a 14ms call to an external authorization service, and the outbound policies closed the request at 0ms. Whether that split is fine depends on your latency budget, and you can compare the same waterfall at 50 RPS and 2,000 RPS to see which span grew. Grafana’s k6 team has a good worked example of the same loop, walking a failed performance test down to an 11-second database query.

To join both ends of the path, run the load test with trace propagation. The W3C Trace Context standard defines a traceparent header that carries a trace ID across layer boundaries, and Zuplo’s plugin propagates it by default, so you can follow a request from client to gateway to backend. On the k6 side, the http-instrumentation-tempo jslib adds that header to every request:

import http from "k6/http";
import tempo from "https://jslib.k6.io/http-instrumentation-tempo/1.0.1/index.js";

// Patch k6's http methods here, before any requests go out
tempo.instrumentHTTP({ propagator: "w3c" });

const BASE_URL = __ENV.TARGET_URL || "https://api.example.com";

export const options = {
  // bodies we never read only cost the generator memory
  discardResponseBodies: true,
  scenarios: {
    steady: {
      executor: "constant-arrival-rate",
      rate: 200, // 200 RPS, held regardless of response times
      timeUnit: "1s",
      duration: "10m",
      preAllocatedVUs: 100,
      maxVUs: 300, // room to add VUs when latency rises, so the rate holds
    },
  },
  thresholds: {
    http_req_failed: ["rate<0.01"],
    http_req_duration: ["p(99)<800"],
  },
};

export default function () {
  http.get(`${BASE_URL}/items`);
}

The instrumentHTTP call wraps k6’s http module so each request gets a fresh trace ID and a joinable server-side trace. None of this is Zuplo-specific - any layer that honors W3C trace context can join the same trace, so the more of your path is instrumented, the fewer gaps you attribute by inference.

If the waterfall shows one big span for a custom policy of your own, add custom spans with the standard OpenTelemetry API to see where the time goes inside it. A custom policy is a TypeScript function in your modules folder wired into a route; the example below is from our troubleshooting guide:

import { ZuploContext, ZuploRequest } from "@zuplo/runtime";
import { trace } from "@opentelemetry/api";

export default async function policy(
  request: ZuploRequest,
  context: ZuploContext,
) {
  const tracer = trace.getTracer("my-tracer");
  // startActiveSpan, not startSpan, so fetch spans nest under this one
  return tracer.startActiveSpan("my-custom-operation", async (span) => {
    span.setAttribute("endpoint", request.url);

    try {
      // ... policy logic with external calls ...
      return request;
    } finally {
      span.end(); // in finally, so a throw still closes the span
    }
  });
}

One limitation when reading Zuplo waterfalls: because the runtime clock advances on I/O only (the property from above), pure-CPU work shows near-zero span duration. A span wrapping fetch calls times them accurately; one wrapping a tight parsing loop reads as nearly instant. Most gateway work is I/O-bound, so the waterfalls are accurate where it matters, but a small span duration won’t clear CPU-heavy custom code.

Budget for the cost of tracing

Tracing is not free, and we found that out on our own gateway. An internal load test at around 8,000 RPS came back understating our capacity, and the difference turned out to be tracing we had left on at full sampling and stopped thinking about. It is not simply that spans cost CPU. Every span is allocation, buffering, and export work on the hot path, and under the memory pressure that creates, our platform recycles instances early, so the run spun up materially more gateway instances with much shorter lifetimes and every replacement paid its startup cost before serving a single request. We were measuring our telemetry as much as our gateway.

That review also turned up real bugs in our tracing plugin: spans that never ended on error paths, and per-trace buffers that leaked. We shipped the fixes. It generalizes past us, though - a load test audits your telemetry along with your API, since error-path code tends to be the least exercised code you ship and a sustained run is often the first time in its life it executes millions of times in a row.

So sample or disable tracing during max-load runs, and measure the telemetry cost itself with one pass at your production sampling ratio and one with tracing off. In Zuplo the knob is head sampling on the plugin:

import { OpenTelemetryPlugin } from "@zuplo/otel";
import { RuntimeExtensions } from "@zuplo/runtime";

export function runtimeInit(runtime: RuntimeExtensions) {
  runtime.addPlugin(
    new OpenTelemetryPlugin({
      sampling: {
        headSampler: {
          ratio: 0.05, // Export 5% of traces
        },
      },
    }),
  );
}

Sampling changes what a load-test trace search can show you, and the two strategies fail differently, as the OpenTelemetry project’s sampling documentation explains:

Neither is free during a load test: head sampling costs you the traces you most wanted to read, and tail sampling adds a component that can saturate under the load you generate. Sampling reduces only export and storage work - the per-request instrumentation still runs, so a sampled pass is cheaper than an unsampled one, not free. Zuplo’s plugin makes one deliberate exception to the decide-at-the-start rule: traces whose root span ends in an error are exported regardless of the ratio, so failures stay debuggable on a heavily sampled run.

Stop arguing about whose logs are right

Every story in this post is the same argument between two teams, and in every case the argument was unwinnable with the evidence on hand. The generator said 500s, the APM said no failures, and both were correct. Transit looked tripled from two clocks and flat from one. Our own capacity number was wrong and the telemetry measuring it was the reason.

What ends those arguments is more viewpoints, not better opinions:

• Get something logging in the middle of the path, not just at the two ends.
• Apply the attribution rule at each layer: a 5xx in an intermediary’s logs came from behind it, a 5xx the load tool saw that nobody logged came from in front of it.
• Measure every hop from one clock. Treat cross-machine timestamp subtraction as wrong until proven otherwise.
• Propagate traceparent from the load generator so the run and the traces are the same dataset instead of two datasets you’re eyeballing side by side.
• Decide your sampling ratio before the run, and take one pass with tracing off if the number you’re quoting is capacity.

With tracing in place, “p99 degraded at 2,000 RPS” turns into “the authorization policy’s external check degraded at 2,000 RPS,” which is something a team can actually go and fix.

One thing this series hasn’t covered yet: at real scale a load test is an operational event, with providers to notify, budgets to set, and infrastructure to leave standing afterward. That’s the last post in the series.