Load test ramp up time

Run the same command twice against a freshly started process. Here npx autocannon@8 -c 10 -d 10 http://127.0.0.1:9672/cold reported 28 925 requests a second on the first run and 42 462,55 on the second. The whole difference sits in the first three seconds. -W [ -c 10 -d 4 ] removes it.

Why check this

Two runs of one command against one unchanged service can differ by a quarter. Check the warm-up before comparing any two load test figures, and before accepting a regression that followed a deploy changing nothing.

The failure it prevents is a release blocked on a number that measured process start. It also prevents the opposite: a warm-up discarded on a service whose users arrive during it, which every service has after a deploy.

Generator and target share this machine's eight cores, and loopback has no network in it.

Prerequisites

// warmup-server.mjs
import { createServer } from 'node:http';
let log = [], t0 = Date.now(), cache = null, pool = null, ready = false, building = false;
const mark = (d) => { const b = (log[Math.floor((Date.now() - t0) / 1000)] ??= { n: 0, ms: 0 }); b.n += 1; b.ms += d; };
const json = (res, body) => { res.writeHead(200, { 'content-type': 'application/json' }); res.end(body); };
const work = (n) => { let h = 0; for (let i = 0; i < n; i += 1) h = (Math.imul(h, 31) + i) | 0; return h; };
createServer(async (req, res) => {
  const u = req.url, began = performance.now();
  if (u === '/stats') return json(res, JSON.stringify([...log].map((b, s) => ({ s, n: b?.n ?? 0, ms: b ? +(b.ms / b.n).toFixed(3) : 0 }))));
  if (u === '/reset') { t0 = Date.now(); log = []; cache = null; pool = null; ready = false; building = false; return json(res, '{"reset":true}'); }
  if (u === '/cache') { if (cache === null) cache = work(60_000_000); }
  else if (u === '/pool') { pool ??= new Promise((r) => setTimeout(r, 300)); await pool; }
  else if (u === '/cold') {
    if (!building) { building = true; setTimeout(() => { ready = true; }, 3000); }
    if (!ready) work(3_000_000);
  } else work(30_000);
  mark(performance.now() - began);
  json(res, '{"ok":true}');
}).listen(9672, '127.0.0.1', () => console.log('listening on 9672'));
// probe.mjs <path> <count> [nokeepalive]
import { Agent, request } from 'node:http';
const path = process.argv[2], count = Number(process.argv[3]);
const agent = new Agent({ keepAlive: process.argv[4] !== 'nokeepalive', maxSockets: 1 });
const t = [];
for (let i = 0; i < count; i += 1) {
  const began = performance.now();
  await new Promise((done) => request({ port: 9672, path, agent }, (res) => { res.resume(); res.on('end', done); }).end());
  t.push(performance.now() - began);
}
const mean = (a, b) => (t.slice(a, b).reduce((x, y) => x + y, 0) / (b - a)).toFixed(2);
for (let i = 0; i < Math.min(10, count); i += 1) console.log('request ' + String(i + 1).padStart(4) + '   ' + t[i].toFixed(2) + ' ms');
for (const [a, b] of [[10, 100], [100, 1000], [1000, 5000]]) {
  if (count >= b) console.log(('mean ' + (a + 1) + '-' + b).padEnd(15) + mean(a, b) + ' ms');
}
agent.destroy();

