rigel is the Windows box that carries our fast-chat tier, and it is also the machine we sit at. In late October it started to stutter. When our agents were busy, Task Manager showed the C: drive pinned at 100 percent active. The desktop would micro-stutter, then sometimes hang for 5 to 10 seconds, then catch up very fast. Diablo IV, which we play on the same machine, would often crash right after. When the agents were quiet, the drive looked fine.
The obvious reading was read starvation. Many agents searching a large tree, one NVMe drive, a queue that never empties. The obvious fix was a read cache, and we started pricing one.
The theory we did not buy
Before spending anything we ran a read-only investigation: six lenses on the problem, a synthesis, then three adversarial reviews of the synthesis. The first thing it did was measure the thing we assumed.
C: read latency under agent load stayed at a 95th percentile of 0.5 ms. That is not a starved drive. The Windows standby list already held about 25.8 GB of RAM acting as a read cache, with 2.3 MB on the free list, so Windows was already caching reads in memory. A block cache with a RAM tier would mostly duplicate that. A defer-write mode would add data-loss risk, and it still could not shorten a flush that the volume itself was waiting on.
So the cache was out. Something else was holding C:.
What was holding the volume
The event log had the clue. Ntfs/Operational Event 157 reported VSSVC.exe holding an exclusive resource named VCB for more than 30 seconds, eight times in two days. A second log, VolumeSnapshot-Driver Event 126, fired every 5 minutes and 10 seconds, around the clock.
VSSVC is the volume shadow copy service. While it commits a snapshot it flushes the volume and holds C:’s volume lock, sometimes for 30 to 60 seconds, and every writer on C: waits. The game lives on D:, but its shader caches, its documents folder, the launcher files and the pagefile all sit on C:.
Something was creating a snapshot every five minutes. We found it in a scheduled task of our own: a small poller that reads our subscription usage so the dashboard can show it. On each 300 second poll it needed a copy of a SQLite file that the desktop app keeps open with no sharing allowed. The poller’s fallback for a locked file was to ask Windows for a shadow copy of the whole C: volume and read the file from the snapshot.
That fallback was meant for the rare case. Because the app held the file open the whole time, it ran on every poll. That works out to about 288 snapshots a day, and the task had been doing it for more than 14 days.
The proof, and what it does not prove
We had game logs to line up against the snapshot times, which is the part we trust most:
- All three abrupt game exits fell 3 to 16 seconds before a shadow mount.
- Of 22 freezes of 5 seconds or more, 12 ended 1 to 9 seconds before a mount. Chance would put about 0.7 there.
- The worst freezes matched the lock holds to the second: a 60.4 second freeze against a 59.9 second hold, and 35.0 against 36.0.
- Snapshot attempts that took 30 seconds or more grew from about 0.6 a day in August to 12 to 16 a day on 21 and 22 October.
The drive itself made it worse. C: is a DRAM-less QLC drive that was 68 percent full, which makes a flush slower than it needs to be. We are calling that an amplifier, not the cause.
Agent reads were real but secondary. They count as waste, not as the freeze. One of our own investigators ran the only full C: saturation we saw during the whole study, an unbounded 12 GB scan at 23:58. Nothing in the data shows normal agents doing that.
The fix, in order of how reversible it was
First we stopped the scheduled task. We stopped it rather than disabling it, because a disabled root task makes our drift checker page the alerts channel. The last snapshot event was at 01:02. In the next 37 minutes there were none, and no Event 157, with the game running the whole time.
Then the code fix. The poller now keeps the decrypted cookies in memory per account and only re-reads after the server rejects them, never more than once an hour. That takes about 288 snapshots a day down to roughly one per account each time the poller starts. After deploy it took two reads at startup and none on the next poll, which recorded both accounts.
We also found a second source of waste while we were in there. A legacy loop in our core service was re-parsing about 16 GB of transcripts every 6.5 minutes for a dashboard view that nothing used: zero of 12,440 logged requests. We gated it off. The worker went from 531 GB an hour, measured mid-cycle, to 0.26 GB an hour over a 60 second window.
What we do not know yet
We have not closed the loop. Our baseline is 1.37 game freezes of 5 seconds or more per hour of play over 21.1 hours. The comparison against the next few play sessions has not been run, so we cannot yet say the rate fell, only that the mechanism is gone and the snapshots stopped. The work item stays open until that number is in.
Lessons
- Measure the resource before you price the fix. Half an hour with latency counters and the memory counters ruled out the cache we were about to evaluate.
- A fallback path that is cheap to write can be expensive to run. This one was safe at one call and a hazard at 288 a day.
- Line up the symptom log with the suspect’s own clock. Twelve freezes ending just before a mount, against a chance figure of 0.7, did more than any amount of reasoning about disks.
- When you stop a task to test a theory, stop it in the way that does not trigger the rest of your monitoring.