Three hours of memory, twelve hours of gap

Scry is a whole-disk file search for Windows. It keeps an index of every file and folder on the machine, about five million entries on my laptop, and answers a search in about a millisecond. That only works if the index is right. A search tool that shows you files that no longer exist is worse than no search tool.

So when Scry restarts, the first thing it does is catch up on whatever changed while it wasn’t looking. Here’s what that looked like in the log on 9 October:

resynced (changes made while nothing watched): relisted 697 folders changed since 1791493252 (0 from the change journal, the rest by checking C:\) in 16.62s (15.49s finding them)

Sixteen seconds of stale search results. And the part that matters: 0 from the change journal. That number was supposed to be the whole point.

Catching up after a restart

While Scry runs, it watches every drive root with ReadDirectoryChangesW, and changes show up in the index within a fraction of a second. But ReadDirectoryChangesW only reports what happens while you’re watching. There’s no “what did I miss?”

Scry is a port of fsearch, which runs on macOS. There, the file system’s event stream can replay history from a point you give it, so catching up after a restart was a rare path. On Windows there’s no replay. Every restart takes the catch-up path.

Windows does have something better than replay, though: the NTFS change journal. Every change on the volume gets a record. Read the journal from where you left off and you know exactly which folders to look at again.

1. Scry restarts and loads its index from disk: about 5 million entries.
2. It reads its sync point: the second up to which every change is known to be applied.
3. Does the NTFS change journal reach back that far?

yes

1. Read the journal from the sync point on. FSCTL_READ_UNPRIVILEGED_USN_JOURNAL needs no admin rights.
2. Without admin, names come back blank. But every record keeps the id of the folder it happened in.
3. Open just those folders by id and list them again.

69 folders · 41 ms

no

1. Check the timestamp of every folder in the index, on 12 threads, to find what changed.
2. Until that's done, search results can be stale.

15–30 s

Note the question in the middle. The journal is a fixed-size buffer: when it fills up, the oldest records fall off the end. If the sync point is older than the oldest record, the journal can’t vouch for the gap, and Scry falls back to checking every folder. Slow, but correct.

Correct is what made this hard to see. Nothing crashed. Search results were right, eventually. The only symptom was a number in a log file.

The obvious suspect

On a busy system drive, the journal fills fast. So the obvious theory was that C:’s journal was too small and Scry was asking it for more history than it had.

The first fix wasn’t a fix. It was a better log line: when the journal can’t cover the gap, say how far back it goes and how far back we needed.

C: the change journal reaches back 3h 11m only, not the 6h 28m needed; checking its folders instead

There it is. Three hours of memory. Theory confirmed, case closed?

Look at the second number. 6h 28m needed. Scry had been running right up to that restart. It was fully up to date a minute before it stopped. Why did it need six and a half hours of history?

The actual bug

Scry tracks a sync point: the second up to which every change is known to be applied. In memory it moves forward constantly, after every batch of changes.

On disk, it only moved when the whole index was saved. A full save writes a file of about 200 MB, so it doesn’t happen often: every 12 hours, or after 50,000 changes. On a restart, Scry loaded the sync point from the last full save. Not from a minute ago. From whenever that was.

Think of a security camera that keeps three hours of footage, and a guard who writes “all quiet as of” in the logbook twice a day. Ask him at 4 p.m. what happened since the last entry and he’ll point at a morning the tape no longer has.

The journal wasn’t too short. The bookmark was too old.

Before: saved with the full indexAfter: checkpoint every 5 min

Hours since the last full save of the index

6.5 h

Hours Scry was switched off before the restart

0 h

Needs 6h 32m of history; the journal reaches back ~3 h. Check every folder instead: 15–33 s in the logs.

One more detail: earlier that same day, the README’s speed table had picked up a new line. “15-30 s when the last save is hours old.” The bug was documented as a performance characteristic. It lasted four hours and twenty minutes.

The fix

Write the sync point down more often, and write down what it depends on.

Scry now keeps a checkpoint next to the index: every change applied since the last full save, plus the sync point. It’s small, 1 to 4 MB against the index’s 200, so it can be written often. Every five minutes, if anything moved:

} else if synced != checkpointed && last_checkpoint.elapsed() > CHECKPOINT_EVERY {
    shared.checkpoint();
    (last_checkpoint, checkpointed) = (Instant::now(), synced);
}

It’s also written when Scry is told to stop, quit or restart, and when Windows signs out. It goes to a temporary file first and is renamed into place, so a crash mid-write leaves the old one intact. On start, Scry loads the index, applies the checkpoint only if it was made against that exact index, and asks the journal for the rest. A full save makes the checkpoint obsolete and deletes it.

The first restart with it:

resumed from the checkpoint: 7347 changes since the save, in sync as of 1791922811
relisted 69 folders changed since 1791922691 (69 from the change journal) in 40.57ms (23.38ms finding them)

69 from the change journal. The commit went in 35 seconds after that line was written, and shipped in v0.2.0 the next morning.

What it still can’t do

The checkpoint only helps if Scry was running until shortly before the restart. On 14 October it had been off for about fourteen hours:

C: the change journal reaches back 4h 57m only, not the 14h 23m needed; checking its folders instead

Thirty-three seconds. No checkpoint can recover changes that happened while nothing was watching and that the journal has already recycled. In that case Scry takes the slow, correct path, and the log says exactly why.

Three takeaways

A port inherits assumptions nobody wrote down. On macOS, catching up was the rare path, so nobody worried about the sync point being twelve hours stale. On Windows, the rare path became the every-time path. The code didn’t change. The world around it did.

A fallback that works hides bugs. Every one of those slow restarts gave correct results. Nothing failed. If the log hadn’t printed “0 from the change journal”, this could have gone unnoticed for a long time.

Make the log say why. “Checking its folders instead” told us that it fell back. “Reaches back 3h 11m only, not the 6h 28m needed” told us why, and the second number gave the real bug away. Once the log could explain itself, the fix was measured within four minutes.

A thought to add?

A good question, another perspective, or something this made you think about. There’s room for it here.

Loading the conversation…

Display name

Use a name or an alias. No email address needed.

Your comment

Leave this empty

Comments are reviewed before appearing. Your display name and message will be public once approved. Privacy

Submit comment