Steps

  1. Step 1.

    Confirm the port has no listener.

    netstat -ano | grep ":9672 " | grep -c LISTENING
    
    0
  2. Step 2.

    Start the target.

    node warmup-server.mjs > warmup-server.log 2>&1 & sleep 2; netstat -ano | grep ":9672 " | grep LISTENING
    
      TCP    127.0.0.1:9672         0.0.0.0:0              LISTENING       30252
  3. Step 3.

    Run the identical command twice and change nothing between the two.

    npx autocannon@8 -c 10 -d 10 http://127.0.0.1:9672/cold; npx autocannon@8 -c 10 -d 10 http://127.0.0.1:9672/cold
    
    Running 10s test @ http://127.0.0.1:9672/cold
    10 connections
    
    
    ┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
    │ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
    ├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
    │ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.11 ms │ 1.71 ms │ 43 ms │
    └─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
    ┌───────────┬─────────┬─────────┬─────────┬─────────┬─────────┬───────────┬─────────┐
    │ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg     │ Stdev     │ Min     │
    ├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────────┼─────────┤
    │ Req/Sec   │ 341     │ 341     │ 39 807  │ 42 879  │ 28 925  │ 18 796,36 │ 341     │
    ├───────────┼─────────┼─────────┼─────────┼─────────┼─────────┼───────────┼─────────┤
    │ Bytes/Sec │ 62.8 kB │ 62.8 kB │ 7.32 MB │ 7.88 MB │ 5.32 MB │ 3.46 MB   │ 62.7 kB │
    └───────────┴─────────┴─────────┴─────────┴─────────┴─────────┴───────────┴─────────┘
    
    Req/Bytes counts sampled once per second.
    # of samples: 10
    
    289k requests in 10.01s, 53.2 MB read
    Running 10s test @ http://127.0.0.1:9672/cold
    10 connections
    
    
    ┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬───────┐
    │ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev   │ Max   │
    ├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼───────┤
    │ Latency │ 0 ms │ 0 ms │ 0 ms  │ 0 ms │ 0.01 ms │ 0.04 ms │ 10 ms │
    └─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴───────┘
    ┌───────────┬─────────┬─────────┬─────────┬─────────┬───────────┬──────────┬─────────┐
    │ Stat      │ 1%      │ 2.5%    │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min     │
    ├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
    │ Req/Sec   │ 38 303  │ 38 303  │ 42 847  │ 43 423  │ 42 462,55 │ 1 390,06 │ 38 290  │
    ├───────────┼─────────┼─────────┼─────────┼─────────┼───────────┼──────────┼─────────┤
    │ Bytes/Sec │ 7.05 MB │ 7.05 MB │ 7.88 MB │ 7.99 MB │ 7.81 MB   │ 255 kB   │ 7.05 MB │
    └───────────┴─────────┴─────────┴─────────┴─────────┴───────────┴──────────┴─────────┘
    
    Req/Bytes counts sampled once per second.
    # of samples: 11
    
    467k requests in 11.01s, 85.9 MB read

    28 925 against 42 462,55 requests a second, and 0.11 ms against 0.01 ms mean latency, from one command run twice.

    Min 341 next to a 50% of 39 807 puts one second 117 times below the median. Stdev 18 796,36 is 65% of the average, against 1 390,06 in the second run: two regimes, and an average describing neither.

  4. Step 4.

    Split the first seconds from the rest.

    curl -s http://127.0.0.1:9672/reset > /dev/null && npx autocannon@8 -c 10 -d 10 -j http://127.0.0.1:9672/cold > coldrun.json && curl -s http://127.0.0.1:9672/stats > wstats.json && node -e "const g=require('./coldrun.json'),s=require('./wstats.json').filter(b=>b.n>0),f=s[0].s;for(const b of s)console.log('second '+String(b.s-f+1).padStart(2)+'   requests '+String(b.n).padStart(6)+'   mean handler '+String(b.ms).padStart(6)+' ms');const e=s.slice(0,3),l=s.slice(3),en=e.reduce((a,b)=>a+b.n,0),ln=l.reduce((a,b)=>a+b.n,0);console.log('reported for the run   rps '+g.requests.average+'   mean latency '+g.latency.average+' ms');console.log('first 3 seconds        rps '+(en/3).toFixed(1)+'   mean handler '+(e.reduce((a,b)=>a+b.n*b.ms,0)/en).toFixed(3)+' ms   requests '+en);console.log('second 4 onward        rps '+(ln/l.length).toFixed(1)+'   mean handler '+(l.reduce((a,b)=>a+b.n*b.ms,0)/ln).toFixed(3)+' ms   requests '+ln)"
    
    second  1   requests    179   mean handler  2.739 ms
    second  2   requests    354   mean handler  2.741 ms
    second  3   requests    354   mean handler  2.746 ms
    second  4   requests  17401   mean handler  0.028 ms
    second  5   requests  42123   mean handler      0 ms
    second  6   requests  41729   mean handler      0 ms
    second  7   requests  41920   mean handler      0 ms
    second  8   requests  42366   mean handler      0 ms
    second  9   requests  41301   mean handler      0 ms
    second 10   requests  40440   mean handler      0 ms
    second 11   requests  17252   mean handler      0 ms
    reported for the run   rps 28543   mean latency 0.11 ms
    first 3 seconds        rps 295.7   mean handler 2.743 ms   requests 887
    second 4 onward        rps 35566.5   mean handler 0.002 ms   requests 284532

    887 requests, 0.31% of the run, pull the reported rate from 35 566.5 down to 28 543.

    requests.average is the mean of one sample per second, not of requests. Three slow seconds and eight fast ones are eleven samples of equal weight, so 0.31% of the traffic gets 27% of the vote.

    Handler figures are server time. The client saw 0.11 ms because ten requests queued on one thread behind 2.743 ms of work.

  5. Step 5.

    Send warm-up traffic that is not measured, and read both documents.

    curl -s http://127.0.0.1:9672/reset > /dev/null; npx autocannon@8 -W [ -c 10 -d 4 ] -c 10 -d 10 -j http://127.0.0.1:9672/cold > w.json; echo "documents in w.json: $(wc -l < w.json)"; node -e "try { require('./w.json'); console.log('JSON.parse read one document'); } catch (e) { console.log('JSON.parse failed: ' + e.message.split(String.fromCharCode(10))[0]); }"; node -e "require('node:fs').readFileSync('w.json','utf8').trim().split(String.fromCharCode(10)).forEach((x,i)=>{const r=JSON.parse(x);console.log('document '+(i+1)+'   rps '+r.requests.average+'   mean latency '+r.latency.average+' ms')})"
    
    documents in w.json: 2
    JSON.parse failed: D:\how2check\scratch\load-reading-results\w.json: Unexpected non-whitespace character after JSON at position 1184 (line 2 column 1)
    document 1   rps 9813.75   mean latency 0.76 ms
    document 2   rps 42320   mean latency 0.01 ms

    -W works: document 2, the measured run, reports 42 320 against the 28 543 of the unwarmed run in step 4.

    -W with -j writes two JSON documents to one stream, one per run. JSON.parse on the file throws, and a pipeline taking the first line reads 9 813.75 instead of 42 320. Take the last line.

    Measure the warm-up first, then set -d inside the brackets above that figure.

  6. Step 6.

    Restart the target, then name the cause by its shape, one request at a time.

    export MSYS_NO_PATHCONV=1; { echo "--- cold process, one keep-alive connection"; node probe.mjs /jit 5000; echo "--- same process, a new connection for every request"; node probe.mjs /jit 1000 nokeepalive; curl -s http://127.0.0.1:9672/reset > /dev/null; echo "--- empty cache, one keep-alive connection"; node probe.mjs /cache 10; }
    
    --- cold process, one keep-alive connection
    request    1   23.46 ms
    request    2   1.33 ms
    request    3   0.58 ms
    request    4   0.54 ms
    request    5   0.53 ms
    request    6   0.46 ms
    request    7   0.43 ms
    request    8   0.50 ms
    request    9   1.29 ms
    request   10   0.69 ms
    mean 11-100    0.24 ms
    mean 101-1000  0.20 ms
    mean 1001-5000 0.15 ms
    --- same process, a new connection for every request
    request    1   18.07 ms
    request    2   1.58 ms
    request    3   1.37 ms
    request    4   1.19 ms
    request    5   1.37 ms
    request    6   1.52 ms
    request    7   1.12 ms
    request    8   1.49 ms
    request    9   1.96 ms
    request   10   1.50 ms
    mean 11-100    0.98 ms
    mean 101-1000  1.17 ms
    --- empty cache, one keep-alive connection
    request    1   82.71 ms
    request    2   1.04 ms
    request    3   0.67 ms
    request    4   0.56 ms
    request    5   0.55 ms
    request    6   0.52 ms
    request    7   0.53 ms
    request    8   0.58 ms
    request    9   1.54 ms
    request   10   0.82 ms

    Three blocks, three shapes.

    Compilation decays: 1.33 ms at request 2, 0.24 ms over the first hundred, 0.15 ms by the thousandth, with no step in it.

    Connection setup is a constant tax: 0.98 ms and 1.17 ms with a new connection per request against 0.20 ms on one kept connection, and it never decays.

    An empty cache is a step one request wide: 82.71 ms, then 1.04 ms. That is what the first caller after every deploy pays.

    The opening request, 23.46 ms cold and 18.07 ms warm, is mostly the client.

  7. Step 7.

    Look at what a cold pool does to the report.

    curl -s http://127.0.0.1:9672/reset > /dev/null && npx autocannon@8 -c 20 -d 3 http://127.0.0.1:9672/pool
    
    Running 3s test @ http://127.0.0.1:9672/pool
    20 connections
    
    
    ┌─────────┬──────┬──────┬───────┬──────┬─────────┬────────┬────────┐
    │ Stat    │ 2.5% │ 50%  │ 97.5% │ 99%  │ Avg     │ Stdev  │ Max    │
    ├─────────┼──────┼──────┼───────┼──────┼─────────┼────────┼────────┤
    │ Latency │ 0 ms │ 0 ms │ 0 ms  │ 1 ms │ 0.08 ms │ 4.3 ms │ 316 ms │
    └─────────┴──────┴──────┴───────┴──────┴─────────┴────────┴────────┘
    ┌───────────┬────────┬────────┬─────────┬─────────┬───────────┬──────────┬────────┐
    │ Stat      │ 1%     │ 2.5%   │ 50%     │ 97.5%   │ Avg       │ Stdev    │ Min    │
    ├───────────┼────────┼────────┼─────────┼─────────┼───────────┼──────────┼────────┤
    │ Req/Sec   │ 25 023 │ 25 023 │ 40 639  │ 40 703  │ 35 442,67 │ 7 372,82 │ 25 021 │
    ├───────────┼────────┼────────┼─────────┼─────────┼───────────┼──────────┼────────┤
    │ Bytes/Sec │ 4.6 MB │ 4.6 MB │ 7.48 MB │ 7.49 MB │ 6.52 MB   │ 1.36 MB  │ 4.6 MB │
    └───────────┴────────┴────────┴─────────┴─────────┴───────────┴──────────┴────────┘
    
    Req/Bytes counts sampled once per second.
    # of samples: 3
    
    106k requests in 3.01s, 19.6 MB read

    The fourth shape is a plateau: twenty requests waited on one 300 ms setup, released together.

    Every latency percentile reads 0 ms or 1 ms. Max 316 ms and Stdev 4.3 ms, 54 times the Avg, are the only cells holding the event. Twenty requests in 106 000 cannot reach p99, so a percentile threshold never fires.

  8. Step 8.

    Stop the id on the netstat line.

    netstat -ano | grep "127.0.0.1:9672 " | grep LISTENING; powershell -Command "Stop-Process -Id 32540 -Force"; sleep 1; netstat -ano | grep ":9672 " | grep -c LISTENING
    
      TCP    127.0.0.1:9672         0.0.0.0:0              LISTENING       32540
    0

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | Req/Sec Stdev above half of Avg | The run holds two regimes | Split it by second before reading any average. | | Req/Sec Min far under 1% | One or two seconds carried the warm-up | Warm with -W, or report the steady state and the warm-up apart. | | A second run much faster than the first | The process warms and stays warm | Decide which one your users meet, then always report that one. | | Latency Max large with every percentile near zero | A one-time setup blocked a handful of requests | Count them. A percentile cannot see 20 requests in 101 000. | | Per-request times that decay with no step | Compilation or a cache filling gradually | More traffic before the measurement. | | Per-request times flat and higher than expected | A constant cost, such as a new connection each time | Not warm-up. Check keep-alive before tuning the service. |

Common mistakes

Sign: A warm-up run with JSON output crashes JSON.parse, or reports a figure nobody recognises.Cause: Combining -W and -j writes two JSON documents on two lines, the warm-up first and the measured run second. The capture above held 9 813.75 followed by 42 320, and a pipeline taking the first line is off by a factor of four. Read the last line.
Sign: The warm-up runs for the same duration as the measured test and nobody asked for that.Cause: The bracket group has to reach autocannon as separate arguments. Quoted as one string it is discarded, and the header printed Running 10s warmup for a run whose brackets said 4 seconds, doubling the wall time. Unquoted, the same flags printed Running 4s warmup. Read the header line.
Sign: A warm-up is discarded and the report no longer describes the service after a deploy.Cause: The first three seconds above served 295.7 requests a second at 2.743 ms of handler time against 35 566.5 at 0.002 ms later. Users arriving in that window are real. Report both figures and the length of the window, rather than deleting the slow one.
Sign: The probe fails before a request is sent, and the error names a path under Program Files.Cause: Git Bash rewrites an argument that starts with a slash into a Windows path, so the probe receives C:/Program Files/Git/jit instead of /jit and Node rejects it as an unescaped request path. Set MSYS_NO_PATHCONV=1 for the command, or run it from PowerShell.

What to check next

FAQ

What is ramp up time in a load test?

Two things share the name. One is the generator raising its connection count gradually; the other is the service reaching steady speed, which the runs above measure. autocannon has no gradual ramp, only -W.

How long should the warm-up be?

Long enough to cover the slowest cause on the route. Measure it with the per-second split in step 4, then set -d inside the -W brackets above that figure.

Should I discard the first seconds of every run?

Only when no user meets them. A cache filled once at start is warm-up. A cache emptied by every deploy is production behaviour for the first callers after each release.

Verified

Verified by Maks Vernyautocannon 8.0.0node 22.23.2curl 8.1.2

Each output block is what the command above it printed on that date, on the host named in the step. Figures read from a live site move between runs. Compare the shape of the answer rather than the digits, and see the methodology for how a page is re-verified.

intermediate16 minpublished updated Maks Verny