Debug k6 Results Without Blaming the Application First

A nightly k6 run against the catalog endpoint reports a p95 of 260 ms. The objective is 50 ms, and last week's run sat at 10 ms. A regression ticket goes to the catalog team, whose dashboard shows handler p95 at 10 ms all night. Both numbers are correct. The 250 ms between them was spent on the load generator, which was parsing 328 KB of JSON on every iteration on a runner with two cores. The service code did not change.

Part 1 of this series, choosing the test type from the release question, assumed the numbers coming out of a run describe the system. This part covers the step between a red result and a bug report: checking whether the run measured the service at all. Every run below creates one of these disagreements on purpose, so you can see which k6 signal moves for each cause and which one stays put.

A lab that fakes four regressions

The stub has two endpoints. GET /catalog waits 8 ms without using CPU and returns 328,292 bytes of JSON describing 1,500 products. POST /accounts/:id/debit holds a per-account lock for 8 ms. Both send a Server-Timing header with the handler's own duration, and the debit endpoint also reports how long it waited for the lock. Once a second, the server writes the p95 of its handler time to a CSV.

The generator was limited to two cores with GOMAXPROCS=2, as on a small CI runner. According to the Go runtime documentation, that variable limits how many operating-system threads can run Go code at the same time. The same limit applies on Kubernetes without anyone setting it: from Go 1.25, on Linux, the runtime sets the default GOMAXPROCS from the container's cgroup CPU limit, and it ignores the CPU request. So a k6 pod with a CPU limit of 2 behaves like this lab even on a 64-core node. The machine had ten cores, so the stub never had to compete with k6 for CPU.

First split: the time the server can account for

k6 defines http_req_duration as http_req_sending + http_req_waiting + http_req_receiving. It documents waiting as time to first byte, which is why people read it as server time. The first run shows why that reading is unsafe. With two cores, it ramped from 50 to 450 catalog requests per second. The table below splits the request phases for a healthy window and a saturated window:

Almost all of the extra latency was recorded as waiting, the phase everyone attributes to the server, while the server's own figure barely moved. The way to catch this is to record what the server can account for next to every request, and to track the difference as a metric of its own:

import { Trend } from 'k6/metrics';

const serverTime = new Trend('server_time', true);
const unexplained = new Trend('ttfb_minus_server', true);

// inside the default function, after the request
const app = Number(/app;dur=([\d.]+)/.exec(res.headers['Server-Timing'] || '')?.[1]);
if (Number.isFinite(app)) {
  serverTime.add(app);
  unexplained.add(res.timings.waiting - app);
}

The W3C Server Timing specification defines dur and recommends milliseconds as its unit. The same specification warns that these metrics can expose sensitive application and infrastructure details, so turn the header on in the test environment, or strip it at the edge. If the service is traced, a server span's duration gives you the same number. OpenTelemetry's context propagation passes trace IDs in the W3C traceparent header, which is how a client request gets joined to its server span.

From here the diagnosis branches. If ttfb_minus_server grows while server time stays flat, the cause sits outside the service: either the generator or the path to it. If both rise together, the server really is slower, though the test may still be the reason. Read the sections that follow by which of those you are looking at.

The script is part of the workload

The first run's iteration parsed every response and ran two content checks over all 1,500 items:

// Costly at load: every iteration parses 328 KB and walks every item
const res = http.get(`${BASE}/catalog`);
const items = res.json('items');
check(res, {
  'status 200': (r) => r.status === 200,
  'every item has a price': () => items.every((i) => typeof i.price === 'number'),
  'cheapest in stock under 10': () =>
    items.filter((i) => i.stock > 0).sort((a, b) => a.price - b.price)[0].price < 10,
});

