feat(service-automation): a run record says how long it waited (waitMs), so a resumed screen flow no longer reads its user's wait as work

.changeset/32284-run-wait-ms.md

@@ -0,0 +1,17 @@
+---
+'@objectstack/spec': minor
+'@objectstack/service-automation': minor
+---
+
+feat(automation): a run record says how much of its duration the run spent suspended, so a resumed screen flow no longer reads as an 18-second execution
+
+Clause-②: yes (widening)
+Metadata-protocol: added
+
+A run's `durationMs` is its total wall time, pauses included. A screen flow resumed after the user filled the screen in reported `durationMs: 18691`, almost all of it the user's wait, and nothing on the record told an admin that the run was waiting rather than slow.
+
+`ExecutionLogSchema` (`@objectstack/spec/automation`), the run record served by `GET /api/v1/automation/:name/runs/:runId` and the runs list, gains an optional `waitMs`: the total time the run spent suspended at a `screen`, `approval`, `wait` or other pausing node, summed over all its pauses. `durationMs` keeps its meaning, so the time a run spent executing is `durationMs - waitMs`. A run that never paused carries `waitMs: 0`, a measured zero; a `paused` entry carries the wait up to the moment it was written. Absent means not recorded (a `missed` entry, or a run paused before this release), which is not the same as zero.
+
+`@objectstack/service-automation` fills it on every run record: initial execution and its retries, resume (completed, refused, stranded, re-suspended), a paused run cancelled or failed where it waits, and the operator restore of a consumed suspension, which keeps the clock of the pause it re-arms. A suspension carries one number, `SuspendedRun.activeMs` (the time the run had executed when it paused), so the wait sums across any number of pauses and process restarts. `sys_automation_run` gains two nullable columns: `active_ms` on paused rows (and on a stranded row's consumed snapshot) and `wait_ms` on terminal rows.
+
+Nothing to migrate: rows written before this release keep both columns empty and read `waitMs` as not recorded. A client that validates the run record with `ExecutionLogSchema` from an older `@objectstack/spec` strips the new member and reads the record as before.

content/docs/references/api/automation-api.mdx

@@ -937,6 +937,7 @@ const result = AutomationApiErrorCode.parse(data);
 | **startedAt** | `string` | ✅ | Execution start timestamp |
 | **completedAt** | `string` | optional | Execution completion timestamp |
 | **durationMs** | `integer` | optional | Total execution duration in milliseconds |
+| **waitMs** | `integer` | optional | Total time the run spent suspended (waiting at a `screen`, `approval`, `wait` or other pausing node), summed over all its pauses, in milliseconds. Included in `durationMs`, which stays the total wall time, so the time spent executing is `durationMs - waitMs`. `0` on a run that never paused; on a `paused` entry, the wait up to the moment the entry was written. Absent when not recorded — a `missed` entry, or a run paused before this was tracked — which is not the same as zero. |
 | **runAs** | `Enum<'system' \| 'user'>` | optional | Execution context identity |
 | **tenantId** | `string` | optional | Tenant ID for multi-tenant isolation |
 

content/docs/references/automation/execution.mdx

@@ -113,6 +113,7 @@ const result = CheckpointSchema.parse(data);
 | **startedAt** | `string` | ✅ | Execution start timestamp |
 | **completedAt** | `string` | optional | Execution completion timestamp |
 | **durationMs** | `integer` | optional | Total execution duration in milliseconds |
+| **waitMs** | `integer` | optional | Total time the run spent suspended (waiting at a `screen`, `approval`, `wait` or other pausing node), summed over all its pauses, in milliseconds. Included in `durationMs`, which stays the total wall time, so the time spent executing is `durationMs - waitMs`. `0` on a run that never paused; on a `paused` entry, the wait up to the moment the entry was written. Absent when not recorded — a `missed` entry, or a run paused before this was tracked — which is not the same as zero. |
 | **runAs** | `Enum<'system' \| 'user'>` | optional | Execution context identity |
 | **tenantId** | `string` | optional | Tenant ID for multi-tenant isolation |
 

packages/services/service-automation/src/consumed-suspension-restore.ts

@@ -17,7 +17,7 @@
 
 import { describeThrownForLog } from './thrown-cause-diagnostics.js';
 // The values below (`MAX_CONSUMED_SUSPENSIONS`, `MAX_RESTORE_CHAIN_HOPS`,
-// `buildRunTrigger`, `chainEntryOf` and `nestedChildRunId`) are read only
+// `buildRunTrigger`, `chainEntryOf`, `nestedChildRunId` and `waitOfPausedRun`) are read only
 // inside the function bodies, at call time, never while a module is
 // evaluating, so the import cycle with ./engine.js is safe under ESM live
 // bindings; the tsup bundle is one file and has no cycle.
@@ -27,6 +27,7 @@ import {
     buildRunTrigger,
     chainEntryOf,
     nestedChildRunId,
+    waitOfPausedRun,
     type AutomationEngine,
     type ChainRestoreEntry,
     type ConsumedSuspension,
@@ -457,13 +458,22 @@ export async function restoreOneConsumedSuspension(
         // row: `ExecutionStatus` carries no such member, so a durable
         // status that survives the restart is a spec-vocabulary decision
         // nobody has taken — the row's discriminator stays the snapshot.
+        //
+        // [#32284] `waitMs` from the SNAPSHOT's clock: the restore re-arms the
+        // pause the failed resume consumed, so the run reads as never having
+        // left it — the attempt that failed, the time it sat stranded and the
+        // wait from here to its next resume are all one pause, and its active
+        // time is still what it had executed when it first parked. That is
+        // also what its step log says: the snapshot's steps end at the pause.
+        const durationMs = Date.now() - consumed.run.startTime;
         this.recordLog({
             id: runId,
             flowName: consumed.run.flowName,
             flowVersion: consumed.run.flowVersion,
             status: 'paused',
             startedAt: consumed.run.startedAt,
-            durationMs: Date.now() - consumed.run.startTime,
+            durationMs,
+            waitMs: waitOfPausedRun(consumed.run, durationMs),
             trigger: buildRunTrigger(consumed.run.context),
             steps: consumed.run.steps,
             variables: consumed.run.variables,

packages/services/service-automation/src/dag-traversal.ts

@@ -24,10 +24,11 @@ import { summarizeRun } from './run-summary.js';
 import { withDroppedFields } from './run-dropped-fields.js';
 import { describeThrownForLog } from './thrown-cause-diagnostics.js';
 // The values below (`AutomationEngine` for its public static
-// `MAX_NODE_REENTRIES`) are read only inside the function bodies, at call time,
+// `MAX_NODE_REENTRIES`, and `activeMsAtPause`) are read only inside the function bodies, at call time,
 // never while a module is evaluating, so the import cycle with ./engine.js is
 // safe under ESM live bindings; the tsup bundle is one file and has no cycle.
 import {
+    activeMsAtPause,
     AutomationEngine,
     buildRunTrigger,
     DEFAULT_BRANCH_LABEL,
@@ -1361,6 +1362,8 @@ export async function executeWithoutRetry(
                 startedAt,
                 completedAt: new Date().toISOString(),
                 durationMs,
+                // [#32284] A retry attempt is an initial execution: it never paused.
+                waitMs: 0,
                 trigger: buildRunTrigger(context),
                 steps,
                 output,
@@ -1421,7 +1424,7 @@ export async function executeWithoutRetry(
         if (isRefusalSignal(err)) {
             return this.finishRefusedRun({
                 runId, flowName, flowVersion: flow.version,
-                startedAt, durationMs: Date.now() - startTime,
+                startedAt, durationMs: Date.now() - startTime, waitMs: 0,
                 steps, flow, variables,
                 refusalMessage: err.message, context,
             });
@@ -1468,6 +1471,8 @@ export async function executeWithoutRetry(
         // method returns — the only id `resume()` can be called with.
         if (isSuspendSignal(err)) {
             const durationMs = Date.now() - startTime;
+            // [#32284] This attempt's first pause — see `execute()`'s.
+            const waitMs = 0;
             // #7639 — ONE snapshot expression feeding BOTH consumers: the
             // continuation the run will resume from, and the `paused` log
             // entry run-detail serves. Same object, so what an operator
@@ -1485,6 +1490,7 @@ export async function executeWithoutRetry(
                 context: runContext,
                 startedAt,
                 startTime,
+                activeMs: activeMsAtPause(durationMs, waitMs),
                 correlation: err.correlation,
                 screen: err.screen,
             });
@@ -1495,6 +1501,7 @@ export async function executeWithoutRetry(
                 status: 'paused',
                 startedAt,
                 durationMs,
+                waitMs,
                 trigger: buildRunTrigger(context),
                 steps,
                 variables: variablesSnapshot,
@@ -1539,6 +1546,7 @@ export async function executeWithoutRetry(
             startedAt,
             completedAt: new Date().toISOString(),
             durationMs,
+            waitMs: 0,
             trigger: buildRunTrigger(context),
             steps,
             error: errorMessage,

packages/services/service-automation/src/engine.ts

@@ -1294,6 +1294,13 @@ export interface ExecutionLogEntry {
     startedAt: string;
     completedAt?: string;
     durationMs?: number;
+    /**
+     * [#32284] `ExecutionLogSchema.waitMs`: the part of `durationMs` the run
+     * spent suspended, summed over every pause it has left — `0` on a run
+     * that never paused, absent when not recorded. Written beside `durationMs`
+     * at every site that writes one; never derived from it here.
+     */
+    waitMs?: number;
     trigger: { type: string; userId?: string; object?: string; recordId?: string };
     // ↑ built by `buildRunTrigger` at EVERY site — see its doc comment for why
     // that is a chokepoint rather than eight object literals.
@@ -1776,11 +1783,52 @@ export interface SuspendedRun {
     context: AutomationContext;
     startedAt: string;
     startTime: number;
+    /**
+     * [#32284] The run's wait clock: the milliseconds it had spent EXECUTING
+     * (its age at this pause minus every earlier pause) when it paused here.
+     * Nothing executes while the run is parked, so at any later instant the
+     * run's total wait is its age minus this — which is how one number sums
+     * every pause of a run that suspends, resumes and suspends again
+     * ({@link waitOfPausedRun}), and why a restore that re-arms a consumed
+     * pause needs no clock of its own: the snapshot carries this value, and
+     * the time from the pause to the restore is wait like the rest of it.
+     *
+     * Set at every site that builds a suspension ({@link activeMsAtPause});
+     * carried unchanged by every re-save of the SAME pause (`{ ...run }`).
+     * Absent on a suspension recorded before this field existed, or by a
+     * host store that does not round-trip it: such a run's `waitMs` is not
+     * recorded rather than guessed.
+     */
+    activeMs?: number;
     correlation?: string;
     /** Screen the run paused on (screen-flow runtime), for re-fetch + UI render. */
     screen?: ScreenSpec;
 }
 
+/**
+ * [#32284] The `activeMs` a suspension records: the run's age at the pause
+ * minus the wait it has already accumulated. `undefined` when that wait is not
+ * known (the run's previous pause carried no clock), so an unknown wait is
+ * never turned into a precise-looking number further on.
+ */
+export function activeMsAtPause(elapsedMs: number, waitMs: number | undefined): number | undefined {
+    return waitMs === undefined ? undefined : Math.max(0, elapsedMs - waitMs);
+}
+
+/**
+ * [#32284] A paused run's total wait at the moment its pause ENDS — a resume
+ * consumes it, or the run is cancelled, failed or settled where it waits, or a
+ * restore records it paused again: its age then (`elapsedMs`, measured from
+ * `startTime` like `durationMs`) minus the time it had spent executing when it
+ * paused. `undefined` for a suspension with no clock ({@link SuspendedRun.activeMs}).
+ *
+ * Clamped at zero: `startTime` may have been stamped by another replica's
+ * clock, and a published `waitMs` is never negative.
+ */
+export function waitOfPausedRun(run: Pick<SuspendedRun, 'activeMs'>, elapsedMs: number): number | undefined {
+    return typeof run.activeMs === 'number' ? Math.max(0, elapsedMs - run.activeMs) : undefined;
+}
+
 /**
  * Pluggable durable store for suspended runs (ADR-0019). The engine persists a
  * {@link SuspendedRun} on suspend and deletes it on terminal completion; on
@@ -1868,6 +1916,13 @@ export interface RunRecord {
     /** When the run reached its terminal state. */
     finishedAt?: string;
     durationMs?: number;
+    /**
+     * [#32284] The run's {@link ExecutionLogEntry.waitMs}, persisted beside
+     * `durationMs` (`sys_automation_run.wait_ms`) so a run read back after a
+     * restart or a ring eviction still says how much of its duration was
+     * waiting. Absent on a row written before the column existed.
+     */
+    waitMs?: number;
     /** Failure reason for a `failed` run — what a designer needs to fix it. */
     error?: string;
     /**
@@ -7726,6 +7781,8 @@ export class AutomationEngine implements IAutomationService {
                     startedAt,
                     completedAt: new Date().toISOString(),
                     durationMs,
+                    // [#32284] The initial execution never paused: a measured 0.
+                    waitMs: 0,
                     trigger: buildRunTrigger(context),
                     steps,
                     output,
@@ -7824,7 +7881,7 @@ export class AutomationEngine implements IAutomationService {
             if (isRefusalSignal(err)) {
                 return this.finishRefusedRun({
                     runId, flowName, flowVersion: flow.version,
-                    startedAt, durationMs: Date.now() - startTime,
+                    startedAt, durationMs: Date.now() - startTime, waitMs: 0,
                     steps, flow, variables,
                     refusalMessage: err.message, context,
                 });
@@ -7834,6 +7891,9 @@ export class AutomationEngine implements IAutomationService {
             // caller can later `resume()` it. This is NOT a failure.
             if (isSuspendSignal(err)) {
                 const durationMs = Date.now() - startTime;
+                // [#32284] The run's first pause: nothing waited yet, so all
+                // of `durationMs` was execution — the clock the resume reads.
+                const waitMs = 0;
                 // #7639 — ONE snapshot expression feeding BOTH consumers: the
                 // continuation the run will resume from, and the `paused` log
                 // entry run-detail serves. Same object, so what an operator
@@ -7852,6 +7912,7 @@ export class AutomationEngine implements IAutomationService {
                     context: runContext,
                     startedAt,
                     startTime,
+                    activeMs: activeMsAtPause(durationMs, waitMs),
                     correlation: err.correlation,
                     screen: err.screen,
                 });
@@ -7862,6 +7923,7 @@ export class AutomationEngine implements IAutomationService {
                     status: 'paused',
                     startedAt,
                     durationMs,
+                    waitMs,
                     trigger: buildRunTrigger(context),
                     steps,
                     variables: variablesSnapshot,
@@ -7926,6 +7988,7 @@ export class AutomationEngine implements IAutomationService {
                 startedAt,
                 completedAt: new Date().toISOString(),
                 durationMs,
+                waitMs: 0,
                 trigger: buildRunTrigger(context),
                 steps,
                 error: errorMessage,
@@ -9943,6 +10006,8 @@ export class AutomationEngine implements IAutomationService {
         flowVersion?: number;
         startedAt: string;
         durationMs: number;
+        /** [#32284] The run's `waitMs` — `undefined` only where it is not recorded. */
+        waitMs: number | undefined;
         steps: StepLogEntry[];
         /** Read for its `isOutput` variable declarations — see `output` below. */
         flow: FlowParsed;

packages/services/service-automation/src/run-history.ts

@@ -270,6 +270,9 @@ export function runRecordToLogEntry(r: RunRecord): ExecutionLogEntry {
         startedAt: r.startedAt,
         completedAt: r.finishedAt,
         durationMs: r.durationMs,
+        // [#32284] The persisted wait — absent on a row written before the
+        // column existed, which reads "not recorded", never "did not wait".
+        waitMs: r.waitMs,
         // #7533 — the persisted trigger attribution, so a run rehydrated
         // after a restart still says what fired it and (for a record
         // change) which record. `type` falls back to `''` ONLY for rows
@@ -615,6 +618,9 @@ export function recordLog(
             startedAt: entry.startedAt,
             finishedAt: entry.completedAt,
             durationMs: entry.durationMs,
+            // [#32284] Beside `durationMs`, so the durable row answers "how
+            // much of that was waiting?" after a restart as the ring does.
+            waitMs: entry.waitMs,
             error: entry.error,
             // [#15788] The rendered refusal, carried onto the durable row
             // beside `status: 'refused'`. Set by exactly one producer
@@ -717,6 +723,8 @@ export function finishRefusedRun(this: Pick<RunHistoryHost, 'recordLog' | 'logge
     flowVersion?: number;
     startedAt: string;
     durationMs: number;
+    /** [#32284] The run's `waitMs` — `undefined` only where it is not recorded. */
+    waitMs: number | undefined;
     steps: StepLogEntry[];
     /** Read for its `isOutput` variable declarations — see `output` below. */
     flow: FlowParsed;
@@ -746,6 +754,7 @@ export function finishRefusedRun(this: Pick<RunHistoryHost, 'recordLog' | 'logge
             startedAt: args.startedAt,
             completedAt: new Date().toISOString(),
             durationMs: args.durationMs,
+            waitMs: args.waitMs,
             trigger: buildRunTrigger(args.context),
             steps: args.steps,
             output,