fix: distinguish SQLite integrity check time from gate waiting (#144746)

Preserve the existing gate total and outcome while measuring the actual synchronous callback and reporting the remaining elapsed time. Clear measurements on reused diagnostics and omit them for asynchronous child-process checks.

Five original-source attribution regressions, 57 focused tests, full changed checks and seven real Worker/SQLite boundary cases verify the split and unchanged admission lifecycle. No storage or configuration change. Closes #144725.

docs/logging.md

@@ -402,6 +402,16 @@ integrity check; resumed validation and repair can still run on the opener.
 Correlate the process ID with the log timestamp and current process; PIDs can be
 reused after exit.
 
+`integrityGateMs` covers the initial integrity check through admission
+revalidation and resumption. When the driver measures its synchronous integrity
+and foreign-key callback, `integrityCheckSyncMs` reports that callback's elapsed
+time and `integrityOutsideCheckMs` reports the remaining gate time. The two
+integer fields partition `integrityGateMs`; the remainder includes admission,
+IPC, scheduling, and revalidation, not just a parent queue wait. These are wall
+durations, not CPU time. A reclamation Worker can report this synchronous check
+while its `admissionMode` is `async`. An asynchronous child-process check leaves
+both fields absent because its parent cannot measure the callback itself.
+
 SQLite reclamation Workers also emit `slow SQLite reclamation Worker operation`
 at `warn` when their joined operation takes at least one second. The record is
 emitted after Worker exit and parent admission settlement. It includes the

src/infra/sqlite-integrity.test.ts

@@ -1,6 +1,7 @@
 import { fork } from "node:child_process";
 import fs from "node:fs";
 import path from "node:path";
+import { performance } from "node:perf_hooks";
 import type { DatabaseSync } from "node:sqlite";
 import { pathToFileURL } from "node:url";
 import { afterEach, describe, expect, it, vi } from "vitest";
@@ -13,6 +14,10 @@ import {
   assertSqliteIntegrity,
   confirmSqliteFileIntegrity,
   isTerminalSqliteIntegrityError,
+  runSqliteIntegrityOperationSync,
+  sqliteIntegrityCheckSteps,
+  type SqliteIntegrityDiagnostics,
+  type SqliteIntegrityOperation,
 } from "./sqlite-integrity.js";
 
 vi.mock("node:child_process", async (importOriginal) => {
@@ -197,6 +202,141 @@ describe("assertSqliteIntegrity", () => {
   });
 });
 
+describe("integrity gate attribution", () => {
+  afterEach(() => vi.restoreAllMocks());
+
+  function createTimedDatabase(checkMs: number, foreignKeyViolation = false) {
+    const database = new (requireNodeSqlite().DatabaseSync)(":memory:");
+    database.exec(`
+      PRAGMA foreign_keys = OFF;
+      CREATE TABLE parents (id INTEGER PRIMARY KEY);
+      CREATE TABLE children (parent_id INTEGER REFERENCES parents(id));
+      INSERT INTO parents VALUES (1);
+      INSERT INTO children VALUES (${foreignKeyViolation ? 2 : 1});
+    `);
+    let elapsedMs = 0;
+    const advance = (durationMs: number) => {
+      elapsedMs += durationMs;
+    };
+    vi.spyOn(performance, "now").mockImplementation(() => elapsedMs);
+    const prepare = database.prepare.bind(database);
+    vi.spyOn(database, "prepare").mockImplementation((sql) => {
+      const statement = prepare(sql);
+      if (sql === "PRAGMA integrity_check;") {
+        const all = statement.all.bind(statement);
+        vi.spyOn(statement, "all").mockImplementation((...parameters) => {
+          try {
+            return all(...parameters);
+          } finally {
+            advance(checkMs);
+          }
+        });
+      }
+      return statement;
+    });
+    return { database, advance };
+  }
+
+  it.each([
+    { label: "fractional check", checkMs: 4.75, foreignKeyViolation: false, gateMs: 9, syncMs: 4 },
+    { label: "measured zero", checkMs: 0.25, foreignKeyViolation: false, gateMs: 4, syncMs: 0 },
+    { label: "failed check", checkMs: 4.75, foreignKeyViolation: true, gateMs: 9, syncMs: 4 },
+  ])(
+    "splits a $label without changing the gate outcome or error",
+    ({ checkMs, foreignKeyViolation, gateMs, syncMs }) => {
+      const { database, advance } = createTimedDatabase(checkMs, foreignKeyViolation);
+      const diagnostics: SqliteIntegrityDiagnostics = {};
+      let suppliedError: unknown;
+      function* operation(): SqliteIntegrityOperation<void> {
+        const gate = sqliteIntegrityCheckSteps(database, "timed database", diagnostics);
+        const step = gate.next();
+        if (step.done) {
+          throw new Error("Integrity check did not yield");
+        }
+        advance(1.75);
+        try {
+          yield step.value;
+        } catch (error) {
+          suppliedError = error;
+          advance(2.75);
+          gate.throw(error);
+          return;
+        }
+        advance(2.75);
+        gate.next();
+      }
+
+      try {
+        let failure: unknown;
+        try {
+          runSqliteIntegrityOperationSync(operation());
+        } catch (error) {
+          failure = error;
+        }
+        if (foreignKeyViolation) {
+          expect(failure).toMatchObject({
+            name: "SqliteIntegrityError",
+            message: expect.stringContaining("foreign_key_check failed for timed database"),
+          });
+          expect(failure).toBe(suppliedError);
+        } else {
+          expect(failure).toBeUndefined();
+        }
+        expect(diagnostics).toEqual({
+          integrityGateMs: gateMs,
+          integrityGateOutcome: foreignKeyViolation ? "failed" : "healthy",
+          integrityCheckSyncMs: syncMs,
+          integrityOutsideCheckMs: gateMs - syncMs,
+        });
+      } finally {
+        database.close();
+      }
+    },
+  );
+
+  it("does not carry measured check time into later unmeasured gates", () => {
+    const { database, advance } = createTimedDatabase(4.75);
+    const diagnostics: SqliteIntegrityDiagnostics = {};
+    const failure = new Error("external integrity driver failed");
+    try {
+      for (const outcome of ["healthy", "failed"] as const) {
+        runSqliteIntegrityOperationSync(
+          sqliteIntegrityCheckSteps(database, "timed database", diagnostics),
+        );
+        expect(diagnostics).toEqual({
+          integrityGateMs: 4,
+          integrityGateOutcome: "healthy",
+          integrityCheckSyncMs: 4,
+          integrityOutsideCheckMs: 0,
+        });
+
+        const manual = sqliteIntegrityCheckSteps(database, "timed database", diagnostics);
+        expect(manual.next().done).toBe(false);
+        advance(12.5);
+        if (outcome === "failed") {
+          let thrown: unknown;
+          try {
+            manual.throw(failure);
+          } catch (error) {
+            thrown = error;
+          }
+          expect(thrown).toBe(failure);
+        } else {
+          expect(manual.next().done).toBe(true);
+        }
+        expect(diagnostics).toEqual({
+          integrityGateMs: 12,
+          integrityGateOutcome: outcome,
+        });
+        expect(diagnostics).not.toHaveProperty("integrityCheckSyncMs");
+        expect(diagnostics).not.toHaveProperty("integrityOutsideCheckMs");
+      }
+    } finally {
+      database.close();
+    }
+  });
+});
+
 describe("isTerminalSqliteIntegrityError", () => {
   it("distinguishes persistent damage from transient pragma failures", () => {
     const corrupt = new Error("integrity check found damage");

src/infra/sqlite-integrity.ts

@@ -13,15 +13,19 @@ type SqliteIntegrityChecks = {
   integrityCheck: "ok";
 };
 
-export type SqliteIntegrityOperation<T> = Generator<
-  { database: DatabaseSync; databaseLabel: string },
-  T,
-  void
->;
+export type SqliteIntegrityCheck = {
+  database: DatabaseSync;
+  databaseLabel: string;
+  timing?: { syncElapsedMs?: number };
+};
+
+export type SqliteIntegrityOperation<T> = Generator<SqliteIntegrityCheck, T, void>;
 
 export type SqliteIntegrityDiagnostics = {
   integrityGateMs?: number;
   integrityGateOutcome?: "healthy" | "failed";
+  integrityCheckSyncMs?: number;
+  integrityOutsideCheckMs?: number;
   canonicalIndexMs?: number;
   repairedIndexCount?: number;
 };
@@ -33,8 +37,15 @@ export function* sqliteIntegrityCheckSteps(
   diagnostics?: SqliteIntegrityDiagnostics,
 ): SqliteIntegrityOperation<void> {
   const startedAt = performance.now();
+  const check: SqliteIntegrityCheck = { database, databaseLabel };
+  if (diagnostics) {
+    check.timing = {};
+    // A later async driver must not inherit an earlier gate's synchronous measurement.
+    delete diagnostics.integrityCheckSyncMs;
+    delete diagnostics.integrityOutsideCheckMs;
+  }
   try {
-    yield { database, databaseLabel };
+    yield check;
     if (diagnostics) {
       diagnostics.integrityGateOutcome = "healthy";
     }
@@ -46,6 +57,24 @@ export function* sqliteIntegrityCheckSteps(
   } finally {
     if (diagnostics) {
       diagnostics.integrityGateMs = Math.floor(performance.now() - startedAt);
+      if (check.timing?.syncElapsedMs !== undefined) {
+        diagnostics.integrityCheckSyncMs = Math.floor(check.timing.syncElapsedMs);
+        diagnostics.integrityOutsideCheckMs =
+          diagnostics.integrityGateMs - diagnostics.integrityCheckSyncMs;
+      }
+    }
+  }
+}
+
+/** Measure only the calling driver's synchronous check, excluding admission and resumption. */
+export function runSqliteIntegrityCheckSync(check: SqliteIntegrityCheck): void {
+  const timing = check.timing;
+  const startedAt = timing ? performance.now() : 0;
+  try {
+    assertSqliteIntegrity(check.database, check.databaseLabel);
+  } finally {
+    if (timing) {
+      timing.syncElapsedMs = performance.now() - startedAt;
     }
   }
 }
@@ -55,7 +84,7 @@ export function runSqliteIntegrityOperationSync<T>(operation: SqliteIntegrityOpe
   let step = operation.next();
   while (!step.done) {
     try {
-      assertSqliteIntegrity(step.value.database, step.value.databaseLabel);
+      runSqliteIntegrityCheckSync(step.value);
     } catch (error) {
       step = operation.throw(error);
       continue;

src/state/openclaw-agent-db-admission.ts

@@ -1,6 +1,10 @@
 import type { DatabaseSync } from "node:sqlite";
 import { assertSqliteIntegrityInWorker } from "../infra/sqlite-integrity-worker.js";
-import { assertSqliteIntegrity, type SqliteIntegrityOperation } from "../infra/sqlite-integrity.js";
+import {
+  runSqliteIntegrityCheckSync,
+  type SqliteIntegrityCheck,
+  type SqliteIntegrityOperation,
+} from "../infra/sqlite-integrity.js";
 import { normalizeAgentId } from "../routing/session-key.js";
 import { createDeferredCore } from "../shared/deferred.js";
 import {
@@ -146,7 +150,7 @@ export function createOpenClawAgentDatabaseAdmissionOwner(
     void pending.promise.catch(() => {});
     pending.operations += 1;
     const steps = openSteps(options, pending);
-    let check: { database: DatabaseSync; databaseLabel: string } | undefined;
+    let check: SqliteIntegrityCheck | undefined;
     let failure: { error: unknown } | undefined;
     let suspended = false;
     try {
@@ -182,7 +186,7 @@ export function createOpenClawAgentDatabaseAdmissionOwner(
         failure = undefined;
         try {
           pending.controller.signal.throwIfAborted();
-          assertSqliteIntegrity(check.database, check.databaseLabel);
+          runSqliteIntegrityCheckSync(check);
         } catch (error) {
           failure = { error };
         }

src/state/openclaw-agent-db.open-timing.test.ts

@@ -14,6 +14,7 @@ import {
   closeOpenClawAgentDatabasesForTest,
   closeOpenClawAgentDatabasesAsync,
   openOpenClawAgentDatabase,
+  withOpenClawAgentDatabaseAdmission,
   withOpenClawAgentDatabaseAsync,
   resolveOpenClawAgentSqlitePath,
 } from "./openclaw-agent-db.js";
@@ -41,7 +42,7 @@ afterEach(async () => {
   logger.warn.mockClear();
 });
 
-function createTimedOpen(validationMs: number, indexRepairMs = 0) {
+function createTimedOpen(validationMs: number, indexRepairMs = 0, integrityCheckMs = 0) {
   const options = {
     agentId: "timing-test",
     env: { OPENCLAW_STATE_DIR: makeTempDir(tempDirs, "openclaw-agent-open-timing-") },
@@ -61,6 +62,21 @@ function createTimedOpen(validationMs: number, indexRepairMs = 0) {
     const database = open(...args);
     if (args[0] === pathname) {
       advance(50);
+      const prepare = database.prepare.bind(database);
+      vi.spyOn(database, "prepare").mockImplementation((sql) => {
+        const statement = prepare(sql);
+        if (sql === "PRAGMA integrity_check;") {
+          const all = statement.all.bind(statement);
+          vi.spyOn(statement, "all").mockImplementation((...parameters) => {
+            try {
+              return all(...parameters);
+            } finally {
+              advance(integrityCheckMs);
+            }
+          });
+        }
+        return statement;
+      });
       const exec = database.exec.bind(database);
       vi.spyOn(database, "exec").mockImplementation((sql) => {
         exec(sql);
@@ -157,6 +173,8 @@ describe("agent database open timings", () => {
       thresholdMs: 1_000,
       integrityGateMs: 0,
       integrityGateOutcome: "healthy",
+      integrityCheckSyncMs: 0,
+      integrityOutsideCheckMs: 0,
       canonicalIndexMs: 0,
       repairedIndexCount: 0,
       phaseDurationsMs: {
@@ -218,6 +236,8 @@ describe("agent database open timings", () => {
           elapsedMs: 1_150,
           integrityGateMs: 0,
           integrityGateOutcome: drift === "physical" ? "failed" : "healthy",
+          integrityCheckSyncMs: 0,
+          integrityOutsideCheckMs: 0,
           canonicalIndexMs: 1_000,
           repairedIndexCount: drift === "physical" ? canonicalIndexCount : 1,
           phaseDurationsMs: {
@@ -232,6 +252,52 @@ describe("agent database open timings", () => {
     },
   );
 
+  it("separates the synchronous check from readmission waiting in the completed owner log", async () => {
+    const { options, pathname, advance } = createTimedOpen(0, 0, 120.75);
+    openOpenClawAgentDatabase(options);
+    closeOpenClawAgentDatabaseByPath(pathname);
+    logger.warn.mockClear();
+    let admissions = 0;
+
+    const isOpen = await withOpenClawAgentDatabaseAdmission(
+      options,
+      async (run) => {
+        admissions += 1;
+        if (admissions === 2) {
+          advance(999.75);
+        }
+        return await run(() => {});
+      },
+      (database) => database.db.isOpen,
+    );
+
+    expect(isOpen).toBe(true);
+    expect(admissions).toBe(2);
+    expect(logger.warn).toHaveBeenCalledExactlyOnceWith("slow OpenClaw agent database open", {
+      agentId: options.agentId,
+      elapsedMs: 1_270,
+      path: pathname,
+      pid: process.pid,
+      threadId,
+      isMainThread,
+      admissionMode: "async",
+      thresholdMs: 1_000,
+      integrityGateMs: 1_120,
+      integrityGateOutcome: "healthy",
+      integrityCheckSyncMs: 120,
+      integrityOutsideCheckMs: 1_000,
+      canonicalIndexMs: 0,
+      repairedIndexCount: 0,
+      phaseDurationsMs: {
+        open: 60,
+        validation: 1_120,
+        configuration: 80,
+        schema: 0,
+        registration: 10,
+      },
+    });
+  });
+
   it("includes asynchronous admission waiting once for coalesced callers", async () => {
     const { options, pathname, advance } = createTimedOpen(0);
     openOpenClawAgentDatabase(options);
@@ -295,6 +361,8 @@ describe("agent database open timings", () => {
           registration: 80,
         },
       });
+      expect(logger.warn.mock.calls[0]?.[1]).not.toHaveProperty("integrityCheckSyncMs");
+      expect(logger.warn.mock.calls[0]?.[1]).not.toHaveProperty("integrityOutsideCheckMs");
     } finally {
       release.resolve();
       await outcomes;