Append Log Persistence

A snapshot writes the store’s state at one instant. Nothing that happens between two instants is ever recorded, which is why the data loss window never reaches zero no matter how short the interval gets. For the library’s loan counters, in the worst case that means thousands of loan records have to be collected back by hand.

This lesson takes up the second form: recording the write, not the state. Every mutating command is appended to the end of a file in the order it was applied. Recovery replays these commands over an empty store. Because nothing happens beyond appending to the end of the file, the write path is cheap; its cost shows up in two other places: the file grows without bound, and the gap between “appended” and “on disk” becomes a setting.

Recording the Write Itself

The record format carries the store’s command as-is: command letter, key, value. The load is the same as the previous lesson — sixty thousand loan writes spread across twenty thousand members, with the same seed — so the numbers from the two formats can be compared directly.

// log.mjs — command log record and the same loan load
export const record = (k, v) => `W\t${k}\t${v}\n`;   // W: write command

export function generator(seed) {
  let a = seed >>> 0;
  return () => {
    a = (a + 0x6d2b79f5) >>> 0;
    let t = a;
    t = Math.imul(t ^ (t >>> 15), t | 1);
    t ^= t + Math.imul(t ^ (t >>> 7), t | 61);
    return ((t ^ (t >>> 14)) >>> 0) / 4294967296;
  };
}

export function generateLoad(count, seed, memberCount = 20000) {
  const r = generator(seed), list = [];
  for (let i = 0; i < count; i++) {
    const m = Math.floor(r() * memberCount);
    list.push([
      'loan:m' + String(m).padStart(5, '0'),
      `branch=${1 + (m % 8)};day=${[7, 14, 28][i % 3]};renewal=${i % 4}`,
    ]);
  }
  return list;
}

The Log’s Growth and the Rewrite

The run below writes the load to disk for real and, every twenty thousand writes, stops to place two sizes side by side: the log file up to that point, and a snapshot of the same state.

// growth.mjs — the log's growth and the space the rewrite recovers
import { appendFileSync, writeFileSync, statSync, rmSync } from 'node:fs';
import { record, generateLoad } from './log.mjs';

const LOAD = generateLoad(60000, 20260731);
rmSync('loan.log', { force: true });
const state = new Map();
let buffer = '', logBytes = 0;
console.log('write   log bytes  keys  snapshot bytes  log/snapshot');
for (let i = 0; i < LOAD.length; i++) {
  const [k, v] = LOAD[i];
  buffer += record(k, v);                       // every write is appended to the end of the log
  state.set(k, v);
  if ((i + 1) % 20000 === 0) {
    appendFileSync('loan.log', buffer);
    logBytes += Buffer.byteLength(buffer);
    buffer = '';
    let g = 0;
    for (const [sk, sv] of state) g += Buffer.byteLength(sk) + Buffer.byteLength(sv) + 2;
    console.log(String(i + 1).padStart(5), String(logBytes).padStart(12),
      String(state.size).padStart(8), String(g).padStart(13),
      (logBytes / g).toFixed(2).padStart(15));
  }
}
console.log('file:', statSync('loan.log').size, 'bytes,', LOAD.length, 'records,',
  (statSync('loan.log').size / LOAD.length).toFixed(1), 'bytes/write');

let rewritten = '';                                  // rewrite: only the surviving keys
for (const [k, v] of state) rewritten += record(k, v);
writeFileSync('loan-rewritten.log', rewritten);
const before = statSync('loan.log').size, after = statSync('loan-rewritten.log').size;
console.log('rewrite:', state.size, 'records,', after, 'bytes |',
  'saved', before - after, 'bytes (%' + (((before - after) / before) * 100).toFixed(1) + ')');

write   log bytes  keys  snapshot bytes  log/snapshot
20000       793333    12717        479015            1.66
40000      1586666    17330        652842            2.43
60000      2380000    19040        717260            3.32
file: 2380000 bytes, 60000 records, 39.7 bytes/write
rewrite: 19040 records, 755340 bytes | saved 1624660 bytes (%68.3)

