anush sonone

who broke checkout?

ยท updated ยท by anush sonone

try to find which service broke! :)

what this is

faultline replays a microservice incident like a video: metrics, traces, logs and deployments on one event-time clock, with every service scored for root cause as the evidence lands.

the problem it mocks

a modern web app isn't one program. it's dozens of small services calling each other: the storefront calls checkout, checkout calls recommendations, recommendations call the catalog. when one of them goes wrong the symptoms show up everywhere at once, because everything depends on everything, and errors spike three services away from the one that actually broke.

working backwards from those symptoms to the service that started it is called root cause analysis, and in real life it's a human at 3am staring at dashboards and guessing. the dashboards don't help as much as they should, because they show you now, and what you need is the order things happened in. the tools that do show you the order sell it as a black box, and lately the box has an llm in it. faultline does the working-backwards part in the open: you can rewind, you can see every piece of evidence, and you can see exactly how it got a case wrong.

here's the shop the real cases come from, google's online boutique demo, drawn as who calls whom, with one ordinary failure in it.

one shop, one leak, and where the pager points the twelve services of the online boutique that the real cases come from, drawn as a call graph. the frontend calls seven services, checkout calls six, recommendation calls the product catalog, and the cart keeps its data in redis. a memory leak in the product catalog is drawn as the filled box. three services call it directly, recommendation, checkout, and the frontend, so all three slow down and are drawn crossed, and the pager fires for the frontend, two hops from the cause. the eight services that never touch the catalog stay healthy. frontend-external frontend ad recommendation checkout currency shipping cart productcatalog email payment redis the pager says: frontend is slow which is true, and two hops from what actually broke filled: where the memory leak is. crossed: every service that calls it, and therefore slows down. the eight others are fine, and a dashboard sorted by error rate will still list all twelve.

the leak is in one box, the symptoms are in four, and the alert names the one furthest from the cause, because the frontend is the only service a customer can see. the eight healthy ones still show up on every dashboard, and at 3am they all look about the same.

how it works

every metric sample, log line, trace span, and deployment carries the time it happened, not the time it arrived. faultline sorts the entire incident onto that one clock and replays it, which is what lets you scrub backwards.

as the clock moves, each service gets a rolling baseline of its own normal, a median and a spread, and anything that strays far enough from it is flagged. at the end, nine kinds of evidence go into a fixed weighted sum for every service: how far it strayed, whether it went wrong before the services that call it, whether failed requests route through it, whether a deploy landed just before, and so on. that fixed sum is the whole trick, because same input means same score to the byte, and every score comes apart into the nine numbers that made it, so you can argue with any of them.

the other word worth knowing is watermark, which is the engine's promise that it has seen everything up to a given moment. telemetry arrives late and out of order, so the promise leaves a two second allowance, and anything that turns up later than that is counted but not trusted.

how an event gets in

there's really only one loop in the whole engine, and everything you see on the page falls out of it. here's a single event making the trip from disk to a pixel.

one event, start to finish an event is read from disk stamped with the time it happened. the watermark for its partition decides whether it is on time, up to two seconds late, or later than that, in which case it is counted but kept out of query state. the window it belongs to absorbs it, updating a ddsketch percentile at alpha 0.01. the service's rolling median and mad baseline turns it into a z-score. whatever changed on screen, a heatmap cell, a timeline tick, a score, goes to the page in one websocket frame carrying a sequence number. the page redraws. if the page notices a gap in the sequence it asks for a resync and the engine sends its current snapshot so the stream can continue. the engine this page 1. an event is read from disk stamped with when it happened 2. the watermark places it on time, or up to 2s late, is fine. later than that is counted, not trusted 3. its window absorbs it p99 via a DDSketch, alpha 0.01 4. the baseline judges it how far from this service's own normal? 5. one websocket frame: what changed, and a sequence number 6. the page redraws a heatmap cell, a timeline tick, a score moving up the list 7. missed a number? ask for a resync 8. the engine sends its snapshot and the stream picks up from there pressing play runs this loop at ten times real time, about 37 frames a second to the page. scrub backwards and the scores empty out, because a score only ever counts evidence up to the cursor.

