[object Object]

← back to Ticket System

TK-12290: readEvents() incremental tail read instead of full 64MB reparse per call

6b94732a2303c4a6f4d7987bf4c02c41bf56a6f2 · 2026-09-25 14:46:56 -0700 · Steve Abrams

readEvents() re-read+re-parsed the entire append-only events.jsonl (64MB,
606k lines) on every call from tickets()/messages()/nextId()/nextMid()/etc,
costing ~0.6-1.4s per call on this loaded box even for a single-line append.
Now keeps a module-level cache (parsed events + last size/inode + buffered
trailing partial line): same inode + grown size -> parse only the new bytes
and concat; unchanged size -> return cached array; shrunk size or changed
inode (truncate/rotate/rewrite) -> full reparse, so derived state can never
drift from a full reparse. Benchmarked against the real 64MB store: warm
read after a small append dropped from ~1.4s to ~16ms; cold/first-call and
rotation/truncation paths are unchanged (still full reparse).

lib-readevents.test.js adds hermetic coverage: append-only growth matches a
full reparse at every step, a partial trailing line is buffered and folds in
exactly once when completed, in-place truncation (same inode) forces a full
reparse, and inode rotation (rename-over) forces a full reparse. node --test
lib.test.js lib-readevents.test.js: 37/37 green.

Verified live on a throwaway instance (spare port 19795, copy of the real
64MB store) before killing it — healthz 200, /api/tickets served correctly.
Live pm2 ticket-board was NOT restarted; see the TK-12286 restart memo.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01D7LB6rCwpA7ubJTqYzqXEX

Files touched

Diff

commit 6b94732a2303c4a6f4d7987bf4c02c41bf56a6f2
Author: Steve Abrams <steve@designerwallcoverings.com>
Date:   Fri Sep 25 14:46:56 2026 -0700

    TK-12290: readEvents() incremental tail read instead of full 64MB reparse per call
    
    readEvents() re-read+re-parsed the entire append-only events.jsonl (64MB,
    606k lines) on every call from tickets()/messages()/nextId()/nextMid()/etc,
    costing ~0.6-1.4s per call on this loaded box even for a single-line append.
    Now keeps a module-level cache (parsed events + last size/inode + buffered
    trailing partial line): same inode + grown size -> parse only the new bytes
    and concat; unchanged size -> return cached array; shrunk size or changed
    inode (truncate/rotate/rewrite) -> full reparse, so derived state can never
    drift from a full reparse. Benchmarked against the real 64MB store: warm
    read after a small append dropped from ~1.4s to ~16ms; cold/first-call and
    rotation/truncation paths are unchanged (still full reparse).
    
    lib-readevents.test.js adds hermetic coverage: append-only growth matches a
    full reparse at every step, a partial trailing line is buffered and folds in
    exactly once when completed, in-place truncation (same inode) forces a full
    reparse, and inode rotation (rename-over) forces a full reparse. node --test
    lib.test.js lib-readevents.test.js: 37/37 green.
    
    Verified live on a throwaway instance (spare port 19795, copy of the real
    64MB store) before killing it — healthz 200, /api/tickets served correctly.
    Live pm2 ticket-board was NOT restarted; see the TK-12286 restart memo.
    
    Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
    Claude-Session: https://claude.ai/code/session_01D7LB6rCwpA7ubJTqYzqXEX
---
 lib-readevents.test.js | 120 +++++++++++++++++++++++++++++++++++++++++++++++++
 lib.js                 |  53 +++++++++++++++++++++-
 2 files changed, 171 insertions(+), 2 deletions(-)

