Slow statement log: report individual slow executions under st.orm.sql.slow

[zantvoort]

Storm reports SQL in two grains under one logger tree: st.orm.sql logs each statement as it executes, st.orm.sql.perf reports what a unit of work cost as one summary. Neither answers the question a production incident starts with: which single execution was slow, from where, with what.

• The statement log fires before execution (SqlInterceptorManager.intercept), so it carries no duration.
• The summary thresholds are scope-level: statement count and scope wall time. A 900 ms statement inside a three-statement request trips nothing, and a summary row groups by shape and ranks by summed time, so one slow execution hides among two hundred cheap ones.
• Outside a scope (background work, an entry point the filter and the proxy do not wrap, a thread the scope did not reach) nothing times anything.

There is also a measurement to put right first. Every duration Storm records today runs from before getStatement() to the close of the observation, and for a stream that close is the stream's close (QueryImpl.getResultStream). "214 ms in database" therefore includes application-side consumption for streamed reads, in summaries and in SqlCapture.duration alike. A per-statement threshold on that number would misfire on any stream held open across other work.

Measure database time as its own number

Mark the moment executeQuery(), executeUpdate() or executeBatch() returns. Database time is prepare plus execute, up to that mark. For a stream, what follows (fetch round trips interleaved with consumption) is reported separately and never mixed in. One definition, applied everywhere a duration appears: the perf summary's in database, its elapsed and concurrency figures, SqlCapture.duration, and the new slow log. Summary rows gain a max, so a single slow execution no longer disappears into its group's total.

The slow log

A third logger, with the rules of the other two: st.orm.sql.slow, at WARN, one line per execution whose database time exceeds a threshold. Enabled by storm.sql-log.slow-statement: 200ms (Spring), sqlLogSlowStatement / storm.sqlLog.slowStatement (Ktor), storm.sql_log.slow_statement (system property). It needs no scope and works with storm.sql-log.enabled: false. WARN so raising st.orm.sql to DEBUG duplicates nothing; parameter values render only at TRACE, the one rule that already governs st.orm.sql. Log-only, no data model.

The decision is made at execute-return, on the calling thread, which is what makes the rest fall into place:

• The stack is intact, so the call site is walked only for slow executions: free for the rest, exact for the ones that matter. Today callSites is a per-scope opt-in because it costs a stack walk per execution.
• Scope-independent: not bound to a filter, an entry-point proxy or a coroutine context. Every execution is seen, background workers included.
• The connection is still in hand, which a later dev-only EXPLAIN could use.

Rows are known at close, so the line is emitted at close and carries them; the call site is captured at execute-return.

WARN st.orm.sql.slow: SQL slow (SELECT Pet): 1840 ms in database, 3 rows, PetService.kt:42
	SELECT p.id, p.name, ... FROM pet p JOIN owner o ON ... WHERE o.city_id IN (?, ?, ...)
	shape 3f9a2c (typically 6.0 ms, 306x)  parameters 32 (typically 3)  comment traceparent='00-4bf92f35...-01'

BATCH lines carry the batch size, so 3 s for 5,000 rows is not misread. Streamed reads carry their consumption separately (consumed 12,400 rows over 3.2 s).

Parameter-dependent slowness

Many statements are slow only with certain values. shapeId is the key that already exists for this: stable across parameter expansion, so an IN list of 3 and one of 32 are the same shape. While the slow log is on, each shape keeps a baseline of what it typically costs over its recent minutes: a geometric mean, which an outlier barely moves, kept as per-window sums on adders (three adds per execution, nothing when off) and folded sample-weighted at each window close. It classifies each slow line:

• typically 6.0 ms, 306x: this shape is normally fast, the slowness came from these parameters or a plan change. Look at the values.
• typically 310 ms: this statement is always this slow. Look at the query, the graph its type declares, and its indexes.

Alongside, a parameter profile that is safe in production: the parameter count against the shape's typical count, so parameters 32 (typically 3) names the oversized IN list without printing a value. The values themselves at TRACE, inlined through the existing SqlLiterals.inline, giving a paste-ready statement.

The absolute threshold triggers; the shape baseline annotates. Triggering on a relative outlier is noisy at the low end (0.2 ms to 4 ms is 20x); it can be added later with a floor.

Production guardrails

• Rate-limited per shape: when the database degrades every statement is slow. Log a configurable number of lines per shape per minute (slow-statement-limit, default 5, 0 for none) and carry +37 suppressed on the next line rather than flood.
• A failed execution is reported too, as failed (SQLTimeoutException): a statement that timed out spent its time in the database, and the line carries what the caller's exception does not. Named by class alone, since a driver's message may quote values.
• Cost when off: one volatile read on the execution path, the shape of the existing globalOperatorCount > 0 guard.
• Nothing sensitive by default: WARN carries text with placeholders and counts, never values.

The plan comes from the database

The SqlCommenter already sends the trace context into the statement, so PostgreSQL auto_explain / log_min_duration_statement and the MySQL and MariaDB slow query logs capture the actual plan of the actual slow execution with that comment attached. The slow line prints the same key. Storm says what, from where, with which parameter profile; the database says how it ran.

Storm does not run EXPLAIN in this issue. Beyond the connection and dialect plumbing, EXPLAIN with literal values yields a custom plan where the slow prepared execution may have run a generic one, so the explanation can show a fast plan for a slow query. A dev-only EXPLAIN on the same connection at execute-return is possible once the measurement exists, framed as a hint.

One model

Every execution passes one interception point exactly once. Every report draws on one vocabulary (operation, type, origin, shape, kind, rows, database time, call site) and one measurement. Values appear at TRACE and nowhere else.

Report	Answers	Grain	Switch	Values
st.orm.sql	what ran	statement	logger DEBUG / TRACE	TRACE
st.orm.sql.perf	what a call cost	unit of work	logger INFO + boundary config	never
st.orm.sql.slow	which execution was slow, from where, with what	execution	logger WARN + threshold	TRACE
Micrometer storm.query	how statements behave over time, per shape	execution, aggregated	ObservationRegistry	never
SqlCommenter	join key for the database's own slow log and plans	execution	storm.tracing.sql-comments	n/a
SqlCapture	assertions in tests	statement	code	yes, in tests

Docs

sql-logging.md opens with that table, so the three loggers, the metrics, the trace comment and the test capture read as one design rather than six features. A "Slow Statements" section sits between the summaries and the tips, with the Spring / Ktor / JVM tabs the summaries have. The summary section's headline table and SqlCapture.duration state the database-time definition. The observability sections of the Spring and Ktor pages point at the slow log next to the trace comment, since together they are the correlation. Glossary entry updated. Docs are edited in docs/ only; they show at /docs/next until the next release.

Also in this change

The hydration shape on summary rows (storm.sql-log.hydration, j2 c12 d3, shipped in 1.13) is removed: a type's declared shape is a per-type fact, and printing it per execution behind an option was decoration. The per-type report and a possible notable-only signal move to #503.

Tasks

• Core: execute-return mark on every execution path; database time as the one duration in SqlLog.Statement, the summary figures and SqlCapture; stream consumption reported separately; summary rows carry max
• Core: st.orm.sql.slow logger; slow decision at execute-return; call site walked only when slow; line rendering; storm.sql_log.slow_statement
• Core: per-shape baseline and parameter profile; per-shape rate limit; values at TRACE
• Spring and Ktor: slow-statement / sqlLogSlowStatement wiring, independent of enabled
• Docs as above