From fc72727427ac137243912ef6ea217dc1fb815b00 Mon Sep 17 00:00:00 2001 From: yashksaini-coder Date: Sat, 5 Sep 2026 23:56:33 +0530 Subject: [PATCH] fix: count a timeout once, and let the failure rate see it Two rules, one owner each. onTimeout owns the timeouts counter. Giving up is what that counter means, and that hook is the only place that knows whose deadline elapsed. It no longer books totalFailed at all: every node already has one path that books it when the request ends there, resolve for the root client and the fan-out join for everything below, and both fire for every reason rather than only this one. resolve owns the root's totalFailed, for every reason alike, and no longer adds a second timeout to the client's counter. Before this, a client calling its dependency directly was credited twice by two paths for one dead request, and a node between the client and the slow dependency was credited twice again by onTimeout and the join. Measured over 30s, per topology, node failures against what the system booked: client -> service client 2743 -> 1494 system 1494 client -> api -> db api 2362 -> 1446 system 1446 partial 26% loss client 820 -> 410 system 410 The timeout rate no longer outruns the load: 50 rps offered read 91 timeouts a second and now reads 46. With the counting fixed, errorRate can include timeouts, which is the bug this started from. It left them out of both halves, so the cell the canvas labels "failing" was the failure rate among requests that did not time out, and a caller losing a quarter of its traffic read 0%. That case now reads 26%, and a middle node losing everything to its dependency reads 100% where it read 0%. Attribution still lands where the waiting happened. In client -> api -> db the api holds the timeouts and the client holds none, because the client never gave up: it was handed a failure. The client's totalFailed still counts it, from resolve. timeoutAttribution.test.ts pins both rules across all three topologies: no double at the root, the root still booked when a node below it gave up, no node failing more often than the system did, a client that cannot time out faster than it offers load, the counter landing on whoever waited, and the failure rate tracking the traffic actually lost. Seven of the ten fail against the old engine. Closes #51. --- src/sim/engine.ts | 28 ++++-- src/sim/timeoutAttribution.test.ts | 145 +++++++++++++++++++++++++++++ 2 files changed, 167 insertions(+), 6 deletions(-) create mode 100644 src/sim/timeoutAttribution.test.ts diff --git a/src/sim/engine.ts b/src/sim/engine.ts index 4d99643..96b8ef0 100644 --- a/src/sim/engine.ts +++ b/src/sim/engine.ts @@ -833,7 +833,13 @@ export class Engine implements BehaviourCtx { const timeoutRate = state.timeouts.rate(now); const hits = state.hits.rate(now); const misses = state.misses.rate(now); - const resolved = completions + errorsPerSec + shedRate; + /* + * Timeouts belong in both halves. They were in neither, so `errorRate` + * answered "how many of the requests that did not time out went wrong" + * while the cell rendering it says "failing", and a caller losing a + * quarter of its traffic to a slow dependency read 0%. + */ + const resolved = completions + errorsPerSec + shedRate + timeoutRate; // A fresh object per snapshot, deliberately. Mutating a reused entry in // place makes every memoised consumer see an unchanged reference and @@ -871,7 +877,8 @@ export class Engine implements BehaviourCtx { entry.p50 = this.nodePctScratch[0]; entry.p95 = this.nodePctScratch[1]; entry.p99 = this.nodePctScratch[2]; - entry.errorRate = resolved > 0 ? (errorsPerSec + shedRate) / resolved : 0; + entry.errorRate = + resolved > 0 ? (errorsPerSec + shedRate + timeoutRate) / resolved : 0; entry.shedRate = shedRate; entry.timeoutRate = timeoutRate; entry.hitRate = hits + misses > 0 ? hits / (hits + misses) : 0; @@ -1914,8 +1921,14 @@ export class Engine implements BehaviourCtx { const parent = call.parent; const callerState = parent ? this.nodes.get(parent.nodeId) : null; if (callerState) { + // Giving up is what this counter means, so it belongs here and only + // here: this is the node whose deadline elapsed. callerState.timeouts.add(this.now, 1); - callerState.totalFailed++; + // The failure itself is NOT booked here. Every node already has one + // path that books it when the request ends there: `resolve` for the + // root client, and the fan-out join for everything below it, both of + // which fire for every reason rather than only this one. Booking it + // here as well is what made a node fail more often than the system did. } // Detach the call from its parent so its eventual completion is discarded, @@ -1992,9 +2005,12 @@ export class Engine implements BehaviourCtx { this.failures[reason]++; if (client) { client.totalFailed++; - if (reason === 'timeout') client.timeouts.add(this.now, 1); - else if (reason === 'shed') client.sheds.add(this.now, 1); - else client.errors.add(this.now, 1); + // No timeout arm. `onTimeout` already attributed it to whichever + // node gave up, which is this client when it called its dependency + // directly and some node below it otherwise. Counting it again here + // is what made a client's timeout rate outrun the load it offered. + if (reason === 'shed') client.sheds.add(this.now, 1); + else if (reason !== 'timeout') client.errors.add(this.now, 1); } } this.recycle(req); diff --git a/src/sim/timeoutAttribution.test.ts b/src/sim/timeoutAttribution.test.ts new file mode 100644 index 0000000..4b99829 --- /dev/null +++ b/src/sim/timeoutAttribution.test.ts @@ -0,0 +1,145 @@ +import { describe, expect, it } from 'vitest'; +import { Engine } from './engine'; +import { defaultConfig } from './presets'; +import type { NodeKind, SimNode, Topology } from './types'; + +/** + * Who owns a timeout, and what the failure rate counts. + * + * Two rules, one owner each. `onTimeout` owns the `timeouts` counter, because + * giving up is what that counter means and that hook is the only place that + * knows which node's deadline elapsed. `resolve` owns the ROOT's + * `totalFailed`, because it books every reason alike and is the only place + * that sees the request end. + * + * They used to overlap. `resolve` also booked the timeout, so a client calling + * its dependency directly was credited twice by two different code paths for + * one dead request: its timeout rate outran the load it was offering, and its + * `totalFailed` came out at nearly twice what the system booked. + * + * Separately, `errorRate` left timeouts out of both halves of its ratio, so + * the cell the canvas labels "failing" was the failure rate among requests + * that did not time out. A caller losing a quarter of its traffic read 0%. + */ + +const n = (id: string, kind: NodeKind, cfg = {}): SimNode => + ({ + id, + kind, + label: id, + x: 0, + y: 0, + config: { ...defaultConfig(kind), ...cfg }, + }) as SimNode; + +/** The client calls its dependency directly, so the client is the one that gives up. */ +const direct: Topology = { + nodes: [ + n('c', 'client', { rps: 50, timeoutMs: 20 }), + n('s', 'service', { serviceMs: 200 }), + ], + edges: [{ id: 'c->s', from: 'c', to: 's', weight: 1 }], +}; + +/** A node below the root gives up instead, and the failure propagates. */ +const throughApi: Topology = { + nodes: [ + n('c', 'client', { rps: 50, timeoutMs: 500 }), + n('a', 'service', { serviceMs: 5, timeoutMs: 20, capacity: 64 }), + n('d', 'db', { serviceMs: 200 }), + ], + edges: [ + { id: 'c->a', from: 'c', to: 'a', weight: 1 }, + { id: 'a->d', from: 'a', to: 'd', weight: 1 }, + ], +}; + +/** Some requests beat the deadline and some do not, so the true loss is partial. */ +const partial: Topology = { + nodes: [ + n('c', 'client', { rps: 40, timeoutMs: 40 }), + n('s', 'service', { serviceMs: 40, serviceCv: 1.2, capacity: 8 }), + ], + edges: [{ id: 'c->s', from: 'c', to: 's', weight: 1 }], +}; + +function run(topology: Topology, seconds = 30) { + const engine = new Engine(topology, 42); + for (let i = 0; i < Math.round((seconds * 1000) / (1000 / 60)); i += 1) { + engine.advance(1000 / 60); + } + return engine.snapshot(); +} + +describe('a timeout is booked once', () => { + it('does not double the root when the root is the caller', () => { + const s = run(direct); + expect(s.nodes['c']!.totalFailed).toBe(s.system.totalFailed); + }); + + it('still books the root when a node below it gave up', () => { + const s = run(throughApi); + expect(s.nodes['c']!.totalFailed).toBe(s.system.totalFailed); + }); + + it('keeps a node from failing more often than the whole system did', () => { + for (const topology of [direct, throughApi, partial]) { + const s = run(topology); + for (const stats of Object.values(s.nodes)) { + expect(stats.totalFailed).toBeLessThanOrEqual(s.system.totalFailed); + } + } + }); + + it('does not let a client time out faster than it offers load', () => { + const c = run(direct).nodes['c']!; + expect(c.timeoutRate).toBeLessThanOrEqual(c.arrivalRate + 1); + }); +}); + +describe('the timeout lands on whichever node gave up', () => { + it('credits the client when the client is the one waiting', () => { + expect(run(direct).nodes['c']!.timeoutRate).toBeGreaterThan(0); + }); + + it('credits the middle node, and not the client, when that is who waited', () => { + const s = run(throughApi); + expect(s.nodes['a']!.timeoutRate).toBeGreaterThan(0); + expect(s.nodes['c']!.timeoutRate).toBe(0); + }); +}); + +describe('the failure rate counts timeouts', () => { + it('tracks the traffic actually lost', () => { + const c = run(partial).nodes['c']!; + const lost = 1 - c.throughput / c.arrivalRate; + + expect(c.shedRate).toBe(0); + expect(c.timeoutRate).toBeGreaterThan(0); + expect(c.errorRate).toBeGreaterThan(lost - 0.1); + expect(c.errorRate).toBeLessThan(lost + 0.1); + }); + + it('sees a middle node losing everything to its dependency', () => { + expect(run(throughApi).nodes['a']!.errorRate).toBeGreaterThan(0.9); + }); + + it('eases off as the deadline gets more generous', () => { + const tight = run(partial).nodes['c']!.errorRate; + const loose = run({ + ...partial, + nodes: [n('c', 'client', { rps: 40, timeoutMs: 200 }), partial.nodes[1]!], + }).nodes['c']!.errorRate; + + expect(tight).toBeGreaterThan(loose); + }); + + it('stays inside its bounds', () => { + for (const topology of [direct, throughApi, partial]) { + for (const stats of Object.values(run(topology).nodes)) { + expect(stats.errorRate).toBeGreaterThanOrEqual(0); + expect(stats.errorRate).toBeLessThanOrEqual(1); + } + } + }); +});