package store import ( "context" "database/sql" "database/sql/driver" "log" "reflect" "strings" "sync/atomic" "time" ) // R-1346 (2026-10-30): the per-statement timing. The access log names a slow REQUEST; this names the slow STATEMENT // inside it. Every Exec, Query (until its rows are closed) and BEGIN that takes longer than slowStatementAfter is // logged once as // // [WARN] slow statement: 1234ms (over 1s): SELECT DISTINCT controller_version FROM reports WHERE … // // — the SQL text only (whitespace folded, at most 300 characters), NEVER the bound values: they can be customer data. // A wrapper around modernc's driver, registered once as "sqlite-timed"; store.New opens it. Pinned by // TestTimedDriver_ASlowStatementIsNamed and TestTimedDriver_NeverLogsValues. const timedDriverName = "sqlite-timed" // slowStatementAfter is the threshold (nanoseconds); SetSlowStatementThreshold changes it for a test or a probe. var slowStatementAfter atomic.Int64 // SetSlowStatementThreshold changes the threshold (a test, the R-1346 probe). Not called by the hub itself. func SetSlowStatementThreshold(d time.Duration) { slowStatementAfter.Store(int64(d)) } // statementLogger is where the line goes (the store's logger, set by New; the standard logger until then). var statementLogger atomic.Pointer[log.Logger] func init() { slowStatementAfter.Store(int64(time.Second)) // The SAME driver value modernc registered as "sqlite" (its connection hooks live on it); sql.Open connects nothing. db, err := sql.Open("sqlite", "") if err != nil { panic("store: the sqlite driver is not registered: " + err.Error()) } sql.Register(timedDriverName, &timedDriver{inner: db.Driver()}) _ = db.Close() } func logSlowStatement(kind, query string, took time.Duration) { after := time.Duration(slowStatementAfter.Load()) if took < after { return } q := strings.Join(strings.Fields(query), " ") if len(q) > 300 { q = q[:300] + "…" } if kind != "" { q = kind + " " + q } l := statementLogger.Load() if l == nil { l = log.Default() } l.Printf("[WARN] slow statement: %dms (over %s): %s", took.Milliseconds(), after, q) } type timedDriver struct{ inner driver.Driver } func (d *timedDriver) Open(name string) (driver.Conn, error) { c, err := d.inner.Open(name) if err != nil { return nil, err } return &timedConn{Conn: c}, nil } type timedConn struct{ driver.Conn } func (c *timedConn) ExecContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Result, error) { ex, ok := c.Conn.(driver.ExecerContext) if !ok { return nil, driver.ErrSkip } began := time.Now() r, err := ex.ExecContext(ctx, query, args) logSlowStatement("", query, time.Since(began)) return r, err } func (c *timedConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) { q, ok := c.Conn.(driver.QueryerContext) if !ok { return nil, driver.ErrSkip } began := time.Now() r, err := q.QueryContext(ctx, query, args) if err != nil { logSlowStatement("", query, time.Since(began)) return nil, err } return &timedRows{Rows: r, query: query, began: began}, nil } func (c *timedConn) PrepareContext(ctx context.Context, query string) (driver.Stmt, error) { if p, ok := c.Conn.(driver.ConnPrepareContext); ok { return p.PrepareContext(ctx, query) } return c.Conn.Prepare(query) } // BeginTx: with _txlock=immediate the BEGIN itself waits for the write lock — a slow one is a writer queue, named so. func (c *timedConn) BeginTx(ctx context.Context, opts driver.TxOptions) (driver.Tx, error) { began := time.Now() var ( tx driver.Tx err error ) if b, ok := c.Conn.(driver.ConnBeginTx); ok { tx, err = b.BeginTx(ctx, opts) } else { tx, err = c.Conn.Begin() //nolint:staticcheck // the fallback database/sql itself uses } logSlowStatement("", "BEGIN (waiting for the write lock)", time.Since(began)) return tx, err } func (c *timedConn) Ping(ctx context.Context) error { if p, ok := c.Conn.(driver.Pinger); ok { return p.Ping(ctx) } return nil } func (c *timedConn) ResetSession(ctx context.Context) error { if r, ok := c.Conn.(driver.SessionResetter); ok { return r.ResetSession(ctx) } return nil } func (c *timedConn) IsValid() bool { if v, ok := c.Conn.(driver.Validator); ok { return v.IsValid() } return true } // timedRows times a query until its rows are closed — a GROUP BY or a DISTINCT does its work before the first row, a // plain scan while the rows are read; both count. type timedRows struct { driver.Rows query string began time.Time closed bool } func (r *timedRows) Close() error { err := r.Rows.Close() if !r.closed { r.closed = true logSlowStatement("", r.query, time.Since(r.began)) } return err } func (r *timedRows) ColumnTypeDatabaseTypeName(i int) string { if c, ok := r.Rows.(driver.RowsColumnTypeDatabaseTypeName); ok { return c.ColumnTypeDatabaseTypeName(i) } return "" } func (r *timedRows) ColumnTypeLength(i int) (int64, bool) { if c, ok := r.Rows.(driver.RowsColumnTypeLength); ok { return c.ColumnTypeLength(i) } return 0, false } func (r *timedRows) ColumnTypeNullable(i int) (bool, bool) { if c, ok := r.Rows.(driver.RowsColumnTypeNullable); ok { return c.ColumnTypeNullable(i) } return false, false } func (r *timedRows) ColumnTypePrecisionScale(i int) (int64, int64, bool) { if c, ok := r.Rows.(driver.RowsColumnTypePrecisionScale); ok { return c.ColumnTypePrecisionScale(i) } return 0, 0, false } func (r *timedRows) ColumnTypeScanType(i int) reflect.Type { if c, ok := r.Rows.(driver.RowsColumnTypeScanType); ok { return c.ColumnTypeScanType(i) } return reflect.TypeOf(new(any)).Elem() }