How to run a soak test

Run the same load in cycles with a return to idle between them, and sample process.getActiveResourcesInfo() at each idle. Here 27 requests per cycle left the service holding 27, then 54, then 81 timers and listeners, while resident memory moved 1.1 MB in total. The idle count is the leak.

Why check this

Run this before a release that stays up for days between deploys, and after any change to a handler that subscribes, schedules or connects. Memory is the resource everyone watches and rarely the one that fails first.

The failure it catches is a service that passes a five minute load test and answers 503 on the third day, because every order kept one connection to a downstream that accepts 60. The limit a timer reaches is a count, not a byte total, so a memory graph never bends.

Prerequisites

// sink.mjs   the downstream service the handler connects to
import { createServer } from 'node:net';
const held = [];
const srv = createServer((s) => { held.push(s); s.write('k'); s.on('error', () => {}); });
srv.maxConnections = 60;
srv.listen(9752, '127.0.0.1', () => console.log('sink on 9752, maxConnections 60'));
// soak-server.mjs   the service under test
import { createServer } from 'node:http';
import { connect } from 'node:net';
import { EventEmitter } from 'node:events';

const bus = new EventEmitter();
const sockets = [];
const t0 = Date.now();
let handled = 0;

const mb = (b) => +(b / 1048576).toFixed(1);
const stats = () => {
  const c = {};
  for (const r of process.getActiveResourcesInfo()) c[r] = (c[r] ?? 0) + 1;
  return { t: Math.round((Date.now() - t0) / 1000), rss: mb(process.memoryUsage().rss),
    handled, listeners: bus.listenerCount('tick'), sockets: sockets.length, resources: c };
};
const json = (res, code, o) => {
  res.writeHead(code, { 'content-type': 'application/json' });
  res.end(JSON.stringify(o));
};

function order(req, res, cleanUp) {
  handled += 1;
  const retry = setTimeout(() => {}, 600000);
  const onTick = () => {};
  bus.on('tick', onTick);
  const s = connect(9752, '127.0.0.1');
  let done = false;
  const end = (ok, why) => {
    if (done) return;
    done = true;
    if (cleanUp) { clearTimeout(retry); bus.off('tick', onTick); s.end(); } else if (ok) sockets.push(s);
    ok ? json(res, 200, { ok: true }) : json(res, 503, { ok: false, why });
  };
  s.on('data', () => end(true));
  s.on('error', (e) => end(false, e.code));
  s.on('close', () => end(false, 'closed-by-sink'));
}

createServer((req, res) => {
  const path = req.url.split('?')[0];
  if (path === '/order') return order(req, res, false);
  if (path === '/order-fixed') return order(req, res, true);
  if (path === '/stats') return json(res, 200, stats());
  res.writeHead(404).end();
}).listen(9751, '127.0.0.1', () => console.log('listening on 9751'));

setInterval(() => console.log(JSON.stringify(stats())), 1000).unref();
#!/bin/sh
# soak.sh <route> <cycles>   five seconds of load at 5 req/s, then five idle
ROUTE=$1; N=${2:-3}
i=1
while [ $i -le $N ]; do
  npx autocannon@8 -c 2 -R 5 -d 5 -j http://127.0.0.1:9751$ROUTE > cycle-$i.json 2>/dev/null
  sleep 5
  echo "cycle $i  $(node -e "const r=require('./cycle-$i.json');console.log('sent',r.requests.total,'non2xx',r.non2xx)")  $(curl -s http://127.0.0.1:9751/stats)"
  i=$((i+1))
done

