Skip to content

fix(usage): stop dropping requests that share a millisecond - #3544

Open
ntdat812 wants to merge 1 commit into
decolua:masterfrom
ntdat812:fix/usage-row-dedupe-drops-rows
Open

ntdat812 wants to merge 1 commit into
decolua:masterfrom
ntdat812:fix/usage-row-dedupe-drops-rows

Conversation

@ntdat812

Copy link
Copy Markdown
Contributor

Problem

tests/unit/db-concurrent.test.js has been failing on master:

FAIL  DB Concurrency — atomic safety > 100 parallel saveRequestUsage → no count loss
      AssertionError: expected 2 to be 100
FAIL  DB Concurrency — atomic safety > mixed concurrent: usage + details + connections + aliases
      AssertionError: expected 37 to be 50
FAIL  DB Concurrency — atomic safety > daily summary aggregates correctly under parallel writes
      AssertionError: expected 1 to be 50

It is not a transaction race — the driver is native better-sqlite3 and the comment above the transaction is right that a sync driver cannot yield mid-transaction. It is the dedupe query at the top of it:

const existing = db.get(
  `SELECT id, endpoint FROM usageHistory
   WHERE timestamp = ? AND ...provider/model/connectionId/apiKey...
     AND promptTokens = ? AND completionTokens = ?
   ORDER BY id DESC LIMIT 1`, [...]);

if (existing) {
  if (!existing.endpoint && entry.endpoint) {
    db.run(`UPDATE usageHistory SET endpoint = ? WHERE id = ?`, ...);
  }
  return;          // ← every other case: the row is silently dropped
}

entry.timestamp is an ISO 8601 string, so timestamp = ? is only millisecond-precise. Two genuinely different requests to the same model on the same connection that return the same prompt/completion counts within the same millisecond match this predicate, and the second one is thrown away — along with its totalRequestsLifetime increment and its usageDaily aggregation.

Every production write reaches this through saveUsageStats, which stamps timestamp: new Date().toISOString() at save time, so nothing upstream keeps them apart.

Measured directly, 100 concurrent saveRequestUsage calls on a fresh DB:

timestamps rows kept
distinct (base + i ms) 100 / 100
identical 1 / 100

The repo's own test sees 2, 14 or 1 depending on where the millisecond boundary lands mid-loop, which is why the numbers move between runs.

Fix

The only thing that branch ever did was back-fill an endpoint onto a row that was written without one. Everything else was a silent drop. So match only the rows that case is about:

const backfill = entry.endpoint
  ? db.get(`SELECT id FROM usageHistory WHERE ... AND COALESCE(endpoint, '') = '' ORDER BY id DESC LIMIT 1`, [...])
  : null;

if (backfill) {
  db.run(`UPDATE usageHistory SET endpoint = ? WHERE id = ?`, [entry.endpoint, backfill.id]);
  return;
}
  • endpoint-less row, then the same request again carrying an endpoint → still completed in place, one row (unchanged)
  • two real requests sharing a millisecond → both stored (was: one)
  • two endpoint-less requests sharing a millisecond → both stored (was: one)

What this trades away

If some path really does save the same request twice with an endpoint both times, it is now counted twice. That path was already only collapsed when both saves landed in the same millisecond — one millisecond later the old code double-counted too — so this makes the behaviour consistent rather than timing-dependent. I could not find such a path: each of streamingHandler, nonStreamingHandler and sseToJsonHandler calls saveUsageStats once per request on mutually exclusive branches, and no test covers a double save. If one exists, the durable fix is a per-request id in the dedupe key rather than a value tuple — happy to do that instead if you can point me at it.

Verification

tests/unit/usage-row-dedupe.test.js, 4 tests against a real temp-dir SQLite: requests sharing a millisecond survive (with and without an endpoint), the endpoint back-fill still collapses to one row, and a different model in the same millisecond is not folded into an endpoint-less row.

Restoring the wide match:

FAIL  unit/db-concurrent.test.js > 100 parallel saveRequestUsage → no count loss
FAIL  unit/db-concurrent.test.js > mixed concurrent: usage + details + connections + aliases
FAIL  unit/db-concurrent.test.js > daily summary aggregates correctly under parallel writes
FAIL  unit/usage-row-dedupe.test.js > keeps every request that shares a millisecond with another
FAIL  unit/usage-row-dedupe.test.js > keeps them when they carry no endpoint either
Tests  5 failed | 7 passed (12)

Full offline suite (vitest run unit auth translator, CI=true, excluding real/), same command on both sides:

tests failed
origin/master (699edac) 1910 95
this branch 1914 92

The three that flipped to passing are exactly the db-concurrent ones above — comm on the sorted full test names shows nothing added. eslint clean.

(db-concurrent.test.js also reports a suite-level EBUSY ... unlink data.sqlite during afterAll on Windows, because the SQLite handle is still open when the temp dir is removed. That is pre-existing, platform-specific and unrelated; I left it alone.)

saveRequestUsage treated an existing usageHistory row with the same timestamp,
provider, model, connection, apiKey and token counts as a repeat of the request
being saved, and returned without inserting. The only work that branch actually
did was back-fill a missing endpoint; everything else it swallowed.

timestamp is an ISO string, so the match is only millisecond-precise. Two real
requests to the same model on the same connection returning the same token
counts in the same millisecond — ordinary under parallel load — collapsed into
one row, taking their totalRequestsLifetime increments with them. 100 concurrent
saves left 1.

Limit the match to rows that are still missing an endpoint, which is the case
the branch was written for.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant