Skip to content

Prayog: what broke

Each story is told the same way: the symptom, how it was found, the root cause, the fix, and what it taught. Commits and ADRs are in the public repo (github.com/rj8228/prayog).

1. A rule change silently rewrote history (ADR 0014)

  • Symptom: after enforcing "duplicate client order IDs are rejected", the exchange restarted and traded for about two minutes on a book that differed from what clients had been told. It appended 191 events that never happened.
  • Found by: comparing the replayed event log with the recorded one by hand after the numbers looked wrong.
  • Root cause: two bugs together. The new rule applied to all history, and the smoke test had always sent the same client order ID (smoke), so the old journal held accepted duplicates. Replay under the new rule rejected one, and every later order ID shifted. Recovery only checked that replay produced at least as many events as the log held, so it started anyway.
  • Fix: rule changes became journaled inputs (SetRules(version)): history replays under the rules it was made with, as real venues change behaviour from a point in time, never retroactively. Recovery now compares every replayed event byte for byte and refuses to start on any difference.
  • Lesson: in a deterministic system, code is part of the input. Version the rules and verify replay exactly, not approximately.

2. Orders lost when the pipeline closed right after starting (commit ab57d72)

  • Symptom: two pipeline tests failed on CI only.
  • Found by: a loop that started and closed the pipeline 300 times locally: 261 runs lost commands.
  • Root cause: Disruptor's shutdown drains only consumers whose threads are already running. A consumer that had not started yet counted as stopped, so commands still in the ring were dropped.
  • Fix: start() returns only once every handler's onStart has run.
  • Lesson: "rare on my machine" is a rate, not an absence. Make the race frequent (a tight loop) before fixing it.

3. A late Kafka ack marked a dead connection healthy (commit 9b8a506)

  • Symptom: KafkaPublisherIT failed on CI, sometimes.
  • Root cause: the error callback set a failure flag, but connected was cleared later on the publisher thread, and a late ack from an older batch could set it back to true.
  • Fix: a failed send reports disconnected at once; callbacks from a replaced producer are ignored.
  • Lesson: callbacks from an old generation of a resource must not change the state of the new one.

4. Archiving starved the exchange's heap and lost the shutdown snapshot (commit e0771db, ADR 0022)

  • Symptom: make e2e killed the exchange container during shutdown; the restart had to replay everything.
  • Found by: container logs (killed after the 30 s grace period) and a heap test: with -Xmx96m the old archiver threw OutOfMemoryError on the live 64 MiB segments.
  • Root cause: the byte-for-byte check after gzip held two 64 MiB copies in memory. The shutdown snapshot queued behind it on the same thread.
  • Fix: compare in 64 KiB chunks, gunzip into an exact-size buffer, and stop archiving once shutdown begins.
  • Lesson: background work must be bounded in memory and must yield to shutdown.

5. Order latency p99 of 445 ms with spikes to 3.5 s (docs/benchmarks.md, 2026-10-08)

  • Symptom: Grafana showed new-order p99 at 445 ms during a demo recording; the host benchmark said 12 ms median.
  • Found by: a script that queries Prometheus for latency quantiles and GC pause totals over a time window (docs/_tools/gc_latency_window.py).
  • Root cause: the JVM chose the Serial collector in a 768 MiB container. Pauses were about 6x slower than in a clean window (94 ms instead of 15 ms each, one 5.9 s full collection), most likely because the 8 GB host was short of memory while recording.
  • What I tried: generational ZGC. Its pauses were tiny, but it used the whole heap and allocation stalls raised p99 5x. A concurrent collector needs headroom.
  • Decision: keep the default collector; give Docker more memory first if the tail matters.
  • Lesson: measure the window you care about, and check GC before blaming the code. A "better" collector can be worse in a small container.

6. Leaderboard rows showed hashed IDs (commit 3e107ba, 2026-10-08)

  • Symptom: 17 of 19 leaderboard rows had no name.
  • Found by: recomputing each account ID (SHA-256 of subject and label) for every known user and label, and matching them against the board: 9 rows were browser strategy accounts (algo-*), 2 were people's main accounts.
  • Root cause: post-trade learns a name only when an account calls one of its /account/* endpoints. Strategies trade only through the exchange, so they never did.
  • Fix: a strategy looks its P&L up once when it starts, as the simulated traders already did.
  • Lesson: derived identity (a hash) needs a place where the readable name is recorded, on every path that creates an account.

Smaller ones worth a sentence

  • Post-trade paths answered 403 while post-trade restarted, because the request fell through to the exchange; they now answer 503 post_trade_unavailable (commit e5d932b).
  • Shutdown could exceed Docker's 10 s grace period and lose the snapshot; snapshot first, Kafka last and bounded, grace period 30 s (commit e5d932b).
  • The exchange started before Kafka topics existed; it now waits for kafka-init (commit 4fc0f8f).

How to tell a bug story in an interview

Use the same five beats every time, about 90 seconds:

  1. Symptom with a number ("p99 445 ms, spikes to 3.5 s").
  2. How I found it (the tool or the trick: a 300-run loop, a Prometheus query, JFR).
  3. Root cause in one sentence.
  4. Fix, and what I tried that didn't work (ZGC made it worse).
  5. Lesson that generalises to their systems.

Best three for a full-stack Java role: 5 (GC tail: JVM depth, measurement), 2 (concurrency race), 1 (determinism and data correctness). Use 6 if they ask about a product/UX bug.

Drill: the GC investigation in depth

What is JFR and how did you use it?

Java Flight Recorder: a low-overhead profiler built into the JVM. I ran the JMH benchmark with -XX:StartFlightRecording=...,settings=profile, then jfr print --events jdk.ObjectAllocationSample and grouped allocations by class and first project frame. It showed HashMap$Node from the order index plus boxed Long keys were about a third of the matching thread's bytes.

Why did a HashMap<Long, RestingOrder> allocate so much?

Every put allocates a HashMap.Node (key, value, hash, next) and boxes the long key into a Long (outside the small cache of −128..127). get and remove box again. Replacing it with an open-addressing map over a long[] and an Object[] removes both: no nodes, no boxing. Allocation per operation fell 12–21%.

Why didn't cutting allocation change latency much?

In the full pipeline the index was a small share of all allocation; event records, client-order-id strings and price-level churn dominate. And on a laptop, OS scheduling noise is bigger than the effect. I ran A/B interleaved (after, before, after, before) because drift between runs exceeded the difference.

Why did ZGC make it worse in the container?

ZGC's pauses are tiny but it is concurrent: it needs heap headroom to keep allocating while it collects. In a 768 MiB container it used the whole 512 MiB heap, and allocation stalls (threads waiting for memory, not counted as GC pauses) raised p99 5x. A concurrent collector needs headroom.

Why was the JVM using the Serial collector?

JVM ergonomics: if the machine (container) looks like a "client-class" machine, under 2 CPUs or under ~1792 MB of memory, the JVM picks Serial GC by default instead of G1. The container had 768 MiB. Serial is stop-the-world on one thread, so every pause stops matching and journaling.

How do you measure latency without lying to yourself?

HdrHistogram for percentiles (not averages), measuring from each command's intended send time to avoid coordinated omission (if the system stalls, a closed-loop load generator stops sending and hides the stall), warm-up before measuring, interleaved A/B runs, and recording command, machine and date with every number.