The cost per write is constant: 39.7 bytes. The log file grows linearly with the write count and does not care what it is writing; the tenth update to the same member’s loan record still adds a full record to the file. A snapshot, by contrast, grows with the key count and carries no history of the values it overwrote. The last column gives the gap between the two: at twenty thousand writes, the log is 1.66 times the snapshot; at sixty thousand, 3.32 times. As long as the library keeps operating, the ratio keeps growing, because the numerator never stops while the denominator saturates at twenty thousand members.

This growth is the direct consequence of an append log, and it has exactly one remedy: the rewrite. The store’s current state is scanned and a single record is produced for each surviving key; the old file is replaced with this one. In the measurement, 60,000 records shrink to 19,040, the file drops from 2,380,000 bytes to 755,340 bytes, a saving of 68.3 percent.

Two details are worth reading here. First, the rewritten log (755,340 bytes) is exactly 38,080 bytes larger than the snapshot of the same state (717,260 bytes); that is the two-byte command prefix attached to each of the 19,040 records. Apart from that formatting difference, a rewritten log is a snapshot. Second, and more important: the rewrite also has to scan every entry. In other words, the snapshot cost from the previous lesson — pausing or copying — exists on this path too, just less often. An append log does not eliminate taking a snapshot; it ties the question of when to the file’s size.

The Fsync Policy

A record can be considered “written” at three separate points. It first lands in the application’s own buffer. Once that buffer is flushed, it moves into the operating system’s buffer; the process can crash past this point and the record still survives, because the operating system now holds it. Guaranteeing that the record has reached persistent storage is a separate request: only records past that step survive when the machine loses power.

The policy chooses among these three stops. The run below writes the same fifteen hundred records in three modes and prints quantities independent of the run: write calls, sync count, file size. Duration is also measured, but not printed as a number on its own — only as a ranking, since duration depends on the type of disk and the machine’s load.

PM3. At the library’s busiest hour, the store receives 3,000 writes per second. PM4. The application buffer is 65,536 bytes, and the operating system flushes its own buffer to persistent storage every five seconds.

// sync.mjs — cost and data loss window of three fsync policies
import { openSync, writeSync, fsyncSync, closeSync, statSync, rmSync } from 'node:fs';
import { record, generateLoad } from './log.mjs';

const N = 1500, RATE = 3000, BUFFER = 65536, WRITEBACK = 5;   // PM3, PM4
const LOAD = generateLoad(N, 20260731);

function run(path, period, buffered) {
  rmSync(path, { force: true });
  const fd = openSync(path, 'w');
  let calls = 0, syncs = 0, buf = '', bufBytes = 0;
  const start = process.hrtime.bigint();
  for (let i = 0; i < N; i++) {
    const line = record(LOAD[i][0], LOAD[i][1]);
    if (buffered) {                              // written once the application buffer fills, no syncing
      buf += line; bufBytes += Buffer.byteLength(line);
      if (bufBytes >= BUFFER) { writeSync(fd, buf); calls++; buf = ''; bufBytes = 0; }
    } else {
      writeSync(fd, line); calls++;
      if ((i + 1) % period === 0) { fsyncSync(fd); syncs++; }
    }
  }
  if (buf) { writeSync(fd, buf); calls++; }
  if (!buffered && N % period !== 0) { fsyncSync(fd); syncs++; }
  const duration = Number(process.hrtime.bigint() - start);
  closeSync(fd);
  return { calls, syncs, bytes: statSync(path).size, duration };
}

const modes = [
  ['every write', run('a.log', 1, false)],
  ['once per second', run('b.log', RATE, false)],
  ['leave to the OS', run('c.log', 0, true)],
];
console.log(`measurement: ${N} records, same content, three modes`);
console.log('mode                     write calls  syncs  file bytes');
for (const [label, s] of modes)
  console.log(label.padEnd(24), String(s.calls).padStart(13), String(s.syncs).padStart(12),
    String(s.bytes).padStart(12));
console.log('duration ranking (slowest to fastest):',
  [...modes].sort((x, y) => y[1].duration - x[1].duration).map(([a]) => a).join(', '));

