diff --git a/.github/workflows/worker-exit.yml b/.github/workflows/worker-exit.yml index c9a73e0e..770b788e 100644 --- a/.github/workflows/worker-exit.yml +++ b/.github/workflows/worker-exit.yml @@ -53,6 +53,12 @@ jobs: # the mechanism on this OS and requires one copy to be clean; the last # step runs the search worker's test file in a loop with coverage on, as # the test job does, and requires every run to pass. + # + # Iris's own workers start with no --import, as an installed server's do. + # A thread inherits its process's --import, and on Node 24 a thread that + # inherited --import tsx can crash the process as it ends, in Node's own + # teardown of the thread (nodejs/node#65778; #804 has the measurements), + # so iris-workers.ts registers tsx on its main thread only. worker-exit: name: worker exit (${{ matrix.os }}, Node ${{ matrix.node-version }}) runs-on: ${{ matrix.os }} diff --git a/CHANGELOG.md b/CHANGELOG.md index 630be85f..08d75d4d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -275,7 +275,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - The checkpoint thread stays held from the start of `close()` until it has ended. The answer to a checkpoint in flight used to release it again. If the thread then outlasted `close()`'s timeout, a short-lived process (`iris-eval ingest`, say) could exit with code 13 while `close()` still waited. The worker-exit CI job showed that release when ending the thread directly, in 1 process in 10. - **A search's page of trace ids, and the start's check for evaluations with no stored risk estimate, keep their plans when the file has statistics (#742).** Iris never writes statistics, but `ANALYZE` run by hand does, and under them SQLite read the search index's whole trace_id index to find a page's ids, and every evaluation to find the ones without a risk estimate, at every start. The page's ids are now looked up one doc id at a time in a fixed join, in one statement for any number of matches (100,000 in 80 ms at 100,000 traces, against 92 ms in chunks of 1,000), and the fill names its index. The query-plan test covers every export read, and `getEvalsByTraceIds` names the index it already used. - **The website builds only when something its build reads has changed.** Every pull request used to create a preview build of iris-eval.com, and one day of pull requests used up the host's daily build allowance, which the live site's production deploys share. A preview now builds only for a change to `website/` or `docs/blog/`, and a production deploy also for a `.claims.json` change other than its timestamp and commit stamp. A branch's first deployment compares with `main`, and a base the host's shallow clone lacks is fetched; anything that fails builds. `tests/website-build-scope.test.ts` runs the real skip script in a shallow clone, as the host does, for six kinds of change, a branch's first deployment and an unreachable base, and fails if a website source reads any other path in the repository. CI's website job now runs the production build (`next build`) on every pull request, so a `.claims.json` change that would break the site is still caught without a preview. -- **A database file is never opened by both copies of SQLite in one process (#739).** better-sqlite3 carries its own SQLite and `node:sqlite` is Node's. Their locks cannot see each other within one process, and one can reset the WAL's shared-memory file while the other has it mapped, which kills the process with SIGBUS or corrupts the file. Measured on Linux with Node 24.21.0: SIGBUS in 3 runs of 5, against 0 of 10 with one copy. Iris never did this: the store and its two worker threads use the copy the store's connection got. The one place it happened was a test's stand-in search thread, which died of SIGBUS in 2 of 30 runs on macOS. Now the driver seam enforces it: a file already open in a thread is opened again only with the copy that holds it, and the other copy is refused before it opens anything. A new CI job ends worker threads that hold a connection every way Iris ends them, on Linux, macOS and Windows, Node 22 and 24, both drivers: 9,000 per cell. One process in one cell has since exited with an access violation, on Windows with Node 24, when `close()` ended a checkpoint thread inside a statement (#804). A cell takes 20 to 60 minutes, so the job runs on pull requests that touch storage, its fixtures or the dependencies, on every push to `main`, and nightly. +- **A database file is never opened by both copies of SQLite in one process (#739).** better-sqlite3 carries its own SQLite and `node:sqlite` is Node's. Their locks cannot see each other within one process, and one can reset the WAL's shared-memory file while the other has it mapped, which kills the process with SIGBUS or corrupts the file. Measured on Linux with Node 24.21.0: SIGBUS in 3 runs of 5, against 0 of 10 with one copy. Iris never did this: the store and its two worker threads use the copy the store's connection got. The one place it happened was a test's stand-in search thread, which died of SIGBUS in 2 of 30 runs on macOS. Now the driver seam enforces it: a file already open in a thread is opened again only with the copy that holds it, and the other copy is refused before it opens anything. A new CI job ends worker threads that hold a connection every way Iris ends them, on Linux, macOS and Windows, Node 22 and 24, both drivers: 9,000 per cell. One process in one cell has since exited with an access violation, on Windows with Node 24. That is a Node.js bug in a thread's teardown (nodejs/node#65778), which the job reached by starting its threads with tsx's loader; an installed server's threads have none (#804). A cell takes 20 to 60 minutes, so the job runs on pull requests that touch storage, its fixtures or the dependencies, on every push to `main`, and nightly. - **Scoring a trace no longer reads every evaluation in the store (#711).** Each evaluation with a cost reads its agent's recent history (the failure log), and so do `/api/v1/moments`, `/api/v1/failures`, the views and webhook moment events. There are two ways to read that history, and which one is fast depends on the data. 0.19.0 always read every evaluation of the store; the covering index added for search moved SQLite to walking every trace instead; with statistics it picked the slow way for a store where every trace is evaluated. The read now chooses between two queries that name their index and fix their join order, using counts of index entries. At 100,000 traces with every trace evaluated, `log_trace` with `evaluate: true` took 291 ms in 0.19.0 and takes 25.7 ms, `POST /api/v1/traces` with evaluate 291 ms and 24.9 ms, and `GET /api/v1/moments` 2.1 s and 0.8 s (medians of three rounds). The failure-log read itself went from 160 to 176 ms to 3 ms. On a store with few evaluations, where 0.19.0 was already fast, it stays between 0.1 and 3.5 ms. A test checks every result against the plain query on 12 seeded random stores per driver, through all three of the read's paths. - **Every hot read keeps its query plan, whatever SQLite's statistics say (#711).** Iris never runs `ANALYZE`. With statistics from a store of 100,000 evaluated traces, SQLite made the failure log 35 times slower and the 30-day summary 2.4 times slower. The reads that run on every evaluation or dashboard render (the failure log, case results, `get_traces` with and without `q`, the trace search join, the filter lists, the summary and the eval stats) now name their index and fix their join order. `tests/unit/storage/query-plans.test.ts` checks each statement's plan on both drivers, with and without FTS5, with no statistics and under three sets of them. The test fails if a statement reads a whole table, or if a join starts from the wrong side or reaches the other side through the wrong index. - **The dashboard's first render reads index entries, not trace rows (#711).** At 100,000 traces: `GET /api/v1/filters` 198 ms in 0.19.0, 1.4 ms now (one index seek per distinct agent and framework); `GET /api/v1/summary?hours=720` 284 ms and 62 ms; `GET /api/v1/eval-stats?period=30d` 172 ms and 33 ms. `get_traces` sorted by `cost_usd` or `latency_ms` sorts index entries and reads the 50 rows of the page: 187 ms and 27 ms. diff --git a/src/storage/source-thread.ts b/src/storage/source-thread.ts index 4d9a11ef..265f22c4 100644 --- a/src/storage/source-thread.ts +++ b/src/storage/source-thread.ts @@ -1,10 +1,12 @@ import { Worker, type WorkerOptions } from 'node:worker_threads'; /* - * A thread does not take --import, so when Iris runs from its TypeScript - * sources (tests, `npx tsx`) the thread registers tsx's loader itself, then - * loads its entry. The entry arrives as the thread's last argv item, so the - * code the thread evaluates is a constant: nothing is spliced into it. + * A thread inherits its process's --import (Node 22 and 24), but a process + * running Iris from its TypeScript sources need not have one: the test + * runner transforms the sources itself. So the thread registers tsx's loader + * itself, then loads its entry. The entry arrives as the thread's last argv + * item, so the code the thread evaluates is a constant: nothing is spliced + * into it. */ const BOOT = "import('tsx/esm/api').then((tsx) => { tsx.register(); return import(process.argv[process.argv.length - 1]); })"; diff --git a/tests/fixtures/worker-exit/iris-workers.ts b/tests/fixtures/worker-exit/iris-workers.ts index b5505395..e3190faf 100644 --- a/tests/fixtures/worker-exit/iris-workers.ts +++ b/tests/fixtures/worker-exit/iris-workers.ts @@ -1,9 +1,10 @@ /* * Iris's own worker threads, started and ended again and again, every way - * each ends in the product. Run with tsx; prints "done" when nothing took - * the process down. + * each ends in the product. Prints "done" when nothing took the process down. * - * npx tsx iris-workers.ts (WORKER_EXIT_FROM=dist: the built server) + * node iris-workers.ts (WORKER_EXIT_FROM=dist: the built server) + * + * Run with no loader: Node strips this file's types itself. * * Endings: * store a store opens, a write starts its checkpoint worker and a search its search @@ -20,13 +21,23 @@ import { tmpdir } from 'node:os'; import { join } from 'node:path'; /* - * From the sources (tsx), as the test suite runs it, the search thread - * registers tsx's loader before it loads search-worker.ts. From the build - * (WORKER_EXIT_FROM=dist, after npm run build), as an installed server runs - * it, the thread loads search-worker.js with no loader. + * A thread inherits its process's --import (Node 22 and 24), so a process + * started with --import tsx gives every thread Iris starts tsx's loader as + * well. An installed server's threads never have one, and on Node 24 a + * thread that inherited --import tsx can crash the process as it ends, in + * Node's own teardown of the thread (nodejs/node#65778). So the loader is + * registered here, in this thread only, and only from the sources: + * - From the sources, as the test suite runs them, this thread registers + * tsx's loader, and each of Iris's threads registers its own before it + * loads its entry (source-thread.ts). + * - From the build (WORKER_EXIT_FROM=dist, after npm run build), as an + * installed server runs it, nothing registers a loader: the threads load + * search-worker.js and checkpoint-worker.js as they are. */ -const base = process.env.WORKER_EXIT_FROM === 'dist' ? '../../../dist/' : '../../../src/'; -const ext = process.env.WORKER_EXIT_FROM === 'dist' ? '.js' : '.ts'; +const fromDist = process.env.WORKER_EXIT_FROM === 'dist'; +if (!fromDist) (await import('tsx/esm/api')).register(); +const base = fromDist ? '../../../dist/' : '../../../src/'; +const ext = fromDist ? '.js' : '.ts'; const { SqliteAdapter } = (await import(`${base}storage/sqlite-adapter${ext}`)) as typeof import('../../../src/storage/sqlite-adapter.js'); const { SearchWorkerClient } = (await import(`${base}storage/search-worker-client${ext}`)) as typeof import('../../../src/storage/search-worker-client.js'); const { Checkpointer } = (await import(`${base}storage/checkpointer${ext}`)) as typeof import('../../../src/storage/checkpointer.js'); diff --git a/tests/fixtures/worker-exit/stress.cjs b/tests/fixtures/worker-exit/stress.cjs index d492a135..46eec783 100644 --- a/tests/fixtures/worker-exit/stress.cjs +++ b/tests/fixtures/worker-exit/stress.cjs @@ -130,11 +130,14 @@ function parent() { } if (process.env.WORKER_EXIT_SEARCH === '1') { const cycles = join(__dirname, 'iris-workers.ts'); + // No --import: every thread would inherit it, and an installed server's threads have no loader (iris-workers.ts + // says why). Node strips the file's types itself; a Node that does not by default is given the flag. + const strip = process.features.typescript ? [] : ['--experimental-strip-types']; for (const from of ['src', 'dist']) { for (const driver of drivers) { for (const ending of ['store', 'search-stuck', 'checkpoint-crash', 'checkpoint-kill']) { const label = `iris ${from} ${driver} ${ending}`; - summary.results.push(tally(label, processes, perProcess, ['--import', 'tsx', cycles, driver, ending, String(perProcess)], { WORKER_EXIT_FROM: from })); + summary.results.push(tally(label, processes, perProcess, [...strip, cycles, driver, ending, String(perProcess)], { WORKER_EXIT_FROM: from })); } } } diff --git a/website/src/lib/changelog.generated.json b/website/src/lib/changelog.generated.json index 16d85353..494a6925 100644 --- a/website/src/lib/changelog.generated.json +++ b/website/src/lib/changelog.generated.json @@ -159,7 +159,7 @@ "**Closing the store releases the file before it returns (#750).** The checkpoint worker's connection was asked to close and given 5 s; past that the thread was terminated and `close()` returned at once, while the thread was still in its statement and still held `iris.db` open. On Windows the file could not then be moved or removed until that statement ended, and two storage suites failed on `windows-latest` removing their directories (`EPERM`) after every assertion had passed. `close()` now resolves only once the thread has ended, and answers any request the thread was in with an error rather than leaving it waiting. A test holds the worker in a four-second statement with a 100 ms timeout: before the change `close()` returned with the thread still running (4 runs in 4, both drivers); now it waits for it.\n- The checkpoint thread stays held from the start of `close()` until it has ended. The answer to a checkpoint in flight used to release it again. If the thread then outlasted `close()`'s timeout, a short-lived process (`iris-eval ingest`, say) could exit with code 13 while `close()` still waited. The worker-exit CI job showed that release when ending the thread directly, in 1 process in 10.", "**A search's page of trace ids, and the start's check for evaluations with no stored risk estimate, keep their plans when the file has statistics (#742).** Iris never writes statistics, but `ANALYZE` run by hand does, and under them SQLite read the search index's whole trace_id index to find a page's ids, and every evaluation to find the ones without a risk estimate, at every start. The page's ids are now looked up one doc id at a time in a fixed join, in one statement for any number of matches (100,000 in 80 ms at 100,000 traces, against 92 ms in chunks of 1,000), and the fill names its index. The query-plan test covers every export read, and `getEvalsByTraceIds` names the index it already used.", "**The website builds only when something its build reads has changed.** Every pull request used to create a preview build of iris-eval.com, and one day of pull requests used up the host's daily build allowance, which the live site's production deploys share. A preview now builds only for a change to `website/` or `docs/blog/`, and a production deploy also for a `.claims.json` change other than its timestamp and commit stamp. A branch's first deployment compares with `main`, and a base the host's shallow clone lacks is fetched; anything that fails builds. `tests/website-build-scope.test.ts` runs the real skip script in a shallow clone, as the host does, for six kinds of change, a branch's first deployment and an unreachable base, and fails if a website source reads any other path in the repository. CI's website job now runs the production build (`next build`) on every pull request, so a `.claims.json` change that would break the site is still caught without a preview.", - "**A database file is never opened by both copies of SQLite in one process (#739).** better-sqlite3 carries its own SQLite and `node:sqlite` is Node's. Their locks cannot see each other within one process, and one can reset the WAL's shared-memory file while the other has it mapped, which kills the process with SIGBUS or corrupts the file. Measured on Linux with Node 24.21.0: SIGBUS in 3 runs of 5, against 0 of 10 with one copy. Iris never did this: the store and its two worker threads use the copy the store's connection got. The one place it happened was a test's stand-in search thread, which died of SIGBUS in 2 of 30 runs on macOS. Now the driver seam enforces it: a file already open in a thread is opened again only with the copy that holds it, and the other copy is refused before it opens anything. A new CI job ends worker threads that hold a connection every way Iris ends them, on Linux, macOS and Windows, Node 22 and 24, both drivers: 9,000 per cell. One process in one cell has since exited with an access violation, on Windows with Node 24, when `close()` ended a checkpoint thread inside a statement (#804). A cell takes 20 to 60 minutes, so the job runs on pull requests that touch storage, its fixtures or the dependencies, on every push to `main`, and nightly.", + "**A database file is never opened by both copies of SQLite in one process (#739).** better-sqlite3 carries its own SQLite and `node:sqlite` is Node's. Their locks cannot see each other within one process, and one can reset the WAL's shared-memory file while the other has it mapped, which kills the process with SIGBUS or corrupts the file. Measured on Linux with Node 24.21.0: SIGBUS in 3 runs of 5, against 0 of 10 with one copy. Iris never did this: the store and its two worker threads use the copy the store's connection got. The one place it happened was a test's stand-in search thread, which died of SIGBUS in 2 of 30 runs on macOS. Now the driver seam enforces it: a file already open in a thread is opened again only with the copy that holds it, and the other copy is refused before it opens anything. A new CI job ends worker threads that hold a connection every way Iris ends them, on Linux, macOS and Windows, Node 22 and 24, both drivers: 9,000 per cell. One process in one cell has since exited with an access violation, on Windows with Node 24. That is a Node.js bug in a thread's teardown (nodejs/node#65778), which the job reached by starting its threads with tsx's loader; an installed server's threads have none (#804). A cell takes 20 to 60 minutes, so the job runs on pull requests that touch storage, its fixtures or the dependencies, on every push to `main`, and nightly.", "**Scoring a trace no longer reads every evaluation in the store (#711).** Each evaluation with a cost reads its agent's recent history (the failure log), and so do `/api/v1/moments`, `/api/v1/failures`, the views and webhook moment events. There are two ways to read that history, and which one is fast depends on the data. 0.19.0 always read every evaluation of the store; the covering index added for search moved SQLite to walking every trace instead; with statistics it picked the slow way for a store where every trace is evaluated. The read now chooses between two queries that name their index and fix their join order, using counts of index entries. At 100,000 traces with every trace evaluated, `log_trace` with `evaluate: true` took 291 ms in 0.19.0 and takes 25.7 ms, `POST /api/v1/traces` with evaluate 291 ms and 24.9 ms, and `GET /api/v1/moments` 2.1 s and 0.8 s (medians of three rounds). The failure-log read itself went from 160 to 176 ms to 3 ms. On a store with few evaluations, where 0.19.0 was already fast, it stays between 0.1 and 3.5 ms. A test checks every result against the plain query on 12 seeded random stores per driver, through all three of the read's paths.", "**Every hot read keeps its query plan, whatever SQLite's statistics say (#711).** Iris never runs `ANALYZE`. With statistics from a store of 100,000 evaluated traces, SQLite made the failure log 35 times slower and the 30-day summary 2.4 times slower. The reads that run on every evaluation or dashboard render (the failure log, case results, `get_traces` with and without `q`, the trace search join, the filter lists, the summary and the eval stats) now name their index and fix their join order. `tests/unit/storage/query-plans.test.ts` checks each statement's plan on both drivers, with and without FTS5, with no statistics and under three sets of them. The test fails if a statement reads a whole table, or if a join starts from the wrong side or reaches the other side through the wrong index.", "**The dashboard's first render reads index entries, not trace rows (#711).** At 100,000 traces: `GET /api/v1/filters` 198 ms in 0.19.0, 1.4 ms now (one index seek per distinct agent and framework); `GET /api/v1/summary?hours=720` 284 ms and 62 ms; `GET /api/v1/eval-stats?period=30d` 172 ms and 33 ms. `get_traces` sorted by `cost_usd` or `latency_ms` sorts index entries and reads the 50 rows of the page: 187 ms and 27 ms.",