step 2 is the one that took me longest to respect. a metric that shows up late isn't wrong, it's late, so a window that already closed gets one more second to change its mind, and the ui draws the revision rather than pretending the first answer was final.

step 3 is why the percentiles are approximate. an exact p99 means keeping every sample sorted, which doesn't fit in a stream, so each window keeps a ddsketch instead, a set of logarithmic buckets that answers within one percent. the heatmap, the sql engine, and the benchmarks share that one sketch, so a query and a pixel provably agree.

what a verdict looks like

this is the guided incident in the box above, one row per moment.

how five services become one ranked answer five services, left to right: frontend, checkout, recommendation, cart, catalog. at first every service sits inside its own rolling baseline and nothing is flagged. at five seconds a deployment lands on recommendation, which puts a marker on the timeline but proves nothing by itself. two seconds later recommendation's memory strays past its baseline and it is flagged first, which is what the temporal precedence feature records. checkout calls recommendation and the frontend calls checkout, so their latency and errors follow and they are flagged too, and failed requests all route through recommendation. the fixed weighted sum then ranks recommendation first at 0.86; checkout and the frontend score too, but the contradiction penalty pulls them down because they went wrong after the service they depend on. everything is fine each service has a rolling baseline of its own normal, a median and a spread over the last few minutes. nothing has strayed, so nothing is flagged. a deploy lands on recommendation five seconds in, the timeline gets a marker. on its own that proves nothing, and the score says so: change proximity is one of nine inputs, weighted a tenth. its memory strays first the z-score climbs past the baseline and recommendation is flagged, before anything that calls it. that order is what temporal precedence measures. the symptoms spread checkout calls recommendation and the frontend calls checkout, so two seconds later their latency and errors follow. every failed request routes through recommendation. the verdict: recommendation, at 0.86 checkout and the frontend score too, and the contradiction penalty pulls them down: they went wrong after the service they depend on. click the 0.86 to see all nine parts.

the crossed dots are services that strayed from their own normal, the dashed halo is a deploy that landed on one, and the filled dot is the one faultline ranks first. left to right they're frontend, checkout, recommendation, cart, and catalog, and the two that never get flagged are the ones nobody on the failing path calls.

the same fifteen seconds as the engine's own numbers, straight from the heatmap:

the guided incident, as the engine sees it p99 latency per service over the fifteen seconds of the guided incident, on the event-time clock. all five services sit at 40 milliseconds. a deployment marker lands at five seconds. recommendation starts climbing in the same second and reaches 314 milliseconds by the end. checkout and the frontend start climbing two seconds later, at seven seconds, and end near 202 milliseconds, following the same curve as each other. cart and the product catalog stay flat at 40 the whole time. the values are the ddsketch p99 from the heatmap, so the chart and the box above agree. 0 100 200 300 p99 ms 0s 5s 10s 15s event time, not wall time: when it happened, not when it arrived deploy lands on recommendation recommendation, 314 ms checkout and frontend, 202 ms cart and catalog, flat at 40 ms the callers follow two seconds later this is the order a dashboard cannot show you, because by the time you open it, all three lines are already high.

the thing to notice is the two second gap between the black line leaving 40 and the grey ones following. that gap is the whole case for replay: it's the evidence that recommendation went first, and it only exists on the event-time clock. a dashboard opened at second twelve shows three high lines and no order.

the weights are a starting hypothesis, not a tuned optimum: anomaly strength gets a fifth, three features get fifteen percent, and the rest ten or five. they're fixed on purpose, because tuning them on the cases i'm about to report would make the report worthless.

how the pieces fit together

the engine is only part of the system, so the diagram below is worth reading in two halves. the top half is everything sitting behind the box above, and it shows how a click you make actually reaches the engine. the bottom half is what three of those clicks do once they land, which is where the streaming machinery stops being plumbing and starts being the point.

