Skip to content

Commit e23126c

Browse files
committed
fix(bench): include successful query logging in database workload
Create the QueryLog fixture schema and its indexes so stock Stacks persists diagnostics instead of measuring failed inserts against a missing table. Clear accumulated logs before each repetition outside warmup and measurement, preserving read data. Add an isolated real-query regression that reproduces the missing table failure, verifies persistence, and checks reset integrity. Document the asymmetric logging workload and that earlier failed-write results are not comparable. Validation: four benchmark tests, 366 unit tests, lint, framework types, and two independent reviews passed. Three native oha repetitions passed response parity with zero errors and actual persisted logs. Local results are directional only.
1 parent e621b13 commit e23126c

5 files changed

Lines changed: 154 additions & 1 deletion

File tree

bench/routing/README.md

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -78,6 +78,13 @@ papered over. `post-validate` has the same shape: Elysia uses its `t` schema,
7878
Hono a hand-written check behind its own `validator()` seam, and both are
7979
cheaper than a compiled rule set.
8080

81+
The fixture includes `query_logs` and its indexes, so stock Stacks query logging
82+
performs successful writes. Those writes are part of the database workload;
83+
the bare SQLite targets do not provide query logging. Accumulated logs are
84+
cleared before each repetition, outside warm-up and measurement, while the
85+
seeded read data stays unchanged. Results from the earlier fixture without
86+
`query_logs` measured failed logging writes and are not comparable.
87+
8188
## Profiles
8289

8390
Stacks appears three times on purpose. The gap between the first and the third

bench/routing/fixture.test.ts

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
import { Database } from 'bun:sqlite'
2+
import { expect, it } from 'bun:test'
3+
import { mkdtempSync, rmSync } from 'node:fs'
4+
import { tmpdir } from 'node:os'
5+
import { join } from 'node:path'
6+
import { createFixture, FIXTURE_ROWS, resetFixtureLogs } from './fixture'
7+
8+
it('supports real query logging in the isolated benchmark database', async () => {
9+
const dir = mkdtempSync(join(tmpdir(), 'stacks-routing-fixture-'))
10+
const file = join(dir, 'bench.sqlite')
11+
try {
12+
createFixture(file)
13+
const child = Bun.spawn([
14+
process.execPath,
15+
`--config=${join(import.meta.dir, 'bunfig.toml')}`,
16+
join(import.meta.dir, 'fixtures/query-logging.ts'),
17+
file,
18+
], {
19+
env: { ...process.env, APP_ENV: 'test', DB_CONNECTION: 'sqlite', DB_DATABASE_PATH: file, DB_QUERY_LOGGING_ENABLED: 'true' },
20+
stdout: 'pipe',
21+
stderr: 'pipe',
22+
})
23+
const [exitCode, stdout, stderr] = await Promise.all([
24+
child.exited,
25+
new Response(child.stdout).text(),
26+
new Response(child.stderr).text(),
27+
])
28+
expect(exitCode, stderr).toBe(0)
29+
expect(stdout).toContain('fixture-query-logging-ok')
30+
31+
const db = new Database(file)
32+
try {
33+
expect(db.query('SELECT COUNT(*) AS count FROM bench_items').get()).toEqual({ count: FIXTURE_ROWS })
34+
expect(db.query('SELECT status FROM query_logs').all()).toEqual([{ status: 'completed' }])
35+
}
36+
finally {
37+
db.close()
38+
}
39+
resetFixtureLogs(file)
40+
const reset = new Database(file)
41+
try {
42+
expect(reset.query('SELECT COUNT(*) AS count FROM query_logs').get()).toEqual({ count: 0 })
43+
expect(reset.query('SELECT COUNT(*) AS count FROM bench_items').get()).toEqual({ count: FIXTURE_ROWS })
44+
expect(reset.query('SELECT * FROM bench_items WHERE id = 1').get()).toEqual({ id: 1, name: 'item-1' })
45+
expect(reset.query("SELECT name FROM sqlite_master WHERE type = 'index' AND tbl_name = 'query_logs' ORDER BY name").all()).toEqual([
46+
{ name: 'query_logs_duration_index' },
47+
{ name: 'query_logs_executed_at_index' },
48+
{ name: 'query_logs_status_index' },
49+
])
50+
}
51+
finally {
52+
reset.close()
53+
}
54+
}
55+
finally {
56+
rmSync(dir, { recursive: true, force: true })
57+
}
58+
})

bench/routing/fixture.ts

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,40 @@ export function createFixture(file: string): void {
2828
db.exec('DROP TABLE IF EXISTS bench_items')
2929
db.exec('CREATE TABLE bench_items (id INTEGER PRIMARY KEY, name TEXT NOT NULL)')
3030

31+
// Match the built-in QueryLog model, including its write-side indexes.
32+
// Stock Stacks logs the SELECT; a missing table measures a failed INSERT.
33+
db.exec('DROP TABLE IF EXISTS query_logs')
34+
db.exec(`CREATE TABLE query_logs (
35+
id INTEGER PRIMARY KEY AUTOINCREMENT,
36+
created_at TEXT NOT NULL DEFAULT CURRENT_TIMESTAMP,
37+
updated_at TEXT,
38+
query TEXT NOT NULL,
39+
normalized_query TEXT,
40+
duration REAL DEFAULT 0,
41+
connection TEXT DEFAULT 'unknown',
42+
status TEXT DEFAULT 'completed' CHECK (status IN ('completed', 'failed', 'slow')),
43+
error TEXT,
44+
executed_at TEXT NOT NULL,
45+
bindings TEXT,
46+
trace TEXT,
47+
model TEXT,
48+
method TEXT,
49+
file TEXT,
50+
line INTEGER,
51+
memory_usage REAL,
52+
rows_affected INTEGER,
53+
transaction_id TEXT,
54+
tags TEXT,
55+
affected_tables TEXT,
56+
indexes_used TEXT,
57+
missing_indexes TEXT,
58+
explain_plan TEXT,
59+
optimization_suggestions TEXT
60+
)`)
61+
db.exec('CREATE INDEX query_logs_executed_at_index ON query_logs (executed_at)')
62+
db.exec('CREATE INDEX query_logs_status_index ON query_logs (status)')
63+
db.exec('CREATE INDEX query_logs_duration_index ON query_logs (duration)')
64+
3165
const insert = db.prepare('INSERT INTO bench_items (id, name) VALUES (?, ?)')
3266
const seed = db.transaction((count: number) => {
3367
for (let i = 1; i <= count; i++) insert.run(i, `item-${i}`)
@@ -38,3 +72,16 @@ export function createFixture(file: string): void {
3872
db.close()
3973
}
4074
}
75+
76+
/** Reset accumulated diagnostics outside the timed workload, keeping seed rows. */
77+
export function resetFixtureLogs(file: string): void {
78+
const db = new Database(file)
79+
try {
80+
db.exec('DELETE FROM query_logs')
81+
db.exec("DELETE FROM sqlite_sequence WHERE name = 'query_logs'")
82+
db.exec('PRAGMA wal_checkpoint(TRUNCATE)')
83+
}
84+
finally {
85+
db.close()
86+
}
87+
}
Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
1+
const file = process.argv[2]!
2+
const { config, overridesReady } = await import('@stacksjs/config')
3+
const { db, ensureDatabaseConfigLoaded, initializeDbConfig, resetDatabaseConnection } = await import('../../../storage/framework/core/database/src/utils')
4+
5+
await overridesReady
6+
await ensureDatabaseConfigLoaded()
7+
initializeDbConfig({
8+
app: { env: 'test' },
9+
database: { default: 'sqlite', connections: { sqlite: { database: file } } },
10+
})
11+
config.database.queryLogging = {
12+
...config.database.queryLogging,
13+
enabled: true,
14+
excludedQueries: [],
15+
analysis: { ...config.database.queryLogging?.analysis, enabled: false },
16+
}
17+
18+
try {
19+
const rows = await db.selectFrom('bench_items').select(['id', 'name']).where('id', '=', 1).limit(1).execute()
20+
if (JSON.stringify(rows) !== '[{"id":1,"name":"item-1"}]')
21+
throw new Error('Unexpected benchmark query result')
22+
23+
const deadline = Date.now() + 2000
24+
for (;;) {
25+
const records = await db.unsafe('SELECT query, status FROM query_logs').execute()
26+
if (records.length > 0) {
27+
if (records.length !== 1 || !String(records[0]?.query).includes('bench_items') || records[0]?.status !== 'completed')
28+
throw new Error('Unexpected benchmark query log')
29+
break
30+
}
31+
if (Date.now() > deadline)
32+
throw new Error('Benchmark query was never logged')
33+
await Bun.sleep(10)
34+
}
35+
console.log('fixture-query-logging-ok')
36+
}
37+
finally {
38+
resetDatabaseConnection()
39+
}

bench/routing/run.ts

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ import { join } from 'node:path'
2020
import process from 'node:process'
2121
import { fileURLToPath } from 'node:url'
2222
import { pickDriver } from './drivers'
23-
import { createFixture } from './fixture'
23+
import { createFixture, resetFixtureLogs } from './fixture'
2424
import { renderReport } from './report'
2525
import { assertParity, boot, FIXTURE, headersFor, PORT, stop } from './runtime'
2626
import { SCENARIOS } from './scenarios'
@@ -188,6 +188,8 @@ async function main(): Promise<void> {
188188
const cpuReadings: number[] = []
189189

190190
for (let run = 1; run <= opts.runs; run++) {
191+
if (scenario.requiresDb)
192+
resetFixtureLogs(FIXTURE)
191193
const finishCpu = await measureCpu(booted.pid)
192194
const result = await driver.run({
193195
url: `http://127.0.0.1:${PORT}${scenario.path}`,

0 commit comments

Comments
 (0)