Steps

  1. Step 1.

    Read the idle baseline before any load.

    curl -s http://127.0.0.1:9751/stats
    
    {"t":7,"rss":53.4,"handled":0,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":1}}

    TCPServerWrap is the listening socket. TCPSocketWrap is the connection this request arrived on, so the reading includes the reader. Later samples are compared against these numbers, not against zero.

  2. Step 2.

    Run three cycles against the route that releases what it takes.

    sh soak.sh /order-fixed 3
    
    cycle 1  sent 25 non2xx 0  {"t":19,"rss":52.8,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":1}}
    cycle 2  sent 25 non2xx 0  {"t":30,"rss":53.8,"handled":54,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":1}}
    cycle 3  sent 25 non2xx 0  {"t":42,"rss":54.1,"handled":81,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":1}}

    handled rises by 27 a cycle and every other number returns to the baseline. The server counted 27 where autocannon reported 25 sent, because rate limiting leaves requests in flight at the end of a run. Count on the server.

  3. Step 3.

    Read the per-second log across the first cycle and its idle.

    grep -E '"t":(1[2-9]|2[0-2])' soak-server.log
    
    {"t":12,"rss":52.5,"handled":20,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":2}}
    {"t":13,"rss":52.6,"handled":25,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":2}}
    {"t":14,"rss":52.7,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":15,"rss":52.7,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":16,"rss":52.7,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":17,"rss":52.7,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":18,"rss":52.7,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":19,"rss":52.8,"handled":27,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1}}
    {"t":20,"rss":53.1,"handled":32,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":2}}
    {"t":21,"rss":53.3,"handled":37,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":2}}
    {"t":22,"rss":53.5,"handled":42,"listeners":0,"sockets":0,"resources":{"TCPServerWrap":1,"TCPSocketWrap":2}}

    Under load this process holds two inbound sockets. At second 14 the load stops and TCPSocketWrap leaves the line entirely, which is what a working set looks like. Step 1 reported one because the request asking the question was open.

  4. Step 4.

    Run the same three cycles against the route that keeps everything.

    sh soak.sh /order 3
    
    cycle 1  sent 25 non2xx 0  {"t":53,"rss":54.3,"handled":108,"listeners":27,"sockets":27,"resources":{"TCPServerWrap":1,"TCPSocketWrap":28,"Timeout":27}}
    cycle 2  sent 25 non2xx 0  {"t":65,"rss":54.5,"handled":135,"listeners":54,"sockets":54,"resources":{"TCPServerWrap":1,"TCPSocketWrap":55,"Timeout":54}}
    cycle 3  sent 25 non2xx 19  {"t":76,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":61,"Timeout":81}}

    Three counters climb by 27 a cycle: outbound sockets, uncleared timers, bus listeners. rss moved from 54.3 to 54.5 MB over the same run, which is why a memory dashboard passes this service. Cycle 3 is the first with failures, 19 of them, and the first where sockets stops tracking listeners.

  5. Step 5.

    Read the per-second log across the cycle that failed.

    grep -E '"t":(6[5-9]|7[0-6])' soak-server.log
    
    {"t":65,"rss":54.5,"handled":135,"listeners":54,"sockets":54,"resources":{"TCPServerWrap":1,"TCPSocketWrap":54,"Timeout":54}}
    {"t":66,"rss":54.5,"handled":140,"listeners":59,"sockets":59,"resources":{"TCPServerWrap":1,"TCPSocketWrap":61,"Timeout":59}}
    {"t":67,"rss":54.6,"handled":145,"listeners":64,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":62,"Timeout":64}}
    {"t":68,"rss":54.6,"handled":150,"listeners":69,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":62,"Timeout":69}}
    {"t":69,"rss":54.4,"handled":155,"listeners":74,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":62,"Timeout":74}}
    {"t":70,"rss":54.4,"handled":160,"listeners":79,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":62,"Timeout":79}}
    {"t":71,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":60,"Timeout":81}}
    {"t":72,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":60,"Timeout":81}}
    {"t":73,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":60,"Timeout":81}}
    {"t":75,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":60,"Timeout":81}}
    {"t":76,"rss":54.5,"handled":162,"listeners":81,"sockets":60,"resources":{"TCPServerWrap":1,"TCPSocketWrap":60,"Timeout":81}}

    The failure has a shape. At second 67 sockets stops at 60, while listeners and Timeout carry on to 81. One resource hit an external cap and the other two are still unbounded. Second 74 has no row: the sampler is a setInterval, and an interval under load is not a clock.

  6. Step 6.

    Send one more request now that the downstream is full.

    curl -s -w " HTTP %{http_code}\n" http://127.0.0.1:9751/order
    
    {"ok":false,"why":"closed-by-sink"} HTTP 503

    The connection was accepted and then closed by the peer, which is how an application cap presents. A full accept queue answers ECONNREFUSED instead. Neither fault is in this service, and both are caused by it.

  7. Step 7.

    Look for the warning Node raised on its own.

    grep -m1 "MaxListeners" soak-server.log
    
    (node:34844) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 tick listeners added to [EventEmitter]. MaxListeners is 10. Use emitter.setMaxListeners() to increase limit

    It names the event, the emitter and the count, and it fires once. The count reached 81 in silence, so this line is a starting gun rather than a monitor.

  8. Step 8.

    Stop both processes and confirm the ports are clear.

    netstat -ano | grep -E "127.0.0.1:975[12] " | grep LISTENING; powershell -Command "Stop-Process -Id 34844 -Force; Stop-Process -Id 37736 -Force"; netstat -ano | grep -cE ":975[12] .*LISTENING"
    
      TCP    127.0.0.1:9751         0.0.0.0:0              LISTENING       34844
    TCP    127.0.0.1:9752         0.0.0.0:0              LISTENING       37736
    0

    Read both process ids from the last column and stop those alone.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | Idle counts return to the same numbers each cycle | A working set, released when the work ends | Record the numbers as the baseline for the next release. | | A counter rises by the same amount each cycle | One leak per request | Divide by handled to get the cost per request, then find the missing release. | | Timeout climbing while memory is flat | Timers scheduled and never cleared | Call clearTimeout on every exit path, including the error one. | | listeners climbing on a long-lived emitter | A subscription added per request | Remove it in the same function that added it. | | One counter flat while the others climb | That resource reached a cap | Read the failing response body. The cap is where the outage starts. | | Counts high during load, back to baseline at idle | Concurrency, not a leak | Sample at idle only, as every cycle above does. |

Common mistakes

Sign: A soak is declared clean because the memory graph is flat.Cause: Across the failing run above, rss moved from 54.3 to 54.5 MB while outbound sockets, timers and listeners each climbed to 81 or to the 60 the downstream allowed, and 19 requests in one cycle returned 503. Timers and listeners cost a few hundred bytes each. What they exhaust is a count.
Sign: Resource counts are read while the load is running and every soak looks like a leak.Cause: Step 3 shows the control route holding two inbound sockets under load, then dropping TCPSocketWrap from the line entirely at second 14. In-flight work and retained work look identical during load. The idle sample between cycles is the whole method.
Sign: No MaxListenersExceededWarning in the log, so listener leaks are ruled out.Cause: Node emits that warning once per emitter per event name, the first time the count passes 10. Here it fired at 11 listeners and never again while the count reached 81. A leak spread over many short-lived emitters never reaches 11 on any of them and is never announced at all.
Sign: A soak is reported by how long it ran rather than by what it handled.Cause: This run lasted 76 seconds and found the failure because the leak is per request: 27 requests a cycle, 60 downstream connections available. The generator shared eight cores with the target and loopback has no network in it, so the elapsed time is a property of this machine. Quote requests handled.

What to check next

FAQ

What is soak testing in software testing?

Moderate load held long enough for per-request accumulation to reach a limit. It is not about peak traffic. It asks whether the process still serves after a few hundred thousand requests.

What is the difference between soak testing and load testing?

A load test asks how much the service handles at once and reads throughput and latency. A soak test asks what it fails to release and reads counts at idle. Same generator, different columns.

What is endurance testing?

Another name for the same run: load applied for a long period against resource counters rather than a latency target. The output that matters is a rising count.

How long should a soak test run?

Long enough for the smallest limit to be reachable. Divide that limit by the leak per request. With 60 downstream connections and one held per request, 60 requests were enough, found here in 76 seconds.

Verified

Verified by Maks Vernynode 22.23.2autocannon 8.0.0curl 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.

intermediate12 minpublished updated Maks Verny