how the pieces fit together the page itself comes from vercel, but the app inside it talks over https and a websocket to a cloudflare tunnel, which is the only way in. behind the tunnel, on one small vm, faultlined holds up to 24 sessions of fifteen minutes each and drives play, pause, and seek. each session runs the engine: watermarks, windows, ddsketch percentiles, a temporal join, and the ranking. the engine reads incidents from parquet files on disk, one guided, sixteen synthetic, fifteen real, and writes checksummed checkpoints back to disk. the lower half shows what three clicks do. pressing play advances the event-time clock at ten times real time and streams projections to the page. pressing crash test destroys the session's memory and recovers it from the newest valid checkpoint, with zero duplicate evidence. pressing reveal fetches the ground truth from behind a gate the ranker never sees. you, on this page the page itself comes from vercel everything below runs on one small vm https and a websocket, the only way in cloudflare tunnel play, seek, reveal, crash test faultlined up to 24 sessions, fifteen minutes each one engine per session the engine watermarks, windows, sketches, a temporal join, and the ranking reads writes, reads back incidents parquet on disk. 1 guided, 16 fake, 15 real checkpoints on disk, sha256 per file projections, over the same websocket what the page draws service map, timeline, heatmap, ranking, evidence graph, trace waterfall, runtime inspector and here's what three of your clicks do inside the rule underneath all three: the ranker only ever sees telemetry, never the answer you press play the event-time clock advances at ten times real time. events run the loop above, and the scores change as evidence arrives, not all at once. you press crash test the session's memory is destroyed on purpose. it comes back from the newest valid checkpoint, skipping corrupt ones, with no duplicate evidence. you press reveal the answer lives behind a gate on the api that the ranker never calls, so the score you saw was made blind. same gate the benchmark runs behind.

the app you're clicking is a bundle built from the faultline repo and shipped with this wiki. everything it talks to is on the other side of the tunnel, and it talks to it directly, because vercel can't proxy a websocket.

the third box is the one i care about most. in every incident, real or synthetic, the injected fault is written down in a labels file, and the api only hands it out when a request explicitly asks for it. the ranker has no such request in it, and the benchmark that produces the numbers below runs with the same gate closed.

how i built it

i started at the bottom, with a canonical envelope for every kind of event and a replay clock that reads them off parquet in event-time order, because nothing above that layer means much if two runs of the same incident can disagree. the engine came next: watermarks per partition, tumbling and hopping windows that can revise themselves, the ddsketch percentile, and a left interval join that lines deployments up against the anomalies near them.

then the parts a recruiter can see: the ranking, the trace critical path, checkpoints, and a small sql planner, because a query is a ui too. the planner takes a subset of sql, lowers it through nine logical nodes and six rewrite rules, and runs it on the same operators the heatmap uses, which is why a p99 from the sql box and the p99 in the heatmap are the same number.

all of that worked on my fixtures, and then i loaded a real case and made my first mistake visible: the streaming heatmap rebuilds itself from every event on every publish. on a fifteen second synthetic incident that's nothing. on a real case with 155 thousand events it wedged the server for about seventy seconds per publish, so for now anything past twenty thousand events loads precomputed and the streaming toggle politely refuses. the incremental rebuild is the real fix, and i haven't built it.

the second mistake was really four, and i found them all in one afternoon by running the browser tests against the server under load instead of one at a time. sessions whose tab had closed were never evicted. playback kept running for sessions nobody was watching. the watermark metrics were recomputed on every single event, walking every partition through a string-keyed map, which is invisible on a few hundred events and ruinous on 155 thousand. and the size gate above didn't exist yet. all four are fixed.

the third mistake is the one that embarrasses me most, because it wasn't a bug in the engine, it was a number i believed. my benchmark harness reported batching speedups of six to fifteen times, and i put them in the readme and on this page. then i read the harness properly: it took two clock readings and pushed to a vector inside the timed loop, so at batch size one it was mostly timing itself, and two of the workloads never touched an engine operator at all. that table is withdrawn, and no throughput number gets claimed until the harness measures the real thing.

the fourth mistake arrived when i ran the benchmark's baselines myself, on the exact same real cases, and lost to the simplest one. that story gets its own section below, because it's the most useful thing on this page.