diff --git a/lib-readevents.test.js b/lib-readevents.test.js
new file mode 100644
index 00000000..cac36b71
--- /dev/null
+++ b/lib-readevents.test.js
@@ -0,0 +1,120 @@
+'use strict';
+// TK-12290: hermetic tests for lib.js's incremental-tail-read readEvents().
+// Own throwaway TICKET_DATA_DIR, set BEFORE lib.js is required (node's test runner
+// gives each test FILE its own process by default, so this module instance's
+// module-level _tail cache never collides with lib.test.js's).
+const test = require('node:test');
+const assert = require('node:assert/strict');
+const fs = require('fs');
+const os = require('os');
+const path = require('path');
+
+const TMP = fs.mkdtempSync(path.join(os.tmpdir(), 'tk-readevents-'));
+process.env.TICKET_DATA_DIR = TMP;
+
+const { append, readEvents, EVENTS } = require('./lib.js');
+
+assert.ok(EVENTS.startsWith(os.tmpdir()), 'hermetic isolation broken — EVENTS points outside tmpdir');
+
+const iso = (offsetMs = 0) => new Date(Date.now() + offsetMs).toISOString();
+
+// Independent control: parse the file exactly like the ORIGINAL (pre-TK-12290)
+// full readFileSync+split+parse implementation, so the incremental path is checked
+// against ground truth rather than against its own full-reparse branch.
+function fullParseControl() {
+  return fs.readFileSync(EVENTS, 'utf8').split('\n').filter(Boolean)
+    .map(l => { try { return JSON.parse(l); } catch { return null; } }).filter(Boolean);
+}
+
+// ── 1. append-only growth: repeated incremental tail reads match a full reparse ──
+test('append-only growth: each incremental readEvents() call matches a full reparse', () => {
+  for (let i = 0; i < 25; i++) {
+    append({ ts: iso(i), type: 'create', id: `TK-READ-${i}`, title: `growth ${i}`, project: 'readevents-test', agent: 'a' });
+    const incremental = readEvents();
+    const control = fullParseControl();
+    assert.deepEqual(incremental, control, `mismatch after append #${i}`);
+    assert.equal(incremental.length, i + 1);
+  }
+});
+
+// ── 2. a partial trailing line (no \n yet) is buffered, not lost or mis-parsed ──
+test('partial trailing line is buffered until completed, then folds in exactly once', () => {
+  const before = readEvents();
+  const beforeLen = before.length;
+
+  // Write a broken/incomplete JSON line directly, with NO trailing newline —
+  // simulates reading mid-append, before the writer's newline has landed.
+  const partialText = '{"ts":"' + iso() + '","type":"create","id":"TK-READ-PARTIAL","title":"partial';
+  fs.appendFileSync(EVENTS, partialText);
+
+  const duringPartial = readEvents();
+  assert.equal(duringPartial.length, beforeLen, 'an incomplete trailing line must not appear as an event yet');
+  assert.deepEqual(duringPartial, before, 'no existing events should be disturbed by a pending partial line');
+
+  // Complete the line (finish the JSON + newline) — this is written as a SEPARATE
+  // appendFileSync, exactly like a second read tick landing after the writer flushes.
+  fs.appendFileSync(EVENTS, ' test"}\n');
+  const after = readEvents();
+  assert.equal(after.length, beforeLen + 1, 'completed line must fold in exactly once (no duplication, no loss)');
+  assert.deepEqual(after, fullParseControl(), 'completed read must match a full reparse');
+  assert.equal(after[after.length - 1].id, 'TK-READ-PARTIAL');
+  assert.equal(after[after.length - 1].title, 'partial test');
+
+  // A further no-op read (unchanged size) must return the identical cached array,
+  // not re-read/re-parse — same length/shape at minimum (identity is an implementation detail).
+  const again = readEvents();
+  assert.deepEqual(again, after);
+});
+
+// ── 3. truncation (in-place rewrite, SAME inode, smaller size) forces a full reparse ──
+test('in-place truncation to a smaller file (same inode) forces a full reparse, never stale tail data', () => {
+  readEvents(); // prime the cache against current (larger) file
+  const statBefore = fs.statSync(EVENTS);
+
+  // Rewrite the file smaller IN PLACE (truncate+write keeps the same inode on POSIX).
+  const survivor = { ts: iso(), type: 'create', id: 'TK-READ-SURVIVOR', title: 'only one left', project: 'readevents-test', agent: 'a' };
+  fs.writeFileSync(EVENTS, JSON.stringify(survivor) + '\n');
+  const statAfter = fs.statSync(EVENTS);
+  assert.equal(statAfter.ino, statBefore.ino, 'test assumption: truncate+rewrite keeps the inode (same-inode shrink path)');
+  assert.ok(statAfter.size < statBefore.size, 'test assumption: the rewritten file is smaller');
+
+  const events = readEvents();
+  assert.equal(events.length, 1, 'must reflect the truncated file, not the stale larger cached tail');
+  assert.deepEqual(events, fullParseControl());
+  assert.equal(events[0].id, 'TK-READ-SURVIVOR');
+});
+
+// ── 4. rotation (new inode via rename-over) forces a full reparse ──
+test('rotation (file replaced with a new inode) forces a full reparse', () => {
+  readEvents(); // prime the cache against the current (post-truncation) file
+  const statBefore = fs.statSync(EVENTS);
+
+  const rotated = path.join(TMP, 'events.new.jsonl');
+  const rows = [
+    { ts: iso(), type: 'create', id: 'TK-READ-ROT-1', title: 'rotated one', project: 'readevents-test', agent: 'a' },
+    { ts: iso(1), type: 'create', id: 'TK-READ-ROT-2', title: 'rotated two', project: 'readevents-test', agent: 'a' },
+  ];
+  fs.writeFileSync(rotated, rows.map(r => JSON.stringify(r)).join('\n') + '\n');
+  fs.renameSync(rotated, EVENTS); // atomic replace — guaranteed new inode, distinct dirent target
+
+  const statAfter = fs.statSync(EVENTS);
+  assert.notEqual(statAfter.ino, statBefore.ino, 'test assumption: rename-over produces a new inode');
+
+  const events = readEvents();
+  assert.equal(events.length, 2);
+  assert.deepEqual(events, fullParseControl());
+  assert.deepEqual(events.map(e => e.id), ['TK-READ-ROT-1', 'TK-READ-ROT-2']);
+
+  // And growth resumes incrementally correctly after the rotation.
+  append({ ts: iso(2), type: 'create', id: 'TK-READ-ROT-3', title: 'rotated three', project: 'readevents-test', agent: 'a' });
+  const grown = readEvents();
+  assert.equal(grown.length, 3);
+  assert.deepEqual(grown, fullParseControl());
+});
+
+// ── 5. an unchanged file (same inode+size) returns without re-reading disk ──
+test('unchanged file: readEvents() called twice with no writes returns equal results', () => {
+  const a = readEvents();
+  const b = readEvents();
+  assert.deepEqual(a, b);
+});
diff --git a/lib.js b/lib.js
index 06bf8c56..bab7042c 100644
--- a/lib.js
+++ b/lib.js
@@ -27,9 +27,57 @@ function withLock(fn) {
   }
 }
 