Here is the aligned timeline for that run, cut to every fifth second. gen_cores is k6's CPU time per wall-clock second, so 2.00 means both cores were busy:

  t  gen_cores  iters  dropped  recv_MB  client_p95 server_p95 (ms)
  0       0.44     47        0     15.4         9.8        9.3
 10       0.68    120        0     39.4         9.5        9.2
 20       1.02    186        0     61.1         9.9        9.1
 30       1.40    254        0     83.4        11.8        9.2
 35       1.59    286        0     94.0        14.2        9.3
 40       1.84    321        0    105.4        19.7        9.3
 45       2.02    352        0    115.6       126.8       10.0
 50       2.01    354       15    116.3       201.6       10.3
 55       1.92    306      104    100.5       372.4       11.1

Client p95 started to drift from the server figure at about 1.4 cores, which is 70% of the generator, and roughly doubled by 1.84 cores. In the second the generator reached 2.00 cores, p95 jumped from about 20 ms to 134 ms. Completed iterations stopped near 355 a second while the schedule kept climbing towards 450. Server p95 never went above 14 ms in any second of the run. The end-of-test summary still reported http_req_duration p(95)=260.4ms, with the custom server metric at p(95)=10.01ms two lines above it.

Grafana's guide to running large tests gives the threshold: leave at least 20% of the generator's CPU idle. If k6 uses 100% of the CPU, it warns, the results can show response times much larger than in reality. The fix is to stop paying for parsing that the decision doesn't need. Set discardResponseBodies: true, and opt back in with responseType: 'text' only on the requests whose body you actually read. Check the catalog's content in a smoke run rather than on every iteration at peak:

export const options = {
  discardResponseBodies: true,
  // scenarios unchanged
};

export default function () {
  const res = http.get(`${BASE}/catalog`);
  check(res, { 'status 200': (r) => r.status === 200 });
}

On the same two cores and the same ramp, this version finished with p95 at 9.64 ms, no dropped iterations and at most four active VUs. The generator never used more than 0.25 cores. The change does not reduce bytes on the wire: this run received 82 MB/s against the costly run's 77 MB/s, because the body still crosses the network and is thrown away when it arrives.

To estimate script cost before a big run, measure it at low load. In the first 30 seconds of the costly run, median iteration_duration was 12.33 ms against a median http_req_duration of 8.67 ms. That leaves about 3.7 ms of JavaScript per iteration, and 3.7 ms at 450 iterations a second comes to roughly 1.7 cores before k6 has handled a single byte of HTTP. Don't try to take this measurement at peak. In the saturated window the two medians were 149.75 ms and 138.12 ms, because a starved generator delays reading responses as well as running JavaScript, so the cost turns up inside the request timings.

A one-second CPU sampler is enough to produce the gen_cores column. It reads the process's cumulative CPU time from ps, which works on macOS and Linux:

#!/bin/zsh
# usage: cpu-sample.sh <k6-pid> <out.csv>   (CPU seconds used per wall second)
pid=$1; out=$2
echo "second,cores_used" > $out
toSec() { awk -F'[:.]' '{ if (NF==3) print $1*60+$2+$3/100; else print $1*3600+$2*60+$3+$4/100 }'; }
prev=$(ps -o time= -p $pid | tr -d ' ' | toSec)
while kill -0 $pid 2>/dev/null; do
  sleep 1
  now=$(ps -o time= -p $pid 2>/dev/null | tr -d ' ' | toSec) || break
  [ -z "$now" ] && break
  echo "$(( $(date +%s) - 1 )),$(echo "$now - $prev" | bc -l | awk '{printf "%.2f", $1}')" >> $out
  prev=$now
done

Now the controlled rerun. The costly script ran again with only one change, GOMAXPROCS=4. It reached 420 iterations a second using 2.54 cores, with p95 at 9.73 ms and no dropped iterations. Changing only the generator's capacity made the "regression" disappear, and that is the evidence to attach when closing the ticket.

Dropped iterations show a shortage, not who caused it

The CPU run and the network run both logged the same warning before they dropped work:

level=warning msg="Insufficient VUs, reached 100 active VUs and cannot initialize more" executor=ramping-arrival-rate scenario=browse

k6's dropped-iterations page splits the causes by timing. Drops at the start of a test usually mean you need to allocate more VUs. Drops later in the test may mean the system under test is degrading and iterations are taking longer. The guide to building a k6 load model from traffic treats those late drops as a capacity finding, which is correct once the generator has been ruled out. In the CPU run, the first drop came at second 47, three seconds after the generator hit its ceiling, while server p95 stayed between 9 and 14 ms. In the network run below, drops started at second 39, also with a flat server. Late drops tell you something ran short. On their own they don't say whether it was the service, the generator, or the link.

Keep dropped_iterations as a threshold anyway, because an arrival-rate run that drops work has not delivered the load it claims. In the healthy run, which never emitted the counter, k6 reported 'count==0' count=0 as passing, so the gate is safe to add to every arrival-rate script.

A full link looks like a slow server

For the third run, a small TCP proxy sat between k6 and the stub. It allowed 5,000,000 bytes per second downstream, shared across connections (40 Mbit/s), and added 20 ms of delay in each direction, much like a remote generator on a constrained office or VPN link. The script was the cheap version from above, ramping from 5 to 30 requests a second:

  t  gen_cores  iters  dropped  recv_MB  client_p95 server_p95 (ms)
  0       0.02      4        0      1.3       132.1       13.9
 10       0.02      9        0      3.0       117.8        9.9
 20       0.03     14        0      4.6       118.0        9.9
 30       0.04     15        0      4.9       593.1        9.8
 40       0.03     15        4      4.9      2709.9        9.8
 50       0.03     16        6      5.3      4886.0        9.7
 59       0.02     15       13      4.9      6567.6       10.4
 60       0.02     16        0      5.3      6578.5          -
 66          -      7        0      2.3      6569.2          -

Even at the start, nothing was queued and the client already saw about 118 ms: 40 ms of round trip, around 66 ms to push 328 KB through the link, and 10 ms of server work. From second 25 on, received bytes held at about 5 MB a second, and completions held at 15 or 16 a second, which is the link's capacity divided by the response size. The target kept climbing to 30, so the backlog grew, and p95 reached 6.5 seconds. The generator used 0.05 cores at most, and the server stayed between 9.4 and 12.3 ms.

Once again the growth went into http_req_waiting (p50 of 5,185 ms in the last 15 seconds), not http_req_receiving (53 ms). Queued bytes from earlier responses sit in front of each new response's first byte. The server logged its last request in second 59, yet k6 kept completing responses until second 66. That gap is seven seconds of responses still crossing the link after the service had finished with them.

The sign that separates this from a generator problem is a received-bytes rate that stops rising while the target keeps rising, with the generator mostly idle. Grafana's large-test guide makes the same point about network cards, noting that many AWS EC2 machines come with 1 Gbit/s connections, and suggests watching with iftop. To fix it, move the generator next to the service, or split the load across machines with --execution-segment. Note that each k6 instance then evaluates thresholds on its own share of the load, so you have to aggregate the results before drawing a verdict.

When server time rises too, check the test data

The fourth run switches to the debit endpoint, ramping from 50 to 160 debits a second. In the first version, every iteration debits the same account, which is what happens when a script logs in once with the single user from a fixture file:

// Contended: every iteration writes to the one fixture account
export default function () {
  const account = accounts[0];
  // ...POST /accounts/${account.id}/debit
}

// Spread: a different account per iteration, loaded once and shared
import exec from 'k6/execution';
import { SharedArray } from 'k6/data';

const accounts = new SharedArray('accounts', () => JSON.parse(open('./accounts.json')));

export default function () {
  const account = accounts[exec.scenario.iterationInTest % accounts.length];
  // ...POST /accounts/${account.id}/debit
}

Here is the server's own per-second log from the shared-account run, at five-second intervals:

This time the gap check passes, because the server accounts for the whole delay. Handler p95 reached 1.5 seconds, and 1,527 ms of that was spent waiting for the lock. Throughput stalled near 117 a second, close to the 125 a second that an 8 ms critical section allows on one key, and k6 dropped 144 iterations. With a different account on each iteration, the same ramp reached 147 debits a second with server p95 at about 10 ms throughout, and k6 reported p95 at 10.13 ms.

Whether this counts as a finding depends on production, not on the test. If real traffic concentrates on one key, such as a marketplace account that receives every payment, the lock is a real capacity limit and the test found it. If real traffic spreads across thousands of accounts, the run measured its own fixture. Build the pool in the init context with SharedArray, which k6 loads once and from which each VU gets a copy of any element it reads. The Test Data Generator can produce a bounded pool without accidental repeats.

The generator can also run out of sockets

With 150 VUs and a hard file-descriptor limit of 128, a ten-second run produced this line 709,924 times:

level=warning msg="Request Failed" error="Get \"http://127.0.0.1:3333/catalog\": dial tcp 127.0.0.1:3333: socket: too many open files"

The summary then claimed 80,549 requests a second, seven times the 11,447 a second that the same script achieved without the limit, because a failed dial returns almost instantly. With 88% of requests failing and no threshold set, k6 exited with status 0. A dashboard showing only the error rate would pin this on the service.

Lowering only the soft limit did nothing. Under ulimit -n 128 in zsh, which sets just the soft limit, the same run had no errors. The Go 1.19 release notes explain this: Go programs that import os raise their soft open-file limit to the hard limit at startup. So check ulimit -Hn on the generator, not ulimit -n. Ports are the next limit. k6's OS tuning guide gives macOS's default ephemeral range as 49152 to 65535, which is 16,384 ports, and a typical Linux default of 32768 to 60999.

Put all three timelines on one clock

Every table above came from one join script. It reads k6's CSV output (--out csv=run.csv), the server's per-second log and the CPU samples, and prints one row per second:

// timeline.mjs: node timeline.mjs k6.csv server.csv cpu.csv [step]
import { readFileSync } from 'node:fs';

const [k6File, serverFile, cpuFile, step = '5'] = process.argv.slice(2);
const rows = (f) => readFileSync(f, 'utf8').trim().split('\n').map((l) => l.split(','));
const p95 = (v) => (v.length ? v.sort((a, b) => a - b)[Math.ceil(v.length * 0.95) - 1] : NaN);
const fmt = (n, d, w) => (Number.isFinite(n) ? n.toFixed(d) : '-').padStart(w);

const [head, ...k6] = rows(k6File);
const col = Object.fromEntries(head.map((n, i) => [n, i]));
const bySec = new Map();
for (const r of k6) {
  const s = Number(r[col.timestamp]); // whole seconds; http_req_* are stamped when the response ends
  if (!bySec.has(s)) bySec.set(s, { client: [], dropped: 0, iters: 0, bytes: 0 });
  const b = bySec.get(s);
  const v = Number(r[col.metric_value]);
  switch (r[col.metric_name]) {
    case 'http_req_duration': b.client.push(v); break;
    case 'dropped_iterations': b.dropped += v; break;
    case 'iterations': b.iters += v; break;
    case 'data_received': b.bytes += v; break;
  }
}
const server = new Map(rows(serverFile).slice(1).map((r) => [Number(r[0]), Number(r[2])]));
const cpu = new Map(rows(cpuFile).slice(1).map((r) => [Number(r[0]), Number(r[1])]));

const secs = [...bySec.keys()].sort((a, b) => a - b);
console.log('  t  gen_cores  iters  dropped  recv_MB  client_p95 server_p95 (ms)');
for (const s of secs) {
  if ((s - secs[0]) % Number(step)) continue;
  const b = bySec.get(s);
  console.log(
    `${String(s - secs[0]).padStart(3)}  ${fmt(cpu.get(s), 2, 9)}  ${fmt(b.iters, 0, 5)}  ${fmt(b.dropped, 0, 7)}` +
      `  ${fmt(b.bytes / 1e6, 1, 7)}  ${fmt(p95(b.client), 1, 10)} ${fmt(server.get(s), 1, 10)}`,
  );
}