that's four mistakes in all, and the two that hurt most weren't bugs. they were numbers i'd said out loud before checking.

what's in the box

the box at the top is a recorded incident, and the engine replaying it is the real one, running on a real server. press play and the clock moves at ten times real time: a deploy lands, one service's memory climbs, and the services that call it slow down a few seconds later. the number next to each service is faultline's score for it being the cause, and the answer stays hidden until you press reveal, so you get to guess first.

the picker holds six incidents. one is the guided one, one is from my synthetic test suite, and four are real, from a public benchmark that injects faults into a demo shop running on a real cluster. faultline gets two of the real ones right, misses one by a single rank, and misses the last one badly. those two are in there on purpose, and the next section is why.

what real data did to my numbers

on my 16-incident synthetic suite the ranking is perfect: 100% top-1, robust to every single-feature ablation. satisfying, and nearly meaningless, because i generated those faults, so of course they're separable. that suite is a smoke test of the pipeline, not evidence of anything about the world.

so i took 15 real cases from rcaeval, a public benchmark that injects faults into google's online boutique demo on a real cluster and records the metrics, logs, and traces. i used the cpu, memory, and network delay faults, one per service, and ran the same untuned pipeline blind. then i ran two methods that ship in the benchmark's own code on the same 15 cases, with the same service-level scoring: nsigma, the simplest baseline in there, and baro, a published method. one difference worth knowing: the benchmark hands its methods the moment the fault was injected, so they compare before with after, while faultline has to find the onset itself. this is the table:

method what it is top-1 top-3 avg@5
nsigma a plain z-score threshold on the metrics 93.3% at least 93.3% 0.96
baro a published bayesian change-point method 13.3% 93.3% 0.76
faultline nine features, fixed weights, untuned 26.7% 46.7% 0.41

a plain median-and-spread z-score finds the broken service 93% of the time where my whole evidence pipeline gets 27%. that's a loss, and it's a diagnostic one: faultline already computes that exact z-score as one of its nine features, so the other eight are burying the signal rather than sharpening it. the rank distribution agrees, because it's bimodal: seven cases land at rank 1 to 3, eight cases at rank 8 to 12, and almost nothing in between.

here's the hard miss from the picker, drawn the same way as the shop above, but with the graph the engine actually reconstructed from the real traces and the rank it gave every service.

a real cpu fault on the email service, and why it lands at rank 12 the call graph the engine actually reconstructed from the sampled traces of a real rcaeval case: the frontend calls checkout, currency, the product catalog, and recommendation; checkout calls currency, email, payment, and the product catalog; recommendation calls the product catalog. every one of the twelve services is drawn crossed, because every one of them strayed from its own baseline during the fault. five services, ad, cart, shipping, redis, and the external frontend, appear only in metrics because the one-in-eight trace sample never caught a call to them. the true cause, email, is filled and ranked twelfth at 0.15; currency is ranked first at 0.39. frontend rank 8, 0.31 recommendation rank 2, 0.37 checkout rank 4, 0.33 currency rank 1, 0.39 productcatalog rank 3, 0.33 email rank 12, 0.15 payment rank 11, 0.16 seen only in metrics: the 1-in-8 trace sample never caught a call to them shipping rank 5, 0.32 ad rank 6, 0.31 cart rank 7, 0.31 frontend-external rank 9, 0.31 redis rank 10, 0.20 every box is crossed: on real telemetry, everything strays at once, so anomaly strength is a tie twelve ways. the ranking is then decided by the small features, and by the penalty, which is exactly backwards for a leaf service. a plain z-score threshold ignores the graph entirely and, on these fifteen cases, gets the answer 93% of the time.

compare it to the clean picture further up. there, one box was sick and three followed it. here, all twelve strayed from their own baseline inside the fault window, because a real shop under a real load test is noisy everywhere, and a cpu hog on a leaf service that sees about one call in three hundred barely moves the shape of anything. so the feature i weighted highest, anomaly strength, is a twelve-way tie, and the ranking gets decided by the small features and the penalty.

