fix(db): reduce per-request connection bursts and add dbtrace

* Throttle async session-activity writes to once per token per minute * Add singleflight to session lookups, keystore validation and column/row security loads to stop cold-cache stampedes * Preload security rules in BeforeHandle (restheadspec, resolvespec) so they no longer need a second connection while the read tx is open * Add pkg/dbtrace: opt-in per-request DB call counting and pool logging (db_trace.* config, RESOLVESPEC_DB_TRACE_* env), wired into testserver * Add tests for load dedup, activity throttle and dbtrace
2026-10-01 04:21:58 +00:00 · 2026-09-30 21:44:28 +02:00
parent 62cc14c02a
commit 3e327d0c78
20 changed files with 544 additions and 87 deletions
@@ -0,0 +1,28 @@
+# dbtrace
+
+Per-request DB call counting + pool logging. Off by default.
+
+## Enable
+| Config (`db_trace.*`) | Env | Meaning |
+|---|---|---|
+| `enabled` | `RESOLVESPEC_DB_TRACE_ENABLED` | per-request logging |
+| `min_calls` (5) | `..._MIN_CALLS` | log if tx+pooled+raw >= N |
+| `min_duration` (0) | `..._MIN_DURATION` | or request took >= D |
+| `pool_log` | `..._POOL_LOG` | log pool stats on each dbmanager metrics publish |
+
+Wire: `dbtrace.Configure(dbtrace.FromConfig(cfg.DBTrace))` and wrap handlers with `dbtrace.Middleware` (outside the auth middleware).
+
+## Log fields
+- `tx` transactions begun · `tx_queries` adapter queries inside `RunInTransaction` (share the tx connection)
+- `pooled` adapter queries outside a tx (each takes a pool connection)
+- `raw` direct `*sql.DB` calls, with kinds: `auth.session`, `auth.activity`, `security.column`, `security.row`, `probe.pg_proc`, `keystore.validate`
+- Connections used ≈ `tx + pooled + raw`
+
+## Pool log
+`dbtrace pool <name>: open in_use idle max opened=+N waits=+N wait_time=+D` — `opened`/`waits` are deltas since last publish.
+
+## Limits
+- tx attribution is per request, assumes sequential use of a request's context
+- `auth.activity` runs detached after the response: not in the request's log line
+- `BeginTx`/`CommitTx` (manual tx) not counted; only `RunInTransaction`
+- Raw counters cover the hot paths listed above only (not login/OAuth/passkey/TOTP)
@@ -0,0 +1,167 @@
+// Package dbtrace counts database calls per request and logs the heavy ones.
+// It is off until Configure enables it; the hot-path helpers are no-ops for
+// contexts without a tracker.
+//
+// Connection use per request ≈ tx + pooled + raw (each pooled/raw call takes
+// its own pool connection; calls inside RunInTransaction share the tx's).
+package dbtrace
+
+import (
+	"context"
+	"fmt"
+	"net/http"
+	"sort"
+	"strings"
+	"sync"
+	"sync/atomic"
+	"time"
+
+	"github.com/bitechdev/ResolveSpec/pkg/config"
+	"github.com/bitechdev/ResolveSpec/pkg/logger"
+)
+
+// Options controls tracing.
+type Options struct {
+	Enabled     bool
+	MinCalls    int           // log when tx+pooled+raw >= MinCalls
+	MinDuration time.Duration // or when the request took at least this (0 = off)
+	PoolLog     bool          // log pool deltas on each dbmanager metrics publish
+}
+
+// FromConfig maps the application config to Options.
+func FromConfig(c config.DBTraceConfig) Options {
+	return Options{Enabled: c.Enabled, MinCalls: c.MinCalls, MinDuration: c.MinDuration, PoolLog: c.PoolLog}
+}
+
+var (
+	opts atomic.Pointer[Options]
+)
+
+// Configure sets the active options. Safe to call at any time.
+func Configure(o Options) {
+	if o.MinCalls <= 0 {
+		o.MinCalls = 1
+	}
+	opts.Store(&o)
+}
+
+// Enabled reports whether per-request tracing is on.
+func Enabled() bool {
+	o := opts.Load()
+	return o != nil && o.Enabled
+}
+
+// PoolLogEnabled reports whether pool logging is on.
+func PoolLogEnabled() bool {
+	o := opts.Load()
+	return o != nil && o.PoolLog
+}
+
+// Tracker holds one request's counters.
+type Tracker struct {
+	pooled  atomic.Int32 // adapter calls outside a transaction
+	inTx    atomic.Int32 // adapter calls inside RunInTransaction
+	tx      atomic.Int32 // transactions begun
+	txDepth atomic.Int32
+	raw     atomic.Int32 // direct *sql.DB calls (auth, security, keystore)
+
+	mu      sync.Mutex
+	rawKind map[string]int
+}
+
+type ctxKey struct{}
+
+// Start attaches a new Tracker to ctx.
+func Start(ctx context.Context) (context.Context, *Tracker) {
+	t := &Tracker{}
+	return context.WithValue(ctx, ctxKey{}, t), t
+}
+
+// From returns the Tracker on ctx, or nil.
+func From(ctx context.Context) *Tracker {
+	if ctx == nil {
+		return nil
+	}
+	t, _ := ctx.Value(ctxKey{}).(*Tracker)
+	return t
+}
+
+// Query counts one adapter query.
+func Query(ctx context.Context) {
+	t := From(ctx)
+	if t == nil {
+		return
+	}
+	if t.txDepth.Load() > 0 {
+		t.inTx.Add(1)
+	} else {
+		t.pooled.Add(1)
+	}
+}
+
+// TxBegin counts a transaction and returns a func to call when it ends.
+// Queries between the two are attributed to the transaction's connection.
+func TxBegin(ctx context.Context) func() {
+	t := From(ctx)
+	if t == nil {
+		return func() {}
+	}
+	t.tx.Add(1)
+	t.txDepth.Add(1)
+	return func() { t.txDepth.Add(-1) }
+}
+
+// Raw counts one direct *sql.DB call, labelled by what issued it.
+func Raw(ctx context.Context, kind string) {
+	t := From(ctx)
+	if t == nil {
+		return
+	}
+	t.raw.Add(1)
+	t.mu.Lock()
+	if t.rawKind == nil {
+		t.rawKind = make(map[string]int)
+	}
+	t.rawKind[kind]++
+	t.mu.Unlock()
+}
+
+func (t *Tracker) total() int { return int(t.tx.Load() + t.pooled.Load() + t.raw.Load()) }
+
+// Summary renders the counters, e.g. "tx=1 tx_queries=3 pooled=2 raw=1 [auth.session=1]".
+func (t *Tracker) Summary() string {
+	var b strings.Builder
+	fmt.Fprintf(&b, "tx=%d tx_queries=%d pooled=%d raw=%d", t.tx.Load(), t.inTx.Load(), t.pooled.Load(), t.raw.Load())
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	if len(t.rawKind) > 0 {
+		kinds := make([]string, 0, len(t.rawKind))
+		for k, n := range t.rawKind {
+			kinds = append(kinds, fmt.Sprintf("%s=%d", k, n))
+		}
+		sort.Strings(kinds)
+		fmt.Fprintf(&b, " [%s]", strings.Join(kinds, " "))
+	}
+	return b.String()
+}
+
+// Middleware tracks every request and logs those over the configured
+// thresholds once the handler returns. Options are read per request, so
+// Configure can toggle it at runtime. Raw calls made by detached goroutines
+// after the response (e.g. session activity) are not included in the log line.
+func Middleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		o := opts.Load()
+		if o == nil || !o.Enabled {
+			next.ServeHTTP(w, r)
+			return
+		}
+		ctx, t := Start(r.Context())
+		start := time.Now()
+		next.ServeHTTP(w, r.WithContext(ctx))
+		elapsed := time.Since(start)
+		if t.total() >= o.MinCalls || (o.MinDuration > 0 && elapsed >= o.MinDuration) {
+			logger.Info("dbtrace: %s %s %s duration=%s", r.Method, r.URL.Path, t.Summary(), elapsed.Round(time.Millisecond))
+		}
+	})
+}
@@ -0,0 +1,64 @@
+package dbtrace
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+)
+
+func TestTrackerCounts(t *testing.T) {
+	ctx, tr := Start(context.Background())
+	Query(ctx) // pooled
+	end := TxBegin(ctx)
+	Query(ctx)
+	Query(ctx)
+	end()
+	Query(ctx) // pooled again
+	Raw(ctx, "auth.session")
+	Raw(ctx, "auth.session")
+
+	want := "tx=1 tx_queries=2 pooled=2 raw=2 [auth.session=2]"
+	if got := tr.Summary(); got != want {
+		t.Fatalf("summary = %q, want %q", got, want)
+	}
+	if tr.total() != 5 {
+		t.Fatalf("total = %d, want 5", tr.total())
+	}
+}
+
+func TestHelpersNoopWithoutTracker(t *testing.T) {
+	ctx := context.Background()
+	Query(ctx)
+	Raw(ctx, "x")
+	TxBegin(ctx)()
+	if From(ctx) != nil {
+		t.Fatal("unexpected tracker")
+	}
+}
+
+func TestMiddlewareDisabledAddsNoTracker(t *testing.T) {
+	Configure(Options{Enabled: false})
+	var seen *Tracker
+	h := Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { seen = From(r.Context()) }))
+	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/x", nil))
+	if seen != nil {
+		t.Fatal("tracker present while disabled")
+	}
+}
+
+func TestMiddlewareEnabledTracks(t *testing.T) {
+	Configure(Options{Enabled: true, MinCalls: 2})
+	defer Configure(Options{})
+	var summary string
+	h := Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		Raw(r.Context(), "a")
+		Query(r.Context())
+		summary = From(r.Context()).Summary()
+	}))
+	h.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/x", nil))
+	if !strings.Contains(summary, "pooled=1 raw=1") {
+		t.Fatalf("summary = %q", summary)
+	}
+}