Two details decide whether the rows line up. k6's metrics reference says every http_req_* sample is timestamped when the response ends, so the server should log on completion as well, not on arrival. Otherwise a slow request falls into a different second on each side. When the generator and the service run on different hosts, the join is only as good as their clock sync, so check it before trusting any second-level comparison. In the tables, a dash marks a second the sampler missed or the server didn't serve.

Read across the columns and each cause leaves a different pattern:

An AI assistant is useful for this join, and for spotting which column moved first across a few thousand rows. Its conclusion should name the seconds and metrics it relied on, and it only stands once the controlled rerun moves the result in the predicted direction. A plausible story is not enough.

Make every run check its own validity

The checks above can live in the script, as thresholds that fail when the measurement itself can't be trusted. This version holds a constant 380 requests a second for 30 seconds:

import http from 'k6/http';
import { check } from 'k6';
import { Trend } from 'k6/metrics';

const serverTime = new Trend('server_time', true);
const unexplained = new Trend('ttfb_minus_server', true);

export const options = {
  discardResponseBodies: __ENV.PARSE !== '1',
  scenarios: {
    browse: {
      executor: 'constant-arrival-rate',
      rate: 380,
      timeUnit: '1s',
      duration: '30s',
      preAllocatedVUs: 50,
      maxVUs: 100,
    },
  },
  thresholds: {
    // Validity gates: if these fail, the latency numbers describe the generator, not the service.
    dropped_iterations: ['count==0'],
    ttfb_minus_server: ['p(95)<5'],
    // The service objective itself.
    http_req_duration: ['p(95)<50'],
  },
};

export default function () {
  const res = http.get('http://127.0.0.1:3333/catalog', {
    responseType: __ENV.PARSE === '1' ? 'text' : 'none',
  });
  const app = Number(/app;dur=([\d.]+)/.exec(res.headers['Server-Timing'] || '')?.[1]);
  if (Number.isFinite(app)) {
    serverTime.add(app);
    unexplained.add(res.timings.waiting - app);
  }
  if (__ENV.PARSE === '1') {
    const items = res.json('items');
    check(items, { 'cheapest in stock under 10': (list) =>
      list.filter((i) => i.stock > 0).sort((a, b) => a.price - b.price)[0].price < 10 });
  }
}

With PARSE=1 on two cores, all three gates failed and k6 exited with 99:

    dropped_iterations
    ✗ 'count==0' count=2229

    http_req_duration
    ✗ 'p(95)<50' p(95)=365.62ms

    ttfb_minus_server
    ✗ 'p(95)<5' p(95)=324.01ms

Without parsing, on the same two cores, all three passed: no drops, p95 at 9.56 ms, and an unexplained gap of 666 µs. The exit code is the same 99 whether the service or the measurement failed, so CI has to look at which metrics crossed. k6 names them in its final error line. A crossed validity gate means the run produced no verdict and needs a rerun, not a bug report. Deriving the objective threshold from an SLI is the subject of Part 2 on thresholds that fail CI for the right reasons. The k6 Script Generator gives you a reviewable starting script to add these gates to, and the API Response Time Analyzer helps inspect one window's latency distribution.

Apply this before the next regression ticket

• Expose handler time on one endpoint in the test environment, with Server-Timing or a span, and add the ttfb_minus_server trend to its script.
• Sample generator CPU during the next run. If it goes above 80% of the cores k6 can use, treat the run as a benchmark of the generator. On Kubernetes, the pod's CPU limit sets that core count.
• Estimate script cost at low load: the median of iteration_duration minus http_req_duration, multiplied by the target rate, gives a rough count of cores the JavaScript alone will need.
• Run ulimit -Hn on the generator and compare it with your peak VU count multiplied by connections per VU.
• Add dropped_iterations: ['count==0'] to every arrival-rate script.
• Before filing a regression, rerun once with only the generator's capacity or location changed. Attach the aligned timeline from both runs to the ticket.

