mirror of
https://github.com/windmill-labs/windmill.git
synced 2026-08-20 00:02:19 +00:00
fix: show wall-clock execution time for WAC roots in the UI, keep duration_ms as worker time
Reworks the workflow-as-code (WAC) execution-time fix. The earlier approach persisted wall-clock into `v2_job_completed.duration_ms`, but that column is read as worker *service time* by cloud-usage accounting and EE workspace fairness — so a WAC root that suspends while its task jobs run would bill and be throttled for idle wall-clock, and counting it any other way (e.g. excluding it) would let arbitrary user code in the root go uncounted. Instead, keep `duration_ms` as the worker-measured value (revert the backend change entirely) and compute the wall-clock total in the UI from `completed_at - started_at` for WAC roots only. WAC roots are identified by the `_checkpoint` in `workflow_as_code_status` (present in the completed-job API payload; AI-agent jobs populate the column but have no `_checkpoint`). - frontend/src/lib/utils.ts: add `isWorkflowAsCodeRoot` + `jobDisplayDurationMs` - JobStatus.svelte / JobPreview.svelte: render the WAC-aware display duration Reverts the duration_ms/test/sqlx/ee-repo-ref changes from the prior commits so the backend is unchanged vs main; no EE companion change is needed. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
+31
@@ -0,0 +1,31 @@
|
||||
{
|
||||
"db_name": "PostgreSQL",
|
||||
"query": "INSERT INTO v2_job_completed AS cj\n ( workspace_id\n , id\n , started_at\n , duration_ms\n , result\n , result_columns\n , canceled_by\n , canceled_reason\n , flow_status\n , workflow_as_code_status\n , memory_peak\n , status\n , worker\n )\n SELECT q.workspace_id, q.id, started_at, COALESCE($9::bigint, (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000), $3, $10, $5, $6,\n flow_status, workflow_as_code_status,\n $8, CASE WHEN $4::BOOL THEN 'canceled'::job_status\n WHEN $7::BOOL THEN 'skipped'::job_status\n WHEN $2::BOOL THEN 'success'::job_status\n ELSE 'failure'::job_status END AS status,\n q.worker\n FROM v2_job_queue q LEFT JOIN v2_job_status USING (id) WHERE q.id = $1\n ON CONFLICT (id) DO UPDATE SET status = EXCLUDED.status, result = $3 RETURNING duration_ms AS \"duration_ms!\"",
|
||||
"describe": {
|
||||
"columns": [
|
||||
{
|
||||
"ordinal": 0,
|
||||
"name": "duration_ms!",
|
||||
"type_info": "Int8"
|
||||
}
|
||||
],
|
||||
"parameters": {
|
||||
"Left": [
|
||||
"Uuid",
|
||||
"Bool",
|
||||
"Jsonb",
|
||||
"Bool",
|
||||
"Varchar",
|
||||
"Text",
|
||||
"Bool",
|
||||
"Int4",
|
||||
"Int8",
|
||||
"TextArray"
|
||||
]
|
||||
},
|
||||
"nullable": [
|
||||
false
|
||||
]
|
||||
},
|
||||
"hash": "36c4e57afcab22f4b6825ccebe47767b8a8fe0a638250f7c7777e5a9f7530e5c"
|
||||
}
|
||||
-31
@@ -1,31 +0,0 @@
|
||||
{
|
||||
"db_name": "PostgreSQL",
|
||||
"query": "INSERT INTO v2_job_completed AS cj\n ( workspace_id\n , id\n , started_at\n , duration_ms\n , result\n , result_columns\n , canceled_by\n , canceled_reason\n , flow_status\n , workflow_as_code_status\n , memory_peak\n , status\n , worker\n )\n SELECT q.workspace_id, q.id, started_at,\n -- Workflow-as-code roots (identified by the `_checkpoint` written by the WAC\n -- executor) suspend while their task jobs run, so the worker-measured `$9`\n -- duration only covers the orchestration script's own compute, not the tasks.\n -- `started_at` is preserved across resumes (pull uses `coalesce(started_at, now())`),\n -- so fall back to the wall-clock elapsed time here, exactly like flows do.\n CASE WHEN workflow_as_code_status -> '_checkpoint' IS NOT NULL\n THEN (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000\n ELSE COALESCE($9::bigint, (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000)\n END, $3, $10, $5, $6,\n flow_status, workflow_as_code_status,\n $8, CASE WHEN $4::BOOL THEN 'canceled'::job_status\n WHEN $7::BOOL THEN 'skipped'::job_status\n WHEN $2::BOOL THEN 'success'::job_status\n ELSE 'failure'::job_status END AS status,\n q.worker\n FROM v2_job_queue q LEFT JOIN v2_job_status USING (id) WHERE q.id = $1\n ON CONFLICT (id) DO UPDATE SET status = EXCLUDED.status, result = $3 RETURNING duration_ms AS \"duration_ms!\"",
|
||||
"describe": {
|
||||
"columns": [
|
||||
{
|
||||
"ordinal": 0,
|
||||
"name": "duration_ms!",
|
||||
"type_info": "Int8"
|
||||
}
|
||||
],
|
||||
"parameters": {
|
||||
"Left": [
|
||||
"Uuid",
|
||||
"Bool",
|
||||
"Jsonb",
|
||||
"Bool",
|
||||
"Varchar",
|
||||
"Text",
|
||||
"Bool",
|
||||
"Int4",
|
||||
"Int8",
|
||||
"TextArray"
|
||||
]
|
||||
},
|
||||
"nullable": [
|
||||
false
|
||||
]
|
||||
},
|
||||
"hash": "4e62d7054b7bdb4be07035847b1d2aa9ad5225ebbd0b77b32afc24473cb3f631"
|
||||
}
|
||||
@@ -1 +1 @@
|
||||
34ba4194123e605271b3c15108bc53bb7b2b9876
|
||||
3742e0659c5e97aab03b9efeea14cd94a3ac658a
|
||||
|
||||
@@ -1283,19 +1283,11 @@ async def main(n: int):
|
||||
|
||||
let db_ref = &db;
|
||||
|
||||
// Returns (final result, completed_steps checkpoint, wall-clock elapsed,
|
||||
// stored parent `duration_ms`, DB wall-clock `completed_at - started_at` in ms).
|
||||
async fn run_once(
|
||||
db: &Pool<Postgres>,
|
||||
port: u16,
|
||||
content: String,
|
||||
) -> (
|
||||
serde_json::Value,
|
||||
serde_json::Value,
|
||||
std::time::Duration,
|
||||
i64,
|
||||
f64,
|
||||
) {
|
||||
) -> (serde_json::Value, serde_json::Value, std::time::Duration) {
|
||||
let mut job_id_out: Option<sqlx::types::Uuid> = None;
|
||||
let mut result_out: Option<serde_json::Value> = None;
|
||||
let t0 = std::time::Instant::now();
|
||||
@@ -1348,56 +1340,17 @@ async def main(n: int):
|
||||
)
|
||||
});
|
||||
|
||||
// A WAC v2 root suspends while its steps run, so its stored `duration_ms`
|
||||
// must be the end-to-end wall-clock (`now() - started_at`, like flows),
|
||||
// NOT just the final replay's compute time. Fetch both the stored value
|
||||
// and the DB-computed wall-clock to assert they agree. (Non-macro query
|
||||
// so it needs no offline sqlx cache entry.)
|
||||
let (duration_ms, wallclock_ms): (i64, f64) = sqlx::query_as(
|
||||
"SELECT duration_ms,
|
||||
(EXTRACT('epoch' FROM (completed_at - started_at)) * 1000)::float8
|
||||
FROM v2_job_completed WHERE id = $1",
|
||||
)
|
||||
.bind(job_id)
|
||||
.fetch_one(db)
|
||||
.await
|
||||
.expect("v2_job_completed timing fetch");
|
||||
|
||||
(
|
||||
result_out.unwrap(),
|
||||
ckpt,
|
||||
elapsed,
|
||||
duration_ms,
|
||||
wallclock_ms,
|
||||
)
|
||||
(result_out.unwrap(), ckpt, elapsed)
|
||||
}
|
||||
|
||||
// --- Legacy path: worker-side suspend & replay ---
|
||||
let (legacy_result, legacy_ckpt, legacy_elapsed, legacy_duration_ms, legacy_wallclock_ms) =
|
||||
let (legacy_result, legacy_ckpt, legacy_elapsed) =
|
||||
run_once(db_ref, port, workflow_content(false)).await;
|
||||
|
||||
// --- Fast path: SDK persists the delta via the new API endpoint ---
|
||||
let (fast_result, fast_ckpt, fast_elapsed, fast_duration_ms, fast_wallclock_ms) =
|
||||
let (fast_result, fast_ckpt, fast_elapsed) =
|
||||
run_once(db_ref, port, workflow_content(true)).await;
|
||||
|
||||
// Regression check (workflow-as-code execution time): the WAC root's stored
|
||||
// `duration_ms` must reflect the full end-to-end wall-clock — the same
|
||||
// semantics flows use — and not just the orchestration script's final-replay
|
||||
// compute time. Previously it excluded the suspend/replay round-trips spent
|
||||
// running the steps, so it read far below the actual wall-clock. We allow a
|
||||
// small tolerance for the sub-second gap between the worker's completion and
|
||||
// the `now()` evaluated when the row is committed.
|
||||
for (label, duration_ms, wallclock_ms) in [
|
||||
("legacy", legacy_duration_ms, legacy_wallclock_ms),
|
||||
("fast", fast_duration_ms, fast_wallclock_ms),
|
||||
] {
|
||||
assert!(
|
||||
(duration_ms as f64 - wallclock_ms).abs() <= 250.0,
|
||||
"{label} WAC v2 root duration_ms ({duration_ms}ms) should match the \
|
||||
end-to-end wall-clock ({wallclock_ms:.0}ms) like flows do"
|
||||
);
|
||||
}
|
||||
|
||||
// Behavioral equivalence: same final result and same completed_steps.
|
||||
assert_eq!(
|
||||
legacy_result, fast_result,
|
||||
|
||||
@@ -959,13 +959,6 @@ pub async fn add_completed_job<T: Serialize + Send + Sync + ValidableJson>(
|
||||
}
|
||||
|
||||
let result_columns = result_columns.as_ref();
|
||||
// Worker-measured compute time (`$9`), captured before `duration` is shadowed
|
||||
// by the value persisted to `v2_job_completed`. The persisted value is
|
||||
// wall-clock for workflow-as-code roots (they suspend while their task jobs
|
||||
// run), which is correct for display but would overstate worker service time
|
||||
// for usage accounting — so accounting must use the worker-measured value.
|
||||
#[cfg(feature = "cloud")]
|
||||
let worker_measured_duration = duration;
|
||||
let (opt_uuid, duration, _skip_downstream_error_handlers, wac_job_ids) = (|| {
|
||||
commit_completed_job(
|
||||
db,
|
||||
@@ -1006,11 +999,7 @@ pub async fn add_completed_job<T: Serialize + Send + Sync + ValidableJson>(
|
||||
}
|
||||
|
||||
#[cfg(feature = "cloud")]
|
||||
apply_completed_job_cloud_usage(
|
||||
db,
|
||||
completed_job,
|
||||
worker_measured_duration.unwrap_or(duration),
|
||||
);
|
||||
apply_completed_job_cloud_usage(db, completed_job, duration);
|
||||
|
||||
#[cfg(all(feature = "enterprise", feature = "private"))]
|
||||
crate::jobs_ee::apply_completed_job_error_handlers(
|
||||
@@ -1079,16 +1068,7 @@ async fn commit_completed_job<T: Serialize + Send + Sync + ValidableJson>(
|
||||
, status
|
||||
, worker
|
||||
)
|
||||
SELECT q.workspace_id, q.id, started_at,
|
||||
-- Workflow-as-code roots (identified by the `_checkpoint` written by the WAC
|
||||
-- executor) suspend while their task jobs run, so the worker-measured `$9`
|
||||
-- duration only covers the orchestration script's own compute, not the tasks.
|
||||
-- `started_at` is preserved across resumes (pull uses `coalesce(started_at, now())`),
|
||||
-- so fall back to the wall-clock elapsed time here, exactly like flows do.
|
||||
CASE WHEN workflow_as_code_status -> '_checkpoint' IS NOT NULL
|
||||
THEN (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000
|
||||
ELSE COALESCE($9::bigint, (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000)
|
||||
END, $3, $10, $5, $6,
|
||||
SELECT q.workspace_id, q.id, started_at, COALESCE($9::bigint, (EXTRACT('epoch' FROM (now())) - EXTRACT('epoch' FROM (COALESCE(started_at, now()))))*1000), $3, $10, $5, $6,
|
||||
flow_status, workflow_as_code_status,
|
||||
$8, CASE WHEN $4::BOOL THEN 'canceled'::job_status
|
||||
WHEN $7::BOOL THEN 'skipped'::job_status
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
<script lang="ts">
|
||||
import { displayDate, msToReadableTime } from '$lib/utils'
|
||||
import { displayDate, jobDisplayDurationMs, msToReadableTime } from '$lib/utils'
|
||||
import type { CompletedJob, QueuedJob } from '$lib/gen'
|
||||
import Badge from './common/badge/Badge.svelte'
|
||||
import { forLater } from '$lib/forLater'
|
||||
@@ -20,7 +20,7 @@
|
||||
|
||||
{#if job && 'success' in job && job.success}
|
||||
<Badge {large} color="green">
|
||||
Successfully ran in {msToReadableTime(job.duration_ms)}
|
||||
Successfully ran in {msToReadableTime(jobDisplayDurationMs(job))}
|
||||
{job.is_skipped ? '(Skipped)' : ''}
|
||||
{#if job.self_wait_time_ms || job.aggregate_wait_time_ms}
|
||||
<WaitTimeWarning
|
||||
@@ -32,7 +32,7 @@
|
||||
</Badge>
|
||||
{:else if job && 'success' in job}
|
||||
<Badge {large} color="red">
|
||||
Failed after {msToReadableTime(job.duration_ms)}
|
||||
Failed after {msToReadableTime(jobDisplayDurationMs(job))}
|
||||
{#if job.self_wait_time_ms || job.aggregate_wait_time_ms}
|
||||
<WaitTimeWarning
|
||||
self_wait_time_ms={job.self_wait_time_ms}
|
||||
|
||||
@@ -15,6 +15,7 @@
|
||||
import { Badge } from '../common'
|
||||
import { forLater } from '$lib/forLater'
|
||||
import DurationMs from '../DurationMs.svelte'
|
||||
import { jobDisplayDurationMs } from '$lib/utils'
|
||||
import { workspaceStore } from '$lib/stores'
|
||||
import { twMerge } from 'tailwind-merge'
|
||||
|
||||
@@ -157,7 +158,7 @@
|
||||
</Badge>
|
||||
{#if job?.['duration_ms']}
|
||||
<DurationMs
|
||||
duration_ms={job?.['duration_ms']}
|
||||
duration_ms={jobDisplayDurationMs(job) ?? job?.['duration_ms']}
|
||||
self_wait_time_ms={job?.self_wait_time_ms}
|
||||
aggregate_wait_time_ms={job?.aggregate_wait_time_ms}
|
||||
/>
|
||||
|
||||
@@ -239,6 +239,49 @@ export function msToReadableTime(ms: number | undefined, maximumFractionDigits?:
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* A workflow-as-code (WAC) root is a script/preview job whose
|
||||
* `workflow_as_code_status` carries the `_checkpoint` written by the WAC
|
||||
* executor when it dispatches task jobs. AI-agent jobs also populate
|
||||
* `workflow_as_code_status` but never write `_checkpoint`, so they are not
|
||||
* matched here.
|
||||
*/
|
||||
export function isWorkflowAsCodeRoot(
|
||||
job: { workflow_as_code_status?: unknown } | undefined
|
||||
): boolean {
|
||||
const wac = job?.workflow_as_code_status as Record<string, unknown> | undefined
|
||||
return wac != undefined && wac['_checkpoint'] != undefined
|
||||
}
|
||||
|
||||
/**
|
||||
* Total execution time to display for a job, in ms.
|
||||
*
|
||||
* WAC roots suspend while their task jobs run, so their worker-measured
|
||||
* `duration_ms` only covers the orchestration script's own compute, not the
|
||||
* end-to-end run. For those, show the wall-clock span (`completed_at -
|
||||
* started_at`) — the same total a flow reports. Everything else (and any WAC
|
||||
* root missing the timestamps) falls back to `duration_ms`.
|
||||
*/
|
||||
export function jobDisplayDurationMs(
|
||||
job:
|
||||
| {
|
||||
started_at?: string
|
||||
completed_at?: string
|
||||
duration_ms?: number
|
||||
workflow_as_code_status?: unknown
|
||||
}
|
||||
| undefined
|
||||
): number | undefined {
|
||||
if (isWorkflowAsCodeRoot(job) && job?.started_at && job?.completed_at) {
|
||||
const start = new Date(job.started_at).getTime()
|
||||
const end = new Date(job.completed_at).getTime()
|
||||
if (isFinite(start) && isFinite(end) && end >= start) {
|
||||
return end - start
|
||||
}
|
||||
}
|
||||
return job?.duration_ms
|
||||
}
|
||||
|
||||
export function msToReadableTimeShort(
|
||||
ms: number | undefined,
|
||||
maximumFractionDigits?: number
|
||||
|
||||
Reference in New Issue
Block a user