Your Background Job Is in the Hot Path: The WAL Checkpoint

This is the first fix in the Campfire series. The C# port read pages at two to three times the speed of Rails, but it posted messages at a fifth of it. Every number in this post was measured during development, one fix at a time, on an Intel i9-11900K running Linux, with the app pinned to four CPUs. They aren’t the final benchmark.

The symptom: a flat line

Posting a message ran at 50 requests a second on the shared benchmark harness. Rails, on the same machine, posted 249. The C# number didn’t wobble from run to run. It sat at 50 with a p99 of 329 ms.

A number that steady, with 16 clients pushing, is a clue in itself. It usually means something handles requests one at a time and each one takes the same fixed time. In Campfire that something was easy to name: SQLite allows one writer, so the port has one writer thread with one connection, and every post goes through it. The Rust and Go ports use the same design and post thousands of messages a second, so the design wasn’t the problem. Something on that writer thread was slow.

What the profiler showed

The profiler attached to the running container while the load generator posted messages. On the writer thread, 65% of the samples were in one place: PRAGMA wal_checkpoint(PASSIVE).

A bit of SQLite background. In WAL mode, a commit appends pages to the -wal file instead of rewriting the database. A checkpoint copies those pages back into the database file, and once readers are done with the old pages, the next writer starts the WAL again from the top. Campfire’s Rails app turns SQLite’s automatic checkpoint off on its connections and runs checkpoints from a background thread instead.

That background checkpoint has a weakness. Under a steady stream of commits, its PASSIVE checkpoint never catches up between two of them, so the WAL never restarts and the file keeps growing. The C# port added a fallback for that case: after each commit, the writer looked at the size of the -wal file, and if it was over 4 MB, it ran a checkpoint itself. 4 MB is 1,000 pages of 4 KB, SQLite’s default auto-checkpoint size, so the intent was to do what SQLite would have done.

The bug was in what it measured. SQLite never shrinks the -wal file after a checkpoint. It reuses the file from the start and only truncates it when it’s larger than journal_size_limit, which is 64 MB in this app. So once the file had grown past 4 MB a single time, it stayed past 4 MB, and the check was true after every commit from then on. Every post paid for a checkpoint on the writer thread, including its fsyncs, and every other post waited behind it.

The lesson: check that your trigger can turn off

The checkpoint was background work: housekeeping, meant to run now and then. It ended up in the hot path because its trigger was a value that only ever went up.

The same shape turns up in other places:

  • “Compact when the file is over N MB”, where compaction doesn’t shrink the file.
  • “Flush when the buffer’s capacity passes N”, where capacity never goes back down.
  • “Rebuild the index when the table has more than N rows”, which is true forever once it’s true once.
  • “Warn when memory passes N”, where the process never returns memory to the OS.

Each one is a job meant to run rarely that runs every time once the threshold is crossed, and it looks fine in a short test because the threshold is never reached. You find it under sustained load, or in production a week later.

So for each job like this, ask whether its condition is false again after it runs. If it isn’t, trigger on something the job resets.

The fix

SQLite already counts the right thing. Its auto-checkpoint counts the frames written to the WAL since the last checkpoint, which drops back to zero when the WAL restarts. So the fix was to turn it back on, on the writer connection only:

public static void Enable(SqliteSession writer)
{
    ArgumentNullException.ThrowIfNull(writer);
    writer.Execute($"PRAGMA wal_autocheckpoint = {Pages}"); // 1,000, SQLite's default
}

The readers and the background checkpoint keep the app’s setting of 0, as in Rails. The code that checked the file size after every commit is gone. Now SQLite checkpoints when 1,000 pages are waiting, which is what the fallback had meant to do all along.

This is the one place the C# port behaves differently from Rails on purpose, so it’s listed under “Known differences” in the README, with the test that bounds the WAL’s size. Jose Luis Chavez del Cid (@jlchavez) reached the same diagnosis on his own in the notes to his pull request and suggested the same fix.

The result

On the harness, measured during development with this one change:

  Before After
Post a message (req/s) 50.7 1,449
p99 latency 329 ms 33 ms
C# / Rails 0.2× 5.9×

Posting got 28 times faster. The read pages didn’t change beyond run-to-run noise, which makes sense, since the fix doesn’t touch the read path. Under sustained posting the WAL peaked at 6.6 MB, inside the 8 MB limit the WAL test enforces.

Check your own app

  • Find every job that runs “when X passes N” and ask whether X goes back down after the job runs.
  • Look for work that runs after every write. A loop like “commit, then check something” is easy to miss when the check is usually false.
  • If a write endpoint’s throughput is flat as you add clients, profile the thread that serializes the writes, not the request handlers.
  • If you use SQLite in WAL mode with wal_autocheckpoint = 0, know who checkpoints and what triggers it.

Try it in LINQPad

This script puts the same mistake next to the fix. It grows a WAL past 4 MB, checkpoints it to show the file stays the same size, and then times 1,000 small commits both ways. Add the Microsoft.Data.Sqlite NuGet package to the query (F4).

var path = Path.Combine(Path.GetTempPath(), "wal-demo.sqlite3");
SqliteConnection.ClearAllPools();
foreach (var file in new[] { path, path + "-wal", path + "-shm" }) File.Delete(file);

using var db = new SqliteConnection($"Data Source={path};Pooling=False");
db.Open();
Exec("PRAGMA journal_mode = WAL");
Exec("PRAGMA synchronous = NORMAL");   // commits don't fsync in WAL mode; checkpoints do
Exec("PRAGMA wal_autocheckpoint = 0"); // checkpoints are our job, as in the app
Exec("CREATE TABLE messages (id INTEGER PRIMARY KEY, body TEXT)");

// Grow the WAL past 4 MB, checkpoint it, and look at the file.
var body = new string('x', 2000);
for (var i = 0; i < 3000; i++) Exec($"INSERT INTO messages (body) VALUES ('{body}')");
var before = WalBytes();
Exec("PRAGMA wal_checkpoint(PASSIVE)");
new { BeforeCheckpoint = before, AfterCheckpoint = WalBytes() }.Dump("WAL file size in bytes");

// The old rule: checkpoint after any commit that leaves the file over 4 MB.
var bySize = Post(1000, () => { if (WalBytes() > 4 * 1024 * 1024) Exec("PRAGMA wal_checkpoint(PASSIVE)"); });

// The fix: let SQLite count frames and checkpoint every 1,000 pages.
Exec("PRAGMA wal_autocheckpoint = 1000");
var byFrames = Post(1000, () => { });

new { BySize = bySize, ByFrames = byFrames }.Dump("1,000 small commits");

void Exec(string sql)
{
    using var command = db.CreateCommand();
    command.CommandText = sql;
    command.ExecuteNonQuery();
}

long WalBytes() => new FileInfo(path + "-wal").Length;

TimeSpan Post(int count, Action afterCommit)
{
    var clock = Stopwatch.StartNew();
    for (var i = 0; i < count; i++)
    {
        Exec("INSERT INTO messages (body) VALUES ('hello')");
        afterCommit();
    }
    return clock.Elapsed;
}

On my Windows machine the file was 24.8 MB both before and after the checkpoint, and the 1,000 commits took 6 seconds with the size check against 26 milliseconds with SQLite counting frames. Your disk will give different numbers, but the gap will be there.

The next post is about the biggest change to the read numbers, and it wasn’t in the C# code at all.

csharp dotnet performance sqlite wal checkpoint profiling linqpad