The evidence to keep is the per-second table of generator CPU, received bytes, client p95 and server p95 for the failing run and the rerun. With that table, anyone reading the ticket can check which side moved.

Questions about debugging k6 results

Can the generator run on the same host as the service?

Only to check the script. The lab here did it to isolate one variable at a time, with ten cores and a hard core cap on k6. On a smaller shared host, the two processes compete for the same CPU and the loopback interface hides every network effect, so latency numbers from that setup say little about production.

Should checks be removed to save generator CPU?

Remove checks that cost CPU, not checks that decide correctness. Grafana's large-test guide notes that every check and custom metric sample is recorded separately and has a cost. A status check is cheap. A check that parses and sorts a 328 KB body is the costly kind, and belongs in a smoke run.

Is http_req_waiting ever pure server time?

Only when the generator and the link are both healthy, and that is exactly what ttfb_minus_server measures. In the healthy validity-gate run above the gap was 666 µs at p95. In the CPU and network runs, the same phase carried hundreds or thousands of milliseconds that the server never spent.

Does raising maxVUs fix dropped iterations?

Only when the drops come from configuration, which shows up as drops at the start of the run with a healthy generator. When the generator is already at its CPU ceiling, more VUs cannot help: the schedule already asks for more JavaScript per second than the cores can run, and the doubled-core rerun cleared the drops with the same maxVUs. Fix the script or add capacity first, then size the VUs.

Primary references

• Running large tests (Grafana k6 docs). Keeping 20% of generator CPU idle, the warning that 100% CPU inflates response times, network-card limits and iftop, the cost of checks and custom metrics, the error strings including socket: too many open files, and per-instance thresholds under --execution-segment.
• Dropped iterations concept page (Grafana k6 docs). Early drops meaning too few VUs, later drops possibly meaning a degrading system, and gating the counter with a threshold.
• Built-in metrics reference (Grafana k6 docs). http_req_duration as sending plus waiting plus receiving, waiting as time to first byte, and http_req_* timestamps taken at the end of the response.
• Response object, timings fields (Grafana k6 docs). res.timings.waiting and the other per-request phase values used for the gap metric.
• k6 options reference (Grafana k6 docs). discardResponseBodies and its effect on memory and garbage collection, and --execution-segment.
• HTTP request params (Grafana k6 docs). responseType values text, binary and none for opting individual requests back into a body.
• SharedArray API (Grafana k6 docs). Construction in the init context, a copy of the element on each access, and the pitfalls that undo its memory savings.
• Fine-tuning the OS for k6 (Grafana k6 docs). Soft and hard limits, the macOS ephemeral port range of 49152 to 65535, and the Linux local port range.
• Threshold syntax and aggregations (Grafana k6 docs). count as an aggregation for Counter metrics and the non-zero exit code when a threshold fails.
• CSV results output (Grafana k6 docs). The --out csv option and the columns the join script reads.
• k6 v2.3.0 release at its tag (GitHub). The Go 1.27.1 build image and the Go 1.26 minimum.
• Go runtime package documentation. What GOMAXPROCS limits.
• Go 1.25 release notes. Container-aware GOMAXPROCS taken from the cgroup CPU limit, ignoring CPU requests.
• Go 1.19 release notes. Go programs raising the soft open-file limit to the hard limit at startup.
• W3C Server Timing specification. The header syntax, dur in milliseconds as a recommendation, and the warning about exposing sensitive information.
• OpenTelemetry context propagation concepts. Carrying trace IDs across services in the W3C traceparent header so client requests can be joined to server spans.