const bytesPerRecord = modes[0][1].bytes / N;              // bytes per record
const TOTAL = 60000;
console.log(`\n${TOTAL} writes of load, ${RATE} writes per second, a ${BUFFER}-byte buffer,`,
  `${WRITEBACK}-second writeback`);
console.log('mode                     syncs  worst loss  average loss');
const row = (label, syncs, worst) => console.log(label.padEnd(24), String(syncs).padStart(11),
  String(worst).padStart(14), String(Math.round(worst / 2)).padStart(15));
row('every write', TOTAL, 0);
row('once per second', Math.ceil(TOTAL / RATE), RATE);
row('leave to the OS', 0, Math.floor(BUFFER / bytesPerRecord) + WRITEBACK * RATE);

measurement: 1500 records, same content, three modes
mode                     write calls  syncs  file bytes
every write                       1500         1500        59500
once per second                   1500            1        59500
leave to the OS                      1            0        59500
duration ranking (slowest to fastest): every write, once per second, leave to the OS

60000 writes of load, 3000 writes per second, a 65536-byte buffer, 5-second writeback
mode                     syncs  worst loss  average loss
every write                    60000              0               0
once per second                   20           3000            1500
leave to the OS                    0          16652            8326

All three modes produce the same file: 59,500 bytes, identical content. What differs is only when those bytes take their place, and under what guarantee.

Every write means sixty thousand separate syncs over a sixty-thousand-write load, and it drives the data loss window to zero. On the machine this measurement ran on, each sync cost roughly 3.8 milliseconds; the number changes with the disk and the load, which is why a ranking was printed instead of a duration. What stays fixed is the sync count, and the table shows a gap of four orders of magnitude among the three modes. A zero data loss window has one more condition: the sync must finish before the response reaches the client. If a “loan accepted” reply goes out before the record reaches disk, the window reopens.

Once per second brings the sync count for the same load down to twenty — three thousand times less waiting on the write path. In exchange, the worst case loses one second’s worth of work, that is, 3,000 loan writes. The average loss is half of that.

Leaving it to the operating system removes syncing entirely and also lowers the number of write calls: fifteen hundred records were written with a single call, because all of them fit in the 65,536-byte buffer. This is the cheapest mode, and it also carries the worst loss: 16,652 writes. Where that number comes from matters, because two separate delays add up — the 1,652 records still sitting in the application buffer, and up to five seconds’ worth of work already handed to the operating system but not yet on persistent storage.

What the Policy Buys

The three policies are three answers to the same question: is the cost of losing one loan write larger than the cost of pushing that write to disk? For the library’s session records it is not; a librarian who loses a session just reopens it. For loan counters it is on the margin. For late-fee records it is large, because a lost record maps to money and cannot be recovered.

The append log’s real advantage over a snapshot is that it makes the data loss window adjustable per write. Its cost is the file’s size: 3.32 times the space for the same state, and the regular rewrite needed to reclaim that space. Where the two formats cover each other’s gaps is visible from here, but which one to choose and when has not yet been brought into a single table.

Summary

• An append log records the command, not the state; in the measurement it held 39.7 bytes per write, and the file grew linearly with the write count.
• The log grows with the write count, the snapshot with the key count: for the same data, the ratio was 1.66 at 20,000 writes and 3.32 at 60,000.
• The rewrite brought 60,000 records down to 19,040 and shrank the file by 68.3 percent; the resulting file is a snapshot apart from its two-byte command prefix, and carries the same full scan cost.
• The fsync policy sets the data loss window: every write gives 0 lost writes and 60,000 syncs; once per second gives 3,000 lost writes and 20 syncs; leaving it to the operating system gives 16,652 lost writes and no syncing at all.
• All three modes produced the same 59,500-byte file; the difference between them is not in the content but in the guarantee about which stop the record has reached.

Next Step

Both persistence forms have now been measured, and each has shown its own gap: a snapshot cannot close the data loss window, an append log cannot hold its size down. The next lesson brings the choice together into a single table. Three measures are compared: the recovery step from the process restarting to being ready to serve, the data loss window, and the steady-state cost. A scheme that uses both paths together also enters the same table — a snapshot base with the records since the last snapshot layered on top — and the numbers show why that scheme shortens recovery while also keeping the data loss window narrow.