and the penalty is exactly backwards here. email is a leaf: checkout calls it, and nothing calls it after that. when the services that call it wobble a moment before it does, the contradiction rule reads that as the callers went wrong first, so this can't be email, and docks it the full tenth. that tenth is the entire distance between rank 1 and rank 12, which you can see when the two verdicts are taken apart side by side:

two verdicts taken apart stacked bars of the nine score components for the top three candidates in the guided incident, and for three candidates in a real cpu fault on the email service. in the guided case recommendation scores 0.86, with anomaly strength, precedence, failed trace coverage, critical path, topology, and the nearby deploy all contributing, while checkout and the frontend score 0.48 and 0.46 mostly from anomaly strength and failed traces. in the real case every service has the same saturated anomaly strength and nearly the same precedence, so the currency service leads at 0.39 on a hair of topology, and the email service, the true cause, sits at 0.15 because it takes the full contradiction penalty. the guided incident: recommendation, taken apart recommendation anomaly precedence 0.86 checkout anomaly 0.48 frontend anomaly failed traces 0.46 a real cpu fault on email, taken apart. rank 1, rank 2, and the true cause at rank 12 currency anomaly precedence 0.39 recommendation anomaly precedence 0.37 email anomaly -0.10 0.15 the nine parts, left to right in every bar: anomaly precedence failed traces critical path downstream topology deploy nearby logs contradiction the dashed box hanging off the left is the contradiction penalty: a service whose callers went wrong before it did loses a tenth. in the real case that tenth is the entire gap between rank 1 and rank 12.

in the guided case the bar is long because six kinds of evidence agree, and the deploy sitting right before the fault adds its tenth on top. in the real case the bars are identical up to the third segment, and the winner is winning on a hair of topology. this is what the loss looks like from the inside.

the ablations say which features are doing real work. remove topology consistency and top-1 collapses from 26.7% to 6.7%; remove temporal precedence and it falls to 13.3%. remove change proximity and nothing moves, because rcaeval has no deployment events, so a feature i weighted at a tenth is structurally dead on every real case. the synthetic suite could never have told me that.

the fix is written down next to the numbers rather than built: score magnitude first, and use topology and precedence as tie-breakers instead of dominant weights, then re-run the same 15 cases. until that's done, no accuracy number goes on my rรฉsumรฉ, and this page reports the loss. publishing a loss feels bad for exactly one evening. shipping a number you can't defend feels worse forever.

what it does today

the engine numbers that survived the harness cleanup are the checkpoint ones, measured on my laptop and regenerated by a committed script that stamps the commit, machine, toolchain, seed, and dataset checksum.

metric p50 p99
checkpoint write, fsync included 11.9 ms 15.1 ms
recovery, read and validate 0.42 ms 0.76 ms
duplicate evidence after a forced crash 0 0

the phrase for that is checkpoint recovery with idempotent projections, never exactly-once, because the second promises something about the world and the first only about my disk. a checkpoint is written manifest-last with a checksum per file, and the pointer to the newest one flips only after a fully valid directory exists, so a crash mid-write leaves the previous one untouched.

the demo server holds 24 sessions of fifteen minutes each, so if the box above says it's busy, that's the ceiling and not a crash.

what i'd still fix

learn more

the code's at faultline, laid out roughly like this:

if streaming or root cause analysis is new to you, this is the order i'd go in:

  1. press play in the box above, watch the scores move, then scrub back to the start and watch them empty.
  2. read streaming 101 and 102 by tyler akidau. event time and watermarks are the first half of this page, and he explains them better than i do.
  3. watch his talk below, which covers the same ground with pictures.
  4. read the ddsketch paper, which is short, and then the rcaeval paper, which is the dataset. their code runs the baselines i lost to in an afternoon.
  5. clone the repo, run make demo, and read crates/inference/src/ranking.rs with the table above open beside it.

if you liked this, the sibling project is come kill my cluster!, a raft key-value store written from scratch that you can break live from the page. same idea in both: build the machinery yourself, run it in public, and report what it actually does.

heavily inspired by motherfuckingwebsite.com

utexas.network