hub 0.178.0: the database speed (R-1346) — four indexes and one hint for the five statements that read whole tables (vouch fleet check, OS alarm agent versions, the 04:30 prune inside its write lock, the apps page); the manifest save in one transaction; the slow-statement line (SQL only, never values); evidence p1-r1344 + p2-r1346
This commit is contained in:
admin committed
1 parent
be538975fc
commit
a13c69b01a
15 files changed
+5412
-37
No files matched your search
@@ -78,6 +78,7 @@
|
||||
| `offsitekeys.Service` (`RegisterKey`, `ConfirmKey`, `AuditAll`, `OpenWindowFor`, `CloseWindowFor`, `SweepExpiredWindows`) | hub/internal/offsitekeys/service.go | — | Binding the registrar to the store, descriptor and operator events | The box-facing API (`/api/v1/offsite/register-key…`) answers with NO credential — pinned by `TestOffsiteKeyEndpoints_AuthAndNoPasswordInAnyResponse`. |
|
||||
| `offsitekeys` snapshot watch + `store.Get/SetOffsiteSnapshotListing` / `OffsiteRunTimesSince` (v0.158.0, R-895 slice 2) | hub/internal/offsitekeys/snapshot_watch.go, hub/internal/store/offsite_snapshots.go | — | Judging the 07:10 `snapshots/` listing against yesterday's (baseline in `hub_settings`) and the box's reported runs | Raises `offsite_snapshots_vanished` / `_unexplained` — operator-only and hub-origin (NOT in `allowedEventTypes`). The first listing is a baseline; a move-aside or RESET drops it. |
|
||||
| `accesslog.New` / `Middleware` / `Mark` (v0.158.0, R-1140) | hub/internal/accesslog/accesslog.go | `Mark(ctx, kind)` | The hub's own access log (`<data_dir>/access-log/`, 90 days) and marking the identity KIND an auth check established | Never log a value: the path only (no query; `/bind/<token>` and 32+-char segments redacted). A new auth path calls `Mark` with its kind. A logging failure never fails a request. |
|
||||
| the timed SQLite driver `sqlite-timed` + `SetSlowStatementThreshold` (v0.178.0, R-1346) | hub/internal/store/timeddriver.go | `store.New` opens it — nothing to call | Names a statement over 1 s: `[WARN] slow statement: <ms> (over 1s): <SQL>` | The SQL text only, never a bound value. Put a heavy statement's SQL in a const and pin its plan (`r1346_speed.go`, `TestR1346_HeavyStatementsUseTheirIndex`): on the hub's network disk a whole-table read is seconds to minutes. |
|
||||
| `(*Store).SaveOneTimeSecret` / `OffsitePassword` / `SealLegacyOffsiteSecrets` | hub/internal/store/offsite_seal.go | — | Storing / reading the sub-account password | **Sealed AES-256-GCM; no key → refused (fail-closed).** Under `go test` every store gets a fixed key (`testing.Testing()`); production needs `OFFSITE_SECRET_KEY`. Never serve the value to a box. |
|
||||
| `(*Store).sealAtRest` / `openAtRest` / `sealAPIKey` / `apiKeyHash` / `SealLegacyBoxSecrets` | hub/internal/store/r879_box_seal.go | — | Any box-facing secret column (`hosts.api_key`, `customer_configs.api_key` / `retrieval_password`, `host_pbs_secrets.value`) | **R-879: same seal; a looked-up key is matched on `api_key_hash`, never opened** — box auth needs no sealing key. A sealed value that does not open sets `SecretsUnreadable` (field ""): serve/compare paths 500 on it and `SaveCustomerConfig` / `UpsertHost` refuse it (a load-modify-save would blank the secret). A new writer of an API key must write the hash in the same statement (`sealAPIKey`). Pinned by `store/r879_box_seal_test.go`, `api/r879_box_seal_test.go`. |
|
||||
|
||||
|
||||
File diff suppressed because it is too large.
Load diff
@@ -0,0 +1,50 @@
|
||||
#!/usr/bin/env python3
|
||||
"""healthlog.py <until-ISO-UTC> — R-1344 spike (Part 2, 2026-10-29): every 30 s, read each test box controller's Docker
|
||||
health record (`docker inspect -f '{{json .State.Health}}' felhom-controller`, the probe Docker runs every 30 s:
|
||||
`curl -f localhost:8080/api/health`, timeout 5 s) and append every NEW probe (keyed by its start time) to a CSV:
|
||||
box, start, end, duration_ms, exit_code, status, failing_streak, container_started. Read-only; nothing on a box changes."""
|
||||
import csv, json, os, subprocess, sys, time
|
||||
from datetime import datetime, timezone
|
||||
|
||||
UNTIL = datetime.fromisoformat(sys.argv[1].replace("Z", "+00:00"))
|
||||
OUT = os.path.join(os.path.dirname(os.path.abspath(__file__)), "health.csv")
|
||||
BOXES = {"tester-1": ["ssh", "-o", "BatchMode=yes", "-o", "ConnectTimeout=10", "root@192.168.0.154"],
|
||||
"demo-hp": ["ssh", "-o", "BatchMode=yes", "-o", "ConnectTimeout=10", "hp"]}
|
||||
seen = {b: set() for b in BOXES}
|
||||
new = not os.path.exists(OUT)
|
||||
f = open(OUT, "a", newline="")
|
||||
w = csv.writer(f)
|
||||
if new:
|
||||
w.writerow(["box", "start", "end", "duration_ms", "exit_code", "status", "failing_streak", "container_started", "read_at"])
|
||||
|
||||
|
||||
def ts(s):
|
||||
# Docker: 2026-10-29T11:11:37.145382734Z (nanoseconds) → microseconds for fromisoformat
|
||||
s = s.rstrip("Z")
|
||||
if "." in s:
|
||||
a, b = s.split(".", 1)
|
||||
s = a + "." + (b + "000000")[:6]
|
||||
return datetime.fromisoformat(s).replace(tzinfo=timezone.utc)
|
||||
|
||||
|
||||
while datetime.now(timezone.utc) < UNTIL:
|
||||
for box, ssh in BOXES.items():
|
||||
now = datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ")
|
||||
try:
|
||||
r = subprocess.run(ssh + ["pct exec 9201 -- docker inspect -f '{{json .State.Health}}|{{.State.StartedAt}}' felhom-controller"],
|
||||
capture_output=True, text=True, timeout=40)
|
||||
line = [l for l in r.stdout.splitlines() if l.startswith("{")]
|
||||
if not line:
|
||||
w.writerow([box, "", "", "", "", "READ-FAILED", "", "", now]); f.flush(); continue
|
||||
health, started = line[0].rsplit("|", 1)
|
||||
h = json.loads(health)
|
||||
for e in h.get("Log") or []:
|
||||
if e["Start"] in seen[box]:
|
||||
continue
|
||||
seen[box].add(e["Start"])
|
||||
d = (ts(e["End"]) - ts(e["Start"])).total_seconds() * 1000
|
||||
w.writerow([box, e["Start"][:23], e["End"][:23], round(d), e["ExitCode"], h.get("Status"), h.get("FailingStreak"), started[:19], now])
|
||||
f.flush()
|
||||
except Exception as ex: # a read that fails is a row, never a silent gap
|
||||
w.writerow([box, "", "", "", "", "READ-ERROR " + type(ex).__name__, "", "", now]); f.flush()
|
||||
time.sleep(30)
|
||||
@@ -0,0 +1,89 @@
|
||||
# hub access log 2026-10-20 .. 2026-10-30 09:26 UTC: every request over 4 s except /api/v1/wait (long poll). Client addresses removed.
|
||||
2026-10-20T09:32:16Z POST /configuration/artifacts 303 43537ms
|
||||
2026-10-20T09:46:04Z GET /apps 200 10515ms
|
||||
2026-10-20T12:11:01Z POST /configs/Tester4/edit 303 75400ms
|
||||
2026-10-21T09:13:02Z POST /api/v1/host-enroll 201 11075ms
|
||||
2026-10-21T12:03:50Z POST /api/v1/host-enroll 201 7973ms
|
||||
2026-10-21T18:33:27Z POST /api/v1/host-enroll 201 11191ms
|
||||
2026-10-22T02:30:00Z POST /api/v1/report 500 4911ms
|
||||
2026-10-22T02:30:06Z POST /api/v1/report 500 4408ms
|
||||
2026-10-22T02:30:08Z POST /api/v1/report 500 4507ms
|
||||
2026-10-22T02:30:10Z POST /api/v1/report 500 4435ms
|
||||
2026-10-22T02:30:16Z POST /api/v1/report 500 4787ms
|
||||
2026-10-22T02:30:18Z POST /api/v1/report 500 4534ms
|
||||
2026-10-22T02:30:19Z POST /api/v1/report 500 4921ms
|
||||
2026-10-22T02:30:26Z POST /api/v1/report 500 4754ms
|
||||
2026-10-22T02:30:27Z POST /api/v1/report 500 4711ms
|
||||
2026-10-22T07:56:23Z POST /configuration/artifacts 303 37822ms
|
||||
2026-10-22T09:41:17Z GET /apps 200 26162ms
|
||||
2026-10-22T12:55:56Z POST /configs/Tester-2/reset 303 9013ms
|
||||
2026-10-22T19:13:00Z POST /api/v1/host-enroll 201 8382ms
|
||||
2026-10-23T07:58:04Z POST /configuration/artifacts 303 42136ms
|
||||
2026-10-23T09:03:00Z GET /apps 200 16536ms
|
||||
2026-10-23T12:32:59Z GET / 200 4524ms
|
||||
2026-10-23T15:43:08Z GET /customers/demo-felhom 200 17970ms
|
||||
2026-10-23T15:43:09Z GET /customers/demo-hp 200 33387ms
|
||||
2026-10-23T15:59:35Z GET /customers/demo-hp 200 5317ms
|
||||
2026-10-23T16:21:36Z GET /customers/demo-hp 200 6618ms
|
||||
2026-10-23T16:34:14Z GET /customers/demo-hp 200 30839ms
|
||||
2026-10-23T16:45:06Z GET /customers/demo-hp 200 4879ms
|
||||
2026-10-23T16:57:39Z GET /customers/demo-hp 200 10595ms
|
||||
2026-10-23T17:17:34Z GET /customers/demo-hp 200 20203ms
|
||||
2026-10-23T17:28:17Z GET /customers/demo-hp 200 72876ms
|
||||
2026-10-23T17:29:17Z GET /customers/demo-hp 200 12882ms
|
||||
2026-10-23T17:30:31Z GET /customers/demo-hp 200 47569ms
|
||||
2026-10-23T18:02:27Z POST /api/v1/host-report 200 7798ms
|
||||
2026-10-23T18:02:24Z GET /customers/demo-hp 200 60175ms
|
||||
2026-10-23T18:03:24Z GET /customers/demo-hp 200 4785ms
|
||||
2026-10-23T18:48:37Z GET /customers/demo-hp 200 4428ms
|
||||
2026-10-23T19:10:34Z GET /customers/demo-hp 200 5073ms
|
||||
2026-10-24T00:02:54Z POST /api/v1/host-report 200 6025ms
|
||||
2026-10-24T02:30:28Z POST /api/v1/report 500 4881ms
|
||||
2026-10-24T02:30:38Z POST /api/v1/report 200 4914ms
|
||||
2026-10-24T05:33:00Z GET /customers/demo-hp 200 21436ms
|
||||
2026-10-24T06:02:27Z POST /api/v1/host-report 200 8684ms
|
||||
2026-10-24T06:32:27Z POST /api/v1/host-report 200 5699ms
|
||||
2026-10-24T07:44:29Z POST /configuration/artifacts 303 28888ms
|
||||
2026-10-24T08:29:29Z GET /configuration 200 4122ms
|
||||
2026-10-24T12:02:43Z POST /api/v1/host-report 200 4484ms
|
||||
2026-10-24T12:43:13Z POST /api/v1/host-enroll 201 11177ms
|
||||
2026-10-25T00:32:43Z POST /api/v1/host-report 200 6303ms
|
||||
2026-10-25T01:02:43Z POST /api/v1/host-report 200 4714ms during-db-snapshot
|
||||
2026-10-25T07:00:51Z POST /api/v1/host-report 200 6442ms during-db-snapshot
|
||||
2026-10-25T07:02:43Z POST /api/v1/host-report 200 6306ms during-db-snapshot
|
||||
2026-10-25T13:02:43Z POST /api/v1/host-report 200 4561ms during-db-snapshot
|
||||
2026-10-25T13:32:43Z POST /api/v1/host-report 200 5223ms
|
||||
2026-10-25T16:02:43Z POST /api/v1/host-report 200 4921ms
|
||||
2026-10-25T16:51:48Z POST /api/v1/host-enroll 201 8096ms
|
||||
2026-10-25T17:38:09Z POST /configuration/artifacts 303 39987ms
|
||||
2026-10-25T19:03:06Z POST /api/v1/host-report 200 4626ms during-db-snapshot
|
||||
2026-10-25T19:24:57Z POST /api/v1/host-enroll 201 8201ms
|
||||
2026-10-26T09:04:22Z POST /configuration/artifacts 303 33643ms
|
||||
2026-10-26T09:18:23Z POST /api/v1/host-report 200 4010ms
|
||||
2026-10-26T09:25:31Z POST /configuration/artifacts 303 52286ms
|
||||
2026-10-26T09:30:41Z POST /api/v1/host-enroll 201 11416ms
|
||||
2026-10-26T11:40:34Z POST /api/v1/host-report 200 6146ms
|
||||
2026-10-26T11:51:49Z POST /api/v1/host-enroll 201 7871ms
|
||||
2026-10-26T19:03:23Z POST /api/v1/host-report 200 6178ms during-db-snapshot
|
||||
2026-10-26T19:03:51Z GET /system 200 5775ms during-db-snapshot
|
||||
2026-10-26T20:00:22Z POST /api/v1/host-enroll 201 8343ms
|
||||
2026-10-27T07:46:39Z GET /apps 200 25055ms
|
||||
2026-10-27T13:01:41Z POST /api/v1/host-report 200 5775ms during-db-snapshot
|
||||
2026-10-27T13:03:40Z POST /api/v1/host-report 200 5178ms during-db-snapshot
|
||||
2026-10-27T14:07:05Z GET /apps/romm 200 28984ms
|
||||
2026-10-27T15:43:01Z POST /configuration/artifacts 303 36396ms
|
||||
2026-10-27T19:03:15Z GET /customers/tester-1 200 8853ms during-db-snapshot
|
||||
2026-10-27T19:31:40Z POST /api/v1/host-report 200 4341ms
|
||||
2026-10-27T19:42:14Z GET /customers/tester-1 200 7418ms
|
||||
2026-10-28T07:20:13Z GET /apps 200 30182ms
|
||||
2026-10-28T19:03:40Z POST /api/v1/host-report 200 7081ms during-db-snapshot
|
||||
2026-10-29T01:03:39Z POST /api/v1/host-report 200 9871ms during-db-snapshot
|
||||
2026-10-29T03:30:45Z POST /api/v1/report 500 4707ms
|
||||
2026-10-29T07:04:01Z POST /api/v1/host-report 200 5959ms during-db-snapshot
|
||||
2026-10-29T09:21:19Z POST /configuration/artifacts 303 36965ms
|
||||
2026-10-29T10:49:16Z GET /customers/tester-1 200 7823ms
|
||||
2026-10-29T13:04:27Z POST /api/v1/host-report 200 4281ms during-db-snapshot
|
||||
2026-10-29T13:03:19Z POST /configuration/artifacts 303 170022ms during-db-snapshot
|
||||
2026-10-29T13:06:12Z POST /api/v1/host-report 200 4677ms
|
||||
2026-10-29T13:04:59Z POST /configuration/artifacts 303 170431ms during-db-snapshot
|
||||
2026-10-29T17:57:10Z POST /configuration/artifacts 303 38255ms
|
||||
@@ -0,0 +1,4 @@
|
||||
09:45:54.873451 PROBE exec 6041ms err=<nil>: CREATE INDEX IF NOT EXISTS idx_reports_received ON reports(received_at)
|
||||
09:46:29.076951 PROBE exec 34203ms err=<nil>: CREATE INDEX IF NOT EXISTS idx_host_reports_received ON host_reports(received_at)
|
||||
09:46:35.123934 PROBE exec 6046ms err=<nil>: CREATE INDEX IF NOT EXISTS idx_reports_controller_version ON reports(controller_version)
|
||||
09:46:52.169596 PROBE exec 17045ms err=<nil>: CREATE INDEX IF NOT EXISTS idx_host_reports_agent_version ON host_reports(host_id, agent_version, received_at)
|
||||
@@ -0,0 +1,14 @@
|
||||
# Pages (4 KiB) read per statement, cold cache (cache_size 2 MB), on a copy of hub.db (snapshot 2026-10-30 07:00Z,
|
||||
# 572 MB) in tmpfs on DooPlex. Before = live schema; after = with the four R-1346 indexes / the INDEXED BY hint.
|
||||
statement before after
|
||||
NewestReportedControllerVersion (vouch) 35623 90
|
||||
HostAgentVersionsSeen demo-hp (OS alarm) 38570 118
|
||||
Prune: DELETE reports (in the write lock) 16538 309
|
||||
Prune: DELETE host_reports (write lock) 13559 704
|
||||
GetFleetAppSummary 7 d (apps page) 15404 1437
|
||||
# Table sizes: host_reports 327 MB (19 928 rows), reports 139 MB (21 742 rows), app_telemetry 33 MB (123 115 rows).
|
||||
# controller_version and agent_version sit AFTER report_json in their rows: reading them walks the JSON's overflow pages.
|
||||
# VACUUM INTO (the 6-hourly snapshot) while 9 600 writes ran on the same copy: the slowest write 1.5 ms — the snapshot
|
||||
# takes no write lock; its cost on the live hub is 3 min of disk load (570 MB read + 570 MB written on Longhorn).
|
||||
# Hub pod cgroup 2026-10-30 09:3x: memory.current 268 013 568 of max 268 435 456 (anon 85 MB, file cache 177 MB);
|
||||
# cpu.stat nr_throttled 45 419 of 85 460 periods.
|
||||
@@ -0,0 +1,40 @@
|
||||
09:49:31.734919 PROBE open+migrate 133ms
|
||||
09:49:32.101110 PROBE round 1 GET /apps 354ms
|
||||
09:49:33.424375 [WARN] slow statement: 1281ms (over 200ms): SELECT customer_id, received_at, report_json, health_status, cpu_percent, memory_percent, container_total, container_running, backup_last_sn
|
||||
09:49:34.451805 [WARN] slow statement: 801ms (over 200ms): SELECT app_name, memory_current_mb FROM app_telemetry WHERE customer_id = ? AND reported_at = ( SELECT MAX(reported_at) FROM app_telemetry at
|
||||
09:49:34.667219 PROBE round 1 GET /customers/demo-hp 2566ms
|
||||
09:49:34.944156 PROBE round 1 GET /customers/tester-1 276ms
|
||||
09:49:35.456023 PROBE round 1 GET /customers/demo-felhom 511ms
|
||||
09:49:35.456067 PROBE status 503
|
||||
09:49:35.456070 PROBE round 1 GET /system 0ms
|
||||
09:49:35.459787 PROBE round 1 GET /configuration 3ms
|
||||
09:49:35.499965 PROBE round 1 GET /hosts 40ms
|
||||
09:49:35.634127 PROBE round 1 GET /hosts/demo-hp-bb76ea 134ms
|
||||
09:49:35.659077 PROBE round 1 GET / 24ms
|
||||
09:49:35.659403 PROBE status 302
|
||||
09:49:35.659410 PROBE round 1 GET /configs/demo-hp/edit 0ms
|
||||
09:49:35.668200 PROBE round 1 NewestReportedControllerVersion 8ms
|
||||
09:49:35.675024 PROBE round 1 HostAgentVersionsSeen demo-hp-bb76ea 6ms
|
||||
09:49:35.677130 PROBE round 1 HostAgentVersionsSeen tester-1-d70be4 2ms
|
||||
09:49:35.683713 PROBE round 1 HostAgentVersionsSeen demo-felhom-8363b5 6ms
|
||||
09:49:35.978921 PROBE round 1 GetFleetAppSummary 7d 295ms
|
||||
09:49:35.983219 PROBE round 1 SetArtifactManifest (same values) 4ms
|
||||
09:49:36.277407 PROBE round 2 GET /apps 294ms
|
||||
09:49:37.372406 [WARN] slow statement: 891ms (over 200ms): SELECT app_name, memory_current_mb FROM app_telemetry WHERE customer_id = ? AND reported_at = ( SELECT MAX(reported_at) FROM app_telemetry at
|
||||
09:49:37.630653 PROBE round 2 GET /customers/demo-hp 1353ms
|
||||
09:49:37.874249 PROBE round 2 GET /customers/tester-1 243ms
|
||||
09:49:38.270422 PROBE round 2 GET /customers/demo-felhom 396ms
|
||||
09:49:38.270457 PROBE status 503
|
||||
09:49:38.270460 PROBE round 2 GET /system 0ms
|
||||
09:49:38.271677 PROBE round 2 GET /configuration 1ms
|
||||
09:49:38.284324 PROBE round 2 GET /hosts 12ms
|
||||
09:49:38.381573 PROBE round 2 GET /hosts/demo-hp-bb76ea 97ms
|
||||
09:49:38.445815 PROBE round 2 GET / 64ms
|
||||
09:49:38.446021 PROBE status 302
|
||||
09:49:38.446024 PROBE round 2 GET /configs/demo-hp/edit 0ms
|
||||
09:49:38.450512 PROBE round 2 NewestReportedControllerVersion 4ms
|
||||
09:49:38.455056 PROBE round 2 HostAgentVersionsSeen demo-hp-bb76ea 4ms
|
||||
09:49:38.456489 PROBE round 2 HostAgentVersionsSeen tester-1-d70be4 1ms
|
||||
09:49:38.461097 PROBE round 2 HostAgentVersionsSeen demo-felhom-8363b5 4ms
|
||||
09:49:38.776043 PROBE round 2 GetFleetAppSummary 7d 314ms
|
||||
09:49:38.780616 PROBE round 2 SetArtifactManifest (same values) 4ms
|
||||
@@ -0,0 +1,23 @@
|
||||
09:32:28.144871 PROBE open+migrate 75ms
|
||||
09:32:28.766883 [WARN] slow statement: 608ms (over 200ms): SELECT app_name, MAX(display_name) as display_name, COUNT(DISTINCT customer_id) as deployment_count, AVG(memory_avg_mb) as avg_memory_mb, MAX
|
||||
09:32:28.975341 PROBE round 1 GET /apps 817ms
|
||||
09:32:30.483608 [WARN] slow statement: 1421ms (over 200ms): SELECT customer_id, received_at, report_json, health_status, cpu_percent, memory_percent, container_total, container_running, backup_last_sn
|
||||
09:32:30.867327 [WARN] slow statement: 288ms (over 200ms): SELECT app_name, MAX(display_name), AVG(memory_avg_mb), MAX(memory_peak_mb), MAX(catalog_limit), SUM(log_errors), SUM(log_warnings) FROM app_
|
||||
09:32:31.574715 [WARN] slow statement: 707ms (over 200ms): SELECT app_name, memory_current_mb FROM app_telemetry WHERE customer_id = ? AND reported_at = ( SELECT MAX(reported_at) FROM app_telemetry at
|
||||
09:32:31.835182 PROBE round 1 GET /customers/demo-hp 2859ms
|
||||
09:32:32.244337 PROBE round 1 GET /customers/tester-1 409ms
|
||||
09:32:32.850731 PROBE round 1 GET /customers/demo-felhom 606ms
|
||||
09:32:32.850785 PROBE status 503
|
||||
09:32:32.850790 PROBE round 1 GET /system 0ms
|
||||
09:32:32.854546 PROBE round 1 GET /configuration 3ms
|
||||
09:32:32.873188 PROBE round 1 GET /hosts 18ms
|
||||
09:32:32.958115 PROBE round 1 GET /hosts/demo-hp-bb76ea 84ms
|
||||
09:32:33.012363 PROBE round 1 GET / 54ms
|
||||
09:32:33.012600 PROBE status 302
|
||||
09:32:33.012604 PROBE round 1 GET /configs/demo-hp/edit 0ms
|
||||
09:32:34.739534 [WARN] slow statement: 1726ms (over 200ms): SELECT DISTINCT controller_version FROM reports WHERE controller_version IS NOT NULL AND controller_version != ''
|
||||
09:32:34.739561 PROBE round 1 NewestReportedControllerVersion 1726ms
|
||||
09:38:16.145431 [WARN] slow statement: 341405ms (over 200ms): SELECT COALESCE(agent_version, ''), MIN(received_at) FROM host_reports WHERE host_id = ? GROUP BY agent_version
|
||||
09:38:16.145497 PROBE round 1 HostAgentVersionsSeen demo-hp-bb76ea 341405ms
|
||||
09:40:30.083495 [WARN] slow statement: 133937ms (over 200ms): SELECT COALESCE(agent_version, ''), MIN(received_at) FROM host_reports WHERE host_id = ? GROUP BY agent_version
|
||||
09:40:30.083533 PROBE round 1 HostAgentVersionsSeen tester-1-d70be4 133938ms
|
||||
+27
-1
@@ -1,4 +1,30 @@
|
||||
## Unreleased — R-1344: the agent's restart of a controller that does not answer
|
||||
## v0.178.0 (2026-10-30) — the hub's database speed (R-1346); the agent's restart of a controller that does not answer (R-1344)
|
||||
|
||||
- **R-1346 — measured, then fixed (evidence `documentation/audits/release-2026-10-30/p2-r1346/`).** The hub pod has
|
||||
256 MiB for a 570 MB database, so nearly every page read goes to the network disk; five statements read whole tables:
|
||||
- the vouch save's fleet check (`NewestReportedControllerVersion`, `store.go`): `controller_version` sits after
|
||||
`report_json`, so the DISTINCT walked every report's JSON — 35 623 pages → **90** with
|
||||
`idx_reports_controller_version` (in the pod: 1 726 ms → 8 ms; live it was 38 s, 170 s during the 13:00Z snapshot);
|
||||
- the hourly OS alarm's `HostAgentVersionsSeen` (`os_updates.go`, only for a box with no healthy OS report): 38 570
|
||||
pages in random order → **118** with `idx_host_reports_agent_version` (in the pod: 341 s → 6 ms);
|
||||
- the 04:30 prune (`Prune`): both DELETEs scanned their whole table INSIDE the write lock — 39 s on 2026-10-30, a
|
||||
controller report refused „database is locked" meanwhile — 30 097 pages → **1 013** with `idx_reports_received` and
|
||||
`idx_host_reports_received`;
|
||||
- the apps page (`GetFleetAppSummary`): the planner walked every telemetry row by app name — 15 404 pages → **1 437**
|
||||
with `INDEXED BY idx_app_telemetry_prune` (in the pod: 817 ms → 354 ms).
|
||||
The four indexes are built once at the first start (63 s measured on a copy in the pod; the startup probe allows 180
|
||||
s, R-1326). The SQL lives in `r1346_speed.go`; `TestR1346_HeavyStatementsUseTheirIndex` pins each plan (red first),
|
||||
`TestR1346_BehaviourUnchanged` the results.
|
||||
- **The vouch's manifest save is ONE transaction** (seven upserts, one commit): one sync on the network disk, and the
|
||||
vouch is saved whole or not at all.
|
||||
- **The slow-statement line** (`timeddriver.go`): every statement over 1 s is logged as `[WARN] slow statement: <ms>
|
||||
(over 1s): <SQL text>` — the SQL only, never the bound values (`TestTimedDriver_ASlowStatementIsNamedNeverItsValues`,
|
||||
3 mutants killed). A slow BEGIN is named as a wait for the write lock.
|
||||
- **Measured, not changed:** the 6-hourly snapshot (`VACUUM INTO`, 3 min) takes NO write lock — 9 600 writes ran during
|
||||
one on a copy, the slowest 1.5 ms; its cost is 3 minutes of disk load on the hub's volume, which is why the two
|
||||
170-s vouch saves at 13:03Z were 4× slower than the others.
|
||||
|
||||
### Also in this release — R-1344: the agent's restart of a controller that does not answer
|
||||
|
||||
- **`controller_unresponsive_restart`** (warning, operator-only; in `allowedEventTypes` and `operatorOnlyEvents`, pinned
|
||||
by `TestControllerSupervisorEventsAreAllowlistedAndOperatorOnly`): mailed when the stanza's `unresponsive_restart_at`
|
||||
|
||||
@@ -414,7 +414,7 @@ func (s *Store) SetOSAlarmRaised(key string, t time.Time) error {
|
||||
// HostAgentVersionsSeen returns, per agent version a host ever reported, the first time it was seen (the stale-leg
|
||||
// alarm's start point for a box whose agent CAN run the OS leg but never reported one).
|
||||
func (s *Store) HostAgentVersionsSeen(hostID string) (map[string]time.Time, error) {
|
||||
rows, err := s.db.Query(`SELECT COALESCE(agent_version, ''), MIN(received_at) FROM host_reports WHERE host_id = ? GROUP BY agent_version`, hostID)
|
||||
rows, err := s.db.Query(queryHostAgentVersionsSeen, hostID)
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
|
||||
@@ -0,0 +1,71 @@
|
||||
package store
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"time"
|
||||
)
|
||||
|
||||
// R-1346 (2026-10-30): the statements the measurement named, in one place so the plan test reads the exact SQL the
|
||||
// code runs (r1346_speed_test.go TestR1346_HeavyStatementsUseTheirIndex).
|
||||
|
||||
// queryNewestControllerVersion — the vouch save's R-120 fleet check (configs.go handleSetArtifacts).
|
||||
const queryNewestControllerVersion = `SELECT DISTINCT controller_version FROM reports WHERE controller_version IS NOT NULL AND controller_version != ''`
|
||||
|
||||
// queryHostAgentVersionsSeen — the hourly OS alarm, for a box with no healthy OS report.
|
||||
const queryHostAgentVersionsSeen = `SELECT COALESCE(agent_version, ''), MIN(received_at) FROM host_reports WHERE host_id = ? GROUP BY agent_version`
|
||||
|
||||
// queryPruneReports / queryPruneHostReports — the 04:30 retention prune (Prune).
|
||||
const (
|
||||
queryPruneReports = `DELETE FROM reports WHERE received_at < ?`
|
||||
queryPruneHostReports = `DELETE FROM host_reports WHERE received_at < ?`
|
||||
)
|
||||
|
||||
// queryFleetAppSummary — the apps page (GetFleetAppSummary).
|
||||
const queryFleetAppSummary = `
|
||||
SELECT app_name,
|
||||
MAX(display_name) as display_name,
|
||||
COUNT(DISTINCT customer_id) as deployment_count,
|
||||
AVG(memory_avg_mb) as avg_memory_mb,
|
||||
MAX(memory_peak_mb) as peak_memory_mb,
|
||||
AVG(cpu_avg_percent) as avg_cpu,
|
||||
SUM(log_errors) as total_errors,
|
||||
SUM(log_warnings) as total_warnings,
|
||||
MAX(catalog_estimate) as catalog_estimate,
|
||||
MAX(catalog_limit) as catalog_limit
|
||||
FROM app_telemetry INDEXED BY idx_app_telemetry_prune
|
||||
WHERE reported_at > ?
|
||||
GROUP BY app_name
|
||||
ORDER BY deployment_count DESC, avg_memory_mb DESC`
|
||||
|
||||
// r1346Indexes lets the statements above read only what they need. controller_version and agent_version sit AFTER
|
||||
// report_json in their rows, so without an index every read of them walks each row's whole JSON (overflow pages);
|
||||
// received_at has no index of its own, so the prune scanned both tables INSIDE its write lock (39 s on 2026-10-30,
|
||||
// and a controller report refused with „database is locked" meanwhile). Built once, at the first start that has them:
|
||||
// 63 s measured on a copy of the live database in the hub pod (256 MiB) — inside the startup probe's 180 s with the
|
||||
// measured 31–36 s start (R-1326).
|
||||
var r1346Indexes = []struct{ name, ddl string }{
|
||||
{"idx_reports_received", `CREATE INDEX IF NOT EXISTS idx_reports_received ON reports(received_at)`},
|
||||
{"idx_host_reports_received", `CREATE INDEX IF NOT EXISTS idx_host_reports_received ON host_reports(received_at)`},
|
||||
{"idx_reports_controller_version", `CREATE INDEX IF NOT EXISTS idx_reports_controller_version ON reports(controller_version)`},
|
||||
{"idx_host_reports_agent_version", `CREATE INDEX IF NOT EXISTS idx_host_reports_agent_version ON host_reports(host_id, agent_version, received_at)`},
|
||||
}
|
||||
|
||||
func (s *Store) migrateR1346Indexes() error {
|
||||
for _, ix := range r1346Indexes {
|
||||
var n int
|
||||
if err := s.db.QueryRow(`SELECT COUNT(*) FROM sqlite_master WHERE type = 'index' AND name = ?`, ix.name).Scan(&n); err != nil {
|
||||
return err
|
||||
}
|
||||
if n > 0 {
|
||||
continue
|
||||
}
|
||||
began := time.Now()
|
||||
if _, err := s.db.Exec(ix.ddl); err != nil {
|
||||
return fmt.Errorf("%s: %w", ix.name, err)
|
||||
}
|
||||
if s.logger != nil {
|
||||
s.logger.Printf("[INFO] store: index %s built in %s (R-1346, once)", ix.name, time.Since(began).Round(time.Millisecond))
|
||||
}
|
||||
}
|
||||
return nil
|
||||
}
|
||||
@@ -0,0 +1,123 @@
|
||||
package store
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"log"
|
||||
"strings"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
|
||||
// R-1346 (2026-10-30): the statements the measurement named read whole tables on the hub's network disk — in the pod,
|
||||
// with 256 MiB for a 570 MB database, nearly every page is a disk read. Each is pinned to the plan that reads only what
|
||||
// it needs. A plan is the mechanism; the consequence was measured on a copy of the live database (pages read, before
|
||||
// → after): the vouch's fleet check 35 623 → 90, the OS alarm's agent versions 38 570 → 118, the night prune 30 097 →
|
||||
// 1 013 (read INSIDE its write lock), the apps page 15 404 → 1 437. RED-PROOF: each seen failing before its index /
|
||||
// hint existed.
|
||||
|
||||
func planOf(t *testing.T, s *Store, query string, args ...any) string {
|
||||
t.Helper()
|
||||
rows, err := s.db.Query("EXPLAIN QUERY PLAN "+query, args...)
|
||||
if err != nil {
|
||||
t.Fatalf("explain %q: %v", query, err)
|
||||
}
|
||||
defer rows.Close()
|
||||
var out []string
|
||||
for rows.Next() {
|
||||
var id, parent, notused int
|
||||
var detail string
|
||||
if err := rows.Scan(&id, &parent, ¬used, &detail); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
out = append(out, detail)
|
||||
}
|
||||
return strings.Join(out, " | ")
|
||||
}
|
||||
|
||||
func TestR1346_HeavyStatementsUseTheirIndex(t *testing.T) {
|
||||
s := newTestStore(t)
|
||||
cutoff := "2026-08-01 00:00:00"
|
||||
for _, tc := range []struct {
|
||||
name, query, want string
|
||||
args []any
|
||||
}{
|
||||
{"the vouch's fleet check (NewestReportedControllerVersion)", queryNewestControllerVersion, "COVERING INDEX idx_reports_controller_version", nil},
|
||||
{"the OS alarm's agent versions (HostAgentVersionsSeen)", queryHostAgentVersionsSeen, "COVERING INDEX idx_host_reports_agent_version", []any{"h1"}},
|
||||
{"the prune of reports", queryPruneReports, "INDEX idx_reports_received", []any{cutoff}},
|
||||
{"the prune of host reports", queryPruneHostReports, "INDEX idx_host_reports_received", []any{cutoff}},
|
||||
{"the apps page (GetFleetAppSummary)", queryFleetAppSummary, "INDEX idx_app_telemetry_prune", []any{time.Now()}},
|
||||
} {
|
||||
plan := planOf(t, s, tc.query, tc.args...)
|
||||
if !strings.Contains(plan, tc.want) {
|
||||
t.Errorf("%s: plan %q — want %q (a whole-table read on the network disk)", tc.name, plan, tc.want)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// The behaviour around the plans is unchanged: the newest valid version wins (an rc never does), the prune still
|
||||
// removes exactly the old rows, the manifest still round-trips.
|
||||
func TestR1346_BehaviourUnchanged(t *testing.T) {
|
||||
s := newTestStore(t)
|
||||
for _, v := range []string{"0.340.0", "0.349.0", "0.350.0-rc.1", "", "0.348.2"} {
|
||||
if _, err := s.db.Exec(`INSERT INTO reports (customer_id, report_json, controller_version) VALUES ('c1', '{}', ?)`, v); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
if got := s.NewestReportedControllerVersion(); got != "v0.349.0" && got != "0.349.0" {
|
||||
t.Fatalf("newest = %q, want 0.349.0", got)
|
||||
}
|
||||
if _, err := s.db.Exec(`INSERT INTO reports (customer_id, report_json, received_at) VALUES ('c1', '{}', '2020-01-01 00:00:00')`); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if _, err := s.db.Exec(`INSERT INTO host_reports (host_id, customer_id, report_json, received_at, agent_version) VALUES ('h1', 'c1', '{}', '2020-01-01 00:00:00', '0.100.0'), ('h1', 'c1', '{}', datetime('now'), '0.170.0')`); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
seen, err := s.HostAgentVersionsSeen("h1")
|
||||
if err != nil || len(seen) != 2 {
|
||||
t.Fatalf("agent versions seen = %v, %v", seen, err)
|
||||
}
|
||||
n, err := s.Prune(90)
|
||||
if err != nil || n != 2 {
|
||||
t.Fatalf("prune removed %d (%v), want the 2 old rows", n, err)
|
||||
}
|
||||
m := ArtifactManifest{AgentVersion: "0.171.0", AgentSHA256: "aa", GoldenVersion: "0.349.0", GoldenSHA256: "bb", MinAgent: "0.158.1", WrapperSHA256: "cc", BundleSHA256: "dd"}
|
||||
if err := s.SetArtifactManifest(m); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
if got := s.GetArtifactManifest(); got != m {
|
||||
t.Fatalf("manifest round trip: %+v, want %+v", got, m)
|
||||
}
|
||||
}
|
||||
|
||||
// The slow-statement line names the statement — and never the values bound to it (they can be customer data).
|
||||
func TestTimedDriver_ASlowStatementIsNamedNeverItsValues(t *testing.T) {
|
||||
s := newTestStore(t)
|
||||
var buf bytes.Buffer
|
||||
old := statementLogger.Load()
|
||||
statementLogger.Store(log.New(&buf, "", 0))
|
||||
SetSlowStatementThreshold(0)
|
||||
defer func() { statementLogger.Store(old); SetSlowStatementThreshold(time.Second) }()
|
||||
|
||||
if _, err := s.db.Exec(`INSERT INTO hub_settings (key, value, updated_at) VALUES (?, ?, datetime('now'))`, "r1346-key", "SECRET-VALUE-42"); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
var v string
|
||||
if err := s.db.QueryRow(`SELECT value FROM hub_settings WHERE key = ?`, "r1346-key").Scan(&v); err != nil || v != "SECRET-VALUE-42" {
|
||||
t.Fatalf("read back %q, %v", v, err)
|
||||
}
|
||||
out := buf.String()
|
||||
if !strings.Contains(out, "slow statement:") || !strings.Contains(out, "INSERT INTO hub_settings") ||
|
||||
!strings.Contains(out, "SELECT value FROM hub_settings WHERE key = ?") {
|
||||
t.Fatalf("the statements are not named:\n%s", out)
|
||||
}
|
||||
if strings.Contains(out, "SECRET-VALUE-42") || strings.Contains(out, "r1346-key") {
|
||||
t.Fatalf("a bound VALUE reached the log:\n%s", out)
|
||||
}
|
||||
// Under the threshold: silent.
|
||||
buf.Reset()
|
||||
SetSlowStatementThreshold(time.Hour)
|
||||
_ = s.db.QueryRow(`SELECT 1`).Scan(&v)
|
||||
if buf.Len() != 0 {
|
||||
t.Fatalf("a fast statement was logged: %s", buf.String())
|
||||
}
|
||||
}
|
||||
+33
-20
@@ -97,10 +97,14 @@ const sqliteDSNParams = "?_pragma=journal_mode(WAL)&_pragma=busy_timeout(5000)&_
|
||||
|
||||
// New creates a new store and initializes the schema.
|
||||
func New(dbPath string, logger *log.Logger) (*Store, error) {
|
||||
db, err := sql.Open("sqlite", dbPath+sqliteDSNParams)
|
||||
// R-1346: the timed wrapper around modernc's "sqlite" driver — a statement over a second is logged (timeddriver.go).
|
||||
db, err := sql.Open(timedDriverName, dbPath+sqliteDSNParams)
|
||||
if err != nil {
|
||||
return nil, fmt.Errorf("opening database: %w", err)
|
||||
}
|
||||
if logger != nil {
|
||||
statementLogger.Store(logger)
|
||||
}
|
||||
|
||||
s := &Store{db: db, logger: logger}
|
||||
// Under `go test` ONLY (testing.Testing() is false in the production binary) every store gets a
|
||||
@@ -905,6 +909,10 @@ func (s *Store) migrate() error {
|
||||
if err := s.migrateHouseholdSaved(); err != nil {
|
||||
return fmt.Errorf("household_saved: %w", err)
|
||||
}
|
||||
// R-1346 (2026-10-30): the indexes the slow statements needed (r1346_speed.go).
|
||||
if err := s.migrateR1346Indexes(); err != nil {
|
||||
return fmt.Errorf("r1346 indexes: %w", err)
|
||||
}
|
||||
|
||||
return nil
|
||||
}
|
||||
@@ -1597,13 +1605,13 @@ func (s *Store) GetCustomerHistory(customerID string, since time.Duration) ([]Cu
|
||||
// Prune deletes reports older than the given number of days.
|
||||
func (s *Store) Prune(maxDays int) (int64, error) {
|
||||
cutoff := time.Now().AddDate(0, 0, -maxDays).Format("2006-01-02 15:04:05")
|
||||
res, err := s.db.Exec("DELETE FROM reports WHERE received_at < ?", cutoff)
|
||||
res, err := s.db.Exec(queryPruneReports, cutoff)
|
||||
if err != nil {
|
||||
return 0, err
|
||||
}
|
||||
n, _ := res.RowsAffected()
|
||||
// v0.7.0: prune the parallel host-domain report stream, same retention.
|
||||
if hres, herr := s.db.Exec("DELETE FROM host_reports WHERE received_at < ?", cutoff); herr == nil {
|
||||
if hres, herr := s.db.Exec(queryPruneHostReports, cutoff); herr == nil {
|
||||
hn, _ := hres.RowsAffected()
|
||||
n += hn
|
||||
}
|
||||
@@ -2216,7 +2224,7 @@ func (s *Store) GetGlobalMinControllerVersion() string {
|
||||
// here, so a golden baked behind an unreleased controller still passes. That is a real limit and it is
|
||||
// not the failure mode that has bitten — the three instances were all "deployed newer than baked".
|
||||
func (s *Store) NewestReportedControllerVersion() string {
|
||||
rows, err := s.db.Query(`SELECT DISTINCT controller_version FROM reports WHERE controller_version IS NOT NULL AND controller_version != ''`)
|
||||
rows, err := s.db.Query(queryNewestControllerVersion)
|
||||
if err != nil {
|
||||
return "" // unreadable → the gate degrades to "cannot compare", never to a false refusal
|
||||
}
|
||||
@@ -2393,25 +2401,30 @@ func (s *Store) GetArtifactManifest() ArtifactManifest {
|
||||
// SetArtifactManifest persists the operator-recorded current artifact set (all four fields). Each
|
||||
// field is stored independently so a partial form submission (e.g. agent only) still round-trips.
|
||||
func (s *Store) SetArtifactManifest(m ArtifactManifest) error {
|
||||
if err := s.setSetting(settingArtifactAgentVersion, m.AgentVersion); err != nil {
|
||||
// R-1346 (2026-10-30): ONE transaction — one commit (one sync on the network disk) instead of seven, and a vouch is
|
||||
// saved whole or not at all.
|
||||
tx, err := s.db.Begin()
|
||||
if err != nil {
|
||||
return err
|
||||
}
|
||||
if err := s.setSetting(settingArtifactAgentSHA256, m.AgentSHA256); err != nil {
|
||||
return err
|
||||
defer tx.Rollback() //nolint:errcheck // a no-op after Commit
|
||||
for _, kv := range [][2]string{
|
||||
{settingArtifactAgentVersion, m.AgentVersion},
|
||||
{settingArtifactAgentSHA256, m.AgentSHA256},
|
||||
{settingArtifactGoldenVersion, m.GoldenVersion},
|
||||
{settingArtifactGoldenSHA256, m.GoldenSHA256},
|
||||
{settingArtifactMinAgent, m.MinAgent},
|
||||
{settingArtifactWrapperSHA256, m.WrapperSHA256},
|
||||
{settingArtifactBundleSHA256, m.BundleSHA256},
|
||||
} {
|
||||
if _, err := tx.Exec(`
|
||||
INSERT INTO hub_settings (key, value, updated_at)
|
||||
VALUES (?, ?, datetime('now'))
|
||||
ON CONFLICT(key) DO UPDATE SET value = excluded.value, updated_at = datetime('now')`, kv[0], kv[1]); err != nil {
|
||||
return err
|
||||
}
|
||||
}
|
||||
if err := s.setSetting(settingArtifactGoldenVersion, m.GoldenVersion); err != nil {
|
||||
return err
|
||||
}
|
||||
if err := s.setSetting(settingArtifactGoldenSHA256, m.GoldenSHA256); err != nil {
|
||||
return err
|
||||
}
|
||||
if err := s.setSetting(settingArtifactMinAgent, m.MinAgent); err != nil {
|
||||
return err
|
||||
}
|
||||
if err := s.setSetting(settingArtifactWrapperSHA256, m.WrapperSHA256); err != nil {
|
||||
return err
|
||||
}
|
||||
return s.setSetting(settingArtifactBundleSHA256, m.BundleSHA256)
|
||||
return tx.Commit()
|
||||
}
|
||||
|
||||
// BundleBehindSince returns since when a box's config bundle has differed from the vouched one (zero = it matches, or
|
||||
|
||||
@@ -236,21 +236,7 @@ func min(a, b int) int {
|
||||
|
||||
// GetFleetAppSummary returns fleet-wide aggregate stats for all apps since the given time.
|
||||
func (s *Store) GetFleetAppSummary(since time.Time) ([]FleetAppSummary, error) {
|
||||
rows, err := s.db.Query(`
|
||||
SELECT app_name,
|
||||
MAX(display_name) as display_name,
|
||||
COUNT(DISTINCT customer_id) as deployment_count,
|
||||
AVG(memory_avg_mb) as avg_memory_mb,
|
||||
MAX(memory_peak_mb) as peak_memory_mb,
|
||||
AVG(cpu_avg_percent) as avg_cpu,
|
||||
SUM(log_errors) as total_errors,
|
||||
SUM(log_warnings) as total_warnings,
|
||||
MAX(catalog_estimate) as catalog_estimate,
|
||||
MAX(catalog_limit) as catalog_limit
|
||||
FROM app_telemetry
|
||||
WHERE reported_at > ?
|
||||
GROUP BY app_name
|
||||
ORDER BY deployment_count DESC, avg_memory_mb DESC`, since)
|
||||
rows, err := s.db.Query(queryFleetAppSummary, since)
|
||||
if err != nil {
|
||||
return nil, err
|
||||
}
|
||||
|
||||
@@ -0,0 +1,197 @@
|
||||
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()
|
||||
}
|
||||
Reference in new issue
Block a user