+// TK-12290: incremental tail read. The full readFileSync+split+parse below cost
+// ~0.6-0.7s cold on a loaded box against a 64MB append-only log, and every one of
+// tickets()/messages()/nextMid()/nextId()/knownAgents()/thread() called readEvents()
+// fresh — so one board request paid that cost several times over. Since the file is
+// append-only in normal operation, a module-level cache of {ino, size, events,
+// partial-trailing-line} lets a request that only sees NEW bytes since the last read
+// parse just those bytes and concat onto the already-parsed array, instead of
+// re-reading and re-parsing the whole file. Any non-append change (truncate, rotate,
+// replace) is detected via inode+size and falls back to a full reparse so derived
+// state can never drift from what a full reparse would produce.
+let _tail = null; // { ino, size, events, partial }
+
+function parseLines(lines, out) {
+  for (const line of lines) {
+    if (!line) continue;
+    try { out.push(JSON.parse(line)); } catch { /* skip malformed line, same as full parse */ }
+  }
+  return out;
+}
+
+function readEventsFull(st) {
+  const text = fs.readFileSync(EVENTS, 'utf8');
+  const events = parseLines(text.split('\n'), []);
+  _tail = { ino: st.ino, size: st.size, events, partial: '' };
+  return events;
+}
+
+function readEventsTail(st) {
+  const readLen = st.size - _tail.size;
+  const buf = Buffer.alloc(readLen);
+  const fd = fs.openSync(EVENTS, 'r');
+  try { fs.readSync(fd, buf, 0, readLen, _tail.size); }
+  finally { fs.closeSync(fd); }
+  const chunk = _tail.partial + buf.toString('utf8');
+  const lines = chunk.split('\n');
+  const partial = lines.pop(); // '' when chunk ended in \n, else a real trailing partial line — buffer it
+  const events = _tail.events.concat(parseLines(lines, []));
+  _tail = { ino: st.ino, size: st.size, events, partial };
+  return events;
+}
+
 function readEvents() {
   ensure();
-  return fs.readFileSync(EVENTS, 'utf8').split('\n').filter(Boolean).map(l => { try { return JSON.parse(l); } catch { return null; } }).filter(Boolean);
+  let st;
+  try { st = fs.statSync(EVENTS); } catch { _tail = null; return []; }
+  if (_tail && st.ino === _tail.ino) {
+    if (st.size === _tail.size) return _tail.events;          // unchanged since last read
+    if (st.size > _tail.size) return readEventsTail(st);       // append-only growth — tail read
+    // st.size < _tail.size with the same inode: in-place truncate/rewrite — full reparse
+  }
+  return readEventsFull(st); // first call, rotated inode, or shrank — full reparse
 }
 
 function append(ev) { ensure(); fs.appendFileSync(EVENTS, JSON.stringify(ev) + '\n'); return ev; }
@@ -425,4 +473,5 @@ module.exports = { withLock, append, tickets, nextId, resolveId, idNum, slugify,
   IDRE, REFRE, resolveList,
   nextMid, messages, inbox, thread, resolveMid, threadParticipants, parseMentions, isBroadcast, knownAgents,
   correlationId, createTicket, ticketComment, ticketAction, ticketAssign, ticketStatus, ticketBlocker, ticketDesignate, sendDm, markMessageRead,
-  leases, activeLease, claim, renew, release, reapExpiredLeases, shortTk, LEASE_MS };
+  leases, activeLease, claim, renew, release, reapExpiredLeases, shortTk, LEASE_MS,
+  readEvents }; // TK-12290: exported for the incremental-tail-read tests (lib-readevents.test.js)

← 39f8e674 auto-data-snapshot: 2026-09-25T14:28:14 (2 data files) — dat  ·  back to Ticket System  ·  auto-data-snapshot: 2026-09-25T15:32:10 (1 data files) — tmp e300b94c →