feat: sample workflow phase latency

This commit is contained in:
2026-09-19 19:44:21 +08:00
parent 0ac3f2f3f8
commit a5cef4dbe8
10 changed files with 190 additions and 7 deletions

View File

@@ -37,6 +37,18 @@ type BusinessSnapshot struct {
WorkflowTerminalLatencySeconds float64
// WorkflowTerminalLatencyMaxSeconds 最近窗口终态流程样本最大耗时。
WorkflowTerminalLatencyMaxSeconds float64
// TaskAcceptToStartLatencySeconds 最近窗口任务受理到开始的平均耗时样本。
TaskAcceptToStartLatencySeconds float64
// TaskAcceptToStartLatencyMaxSeconds 最近窗口任务受理到开始的最大耗时样本。
TaskAcceptToStartLatencyMaxSeconds float64
// TaskAcceptToTerminalLatencySeconds 最近窗口任务受理到确定终态的平均耗时样本。
TaskAcceptToTerminalLatencySeconds float64
// TaskAcceptToTerminalLatencyMaxSeconds 最近窗口任务受理到确定终态的最大耗时样本。
TaskAcceptToTerminalLatencyMaxSeconds float64
// WorkflowStartToTerminalLatencySeconds 最近窗口流程开始到停止的平均耗时样本。
WorkflowStartToTerminalLatencySeconds float64
// WorkflowStartToTerminalLatencyMaxSeconds 最近窗口流程开始到停止的最大耗时样本。
WorkflowStartToTerminalLatencyMaxSeconds float64
}
// RecordBusinessSnapshot records one bounded database sample. A failed sample
@@ -77,6 +89,12 @@ func (r *Registry) RecordBusinessSnapshot(snapshot BusinessSnapshot, started tim
r.SetGauge("orbit_pulse_task_terminal_latency_max_seconds", snapshot.TaskTerminalLatencyMaxSeconds, nil)
r.SetGauge("orbit_weave_workflow_terminal_latency_seconds", snapshot.WorkflowTerminalLatencySeconds, nil)
r.SetGauge("orbit_weave_workflow_terminal_latency_max_seconds", snapshot.WorkflowTerminalLatencyMaxSeconds, nil)
r.SetGauge("orbit_pulse_task_accept_to_start_latency_seconds", snapshot.TaskAcceptToStartLatencySeconds, nil)
r.SetGauge("orbit_pulse_task_accept_to_start_latency_max_seconds", snapshot.TaskAcceptToStartLatencyMaxSeconds, nil)
r.SetGauge("orbit_pulse_task_accept_to_terminal_latency_seconds", snapshot.TaskAcceptToTerminalLatencySeconds, nil)
r.SetGauge("orbit_pulse_task_accept_to_terminal_latency_max_seconds", snapshot.TaskAcceptToTerminalLatencyMaxSeconds, nil)
r.SetGauge("orbit_weave_workflow_start_to_terminal_latency_seconds", snapshot.WorkflowStartToTerminalLatencySeconds, nil)
r.SetGauge("orbit_weave_workflow_start_to_terminal_latency_max_seconds", snapshot.WorkflowStartToTerminalLatencyMaxSeconds, nil)
r.SetGauge("orbit_pulse_tasks_oldest_age_seconds", snapshot.TaskOldestAgeSeconds, nil)
r.SetGauge("orbit_result_delivery_oldest_age_seconds", snapshot.DeliveryOldestAgeSeconds, nil)
r.SetGauge("orbit_weave_workflow_oldest_age_seconds", snapshot.WorkflowOldestAgeSeconds, nil)

View File

@@ -10,7 +10,7 @@ var taskStates = []string{"WAITING", "LEASED", "RUNNING", "NEEDS_REVIEW", "SUCCE
var deliveryStates = []string{"PENDING", "LEASED", "ACKED", "EXPIRED"}
var workflowStates = []string{"RUNNING", "WAITING", "CANCELLING", "NEEDS_REVIEW", "SUCCEEDED", "FAILED", "CANCELLED"}
var inboxStates = []string{"PENDING", "LEASED", "PROCESSED", "QUARANTINED"}
var eventTypes = []string{"task.accepted", "task.started", "task.succeeded", "task.failed", "task.needs_review", "task.requeued", "workflow.started", "workflow.advanced", "workflow.recovered", "workflow.blocked", "workflow.stopped"}
var eventTypes = []string{"task.accepted", "task.started", "task.succeeded", "task.failed", "task.cancelled", "task.needs_review", "task.requeued", "workflow.started", "workflow.advanced", "workflow.recovered", "workflow.blocked", "workflow.stopped"}
// Every exported family is declared here, including each allowed label value.
// Adding a metric therefore requires a code review; no user identifier is valid.
@@ -51,6 +51,12 @@ func catalog() map[string]descriptor {
c["orbit_pulse_task_terminal_latency_max_seconds"] = descriptor{gauge, "Maximum sampled Pulse task create-to-terminal latency in seconds", nil}
c["orbit_weave_workflow_terminal_latency_seconds"] = descriptor{gauge, "Average sampled Weave workflow create-to-terminal latency in seconds", nil}
c["orbit_weave_workflow_terminal_latency_max_seconds"] = descriptor{gauge, "Maximum sampled Weave workflow create-to-terminal latency in seconds", nil}
c["orbit_pulse_task_accept_to_start_latency_seconds"] = descriptor{gauge, "Average sampled Pulse task accepted-to-start latency in seconds", nil}
c["orbit_pulse_task_accept_to_start_latency_max_seconds"] = descriptor{gauge, "Maximum sampled Pulse task accepted-to-start latency in seconds", nil}
c["orbit_pulse_task_accept_to_terminal_latency_seconds"] = descriptor{gauge, "Average sampled Pulse task accepted-to-terminal latency in seconds", nil}
c["orbit_pulse_task_accept_to_terminal_latency_max_seconds"] = descriptor{gauge, "Maximum sampled Pulse task accepted-to-terminal latency in seconds", nil}
c["orbit_weave_workflow_start_to_terminal_latency_seconds"] = descriptor{gauge, "Average sampled Weave workflow started-to-terminal latency in seconds", nil}
c["orbit_weave_workflow_start_to_terminal_latency_max_seconds"] = descriptor{gauge, "Maximum sampled Weave workflow started-to-terminal latency in seconds", nil}
c["orbit_business_snapshot_total"] = descriptor{counter, "Completed bounded business-state snapshots by outcome", map[string][]string{"outcome": {"success", "error", "timeout"}}}
c["orbit_business_snapshot_duration_seconds"] = descriptor{histogram, "Bounded business-state snapshot duration in seconds", nil}
c["orbit_business_snapshot_last_success_timestamp_seconds"] = descriptor{gauge, "Unix time of the last successful bounded business-state snapshot", nil}

View File

@@ -128,6 +128,9 @@ func TestBusinessSnapshotKeepsLastGoodStateOnFailure(t *testing.T) {
RecentEvents: map[string]uint64{"task.accepted": 5},
TaskTerminalLatencySeconds: 2.5, TaskTerminalLatencyMaxSeconds: 7.5,
WorkflowTerminalLatencySeconds: 3.5, WorkflowTerminalLatencyMaxSeconds: 9.5,
TaskAcceptToStartLatencySeconds: 1.5, TaskAcceptToStartLatencyMaxSeconds: 4.5,
TaskAcceptToTerminalLatencySeconds: 5.5, TaskAcceptToTerminalLatencyMaxSeconds: 8.5,
WorkflowStartToTerminalLatencySeconds: 6.5, WorkflowStartToTerminalLatencyMaxSeconds: 10.5,
Truncated: true,
}, started, nil)
first := r.Render()
@@ -139,6 +142,9 @@ func TestBusinessSnapshotKeepsLastGoodStateOnFailure(t *testing.T) {
`orbit_business_events_recent{event="task.accepted"} 5`,
"orbit_pulse_task_terminal_latency_seconds 2.5",
"orbit_weave_workflow_terminal_latency_max_seconds 9.5",
"orbit_pulse_task_accept_to_start_latency_seconds 1.5",
"orbit_pulse_task_accept_to_terminal_latency_max_seconds 8.5",
"orbit_weave_workflow_start_to_terminal_latency_seconds 6.5",
"orbit_pulse_tasks_oldest_age_seconds 12.5",
"orbit_weave_inbox_oldest_age_seconds 3.25",
"orbit_business_snapshot_truncated 1",

View File

@@ -4,6 +4,7 @@ import (
"context"
"database/sql"
"errors"
"sort"
"time"
)
@@ -41,6 +42,18 @@ type OperationalSnapshot struct {
WorkflowTerminalLatencySeconds float64
// WorkflowTerminalLatencyMaxSeconds 是最近窗口终态流程样本的最大耗时。
WorkflowTerminalLatencyMaxSeconds float64
// TaskAcceptToStartLatencySeconds 是最近窗口任务从受理事件到开始事件的平均耗时样本。
TaskAcceptToStartLatencySeconds float64
// TaskAcceptToStartLatencyMaxSeconds 是最近窗口任务受理到开始耗时样本的最大值。
TaskAcceptToStartLatencyMaxSeconds float64
// TaskAcceptToTerminalLatencySeconds 是最近窗口任务从受理到确定终态事件的平均耗时样本。
TaskAcceptToTerminalLatencySeconds float64
// TaskAcceptToTerminalLatencyMaxSeconds 是最近窗口任务受理到确定终态耗时样本的最大值。
TaskAcceptToTerminalLatencyMaxSeconds float64
// WorkflowStartToTerminalLatencySeconds 是最近窗口流程从开始到停止事件的平均耗时样本。
WorkflowStartToTerminalLatencySeconds float64
// WorkflowStartToTerminalLatencyMaxSeconds 是最近窗口流程开始到停止耗时样本的最大值。
WorkflowStartToTerminalLatencyMaxSeconds float64
}
var (
@@ -48,7 +61,8 @@ var (
operationalDeliveryStates = []string{"PENDING", "LEASED", "ACKED", "EXPIRED"}
operationalWorkflowStates = []string{"RUNNING", "WAITING", "CANCELLING", "NEEDS_REVIEW", "SUCCEEDED", "FAILED", "CANCELLED"}
operationalInboxStates = []string{"PENDING", "LEASED", "PROCESSED", "QUARANTINED"}
operationalEventTypes = []string{"task.accepted", "task.started", "task.succeeded", "task.failed", "task.needs_review", "task.requeued", "workflow.started", "workflow.advanced", "workflow.recovered", "workflow.blocked", "workflow.stopped"}
operationalEventTypes = []string{"task.accepted", "task.started", "task.succeeded", "task.failed", "task.cancelled", "task.needs_review", "task.requeued", "workflow.started", "workflow.advanced", "workflow.recovered", "workflow.blocked", "workflow.stopped"}
phaseEventTypes = []string{"task.accepted", "task.started", "task.succeeded", "task.failed", "task.cancelled", "workflow.started", "workflow.stopped"}
)
// ReadOperationalSnapshot performs only bounded, indexed reads. It is intended
@@ -105,6 +119,10 @@ func ReadOperationalSnapshot(ctx context.Context, db *sql.DB) (OperationalSnapsh
if err != nil {
return OperationalSnapshot{}, err
}
phaseLatency, err := sampledPhaseLatency(ctx, db, now.Add(-operationalMetricEventWindow))
if err != nil {
return OperationalSnapshot{}, err
}
return OperationalSnapshot{
TaskStates: tasks, TaskOldestAgeSeconds: taskAge,
DeliveryStates: deliveries, DeliveryOldestAgeSeconds: deliveryAge,
@@ -113,7 +131,10 @@ func ReadOperationalSnapshot(ctx context.Context, db *sql.DB) (OperationalSnapsh
RecentEvents: events,
TaskTerminalLatencySeconds: taskLatency.average, TaskTerminalLatencyMaxSeconds: taskLatency.maximum,
WorkflowTerminalLatencySeconds: workflowLatency.average, WorkflowTerminalLatencyMaxSeconds: workflowLatency.maximum,
Truncated: taskTruncated || deliveryTruncated || workflowTruncated || inboxTruncated || eventTruncated || taskLatency.truncated || workflowLatency.truncated,
TaskAcceptToStartLatencySeconds: phaseLatency.taskAcceptToStart.average, TaskAcceptToStartLatencyMaxSeconds: phaseLatency.taskAcceptToStart.maximum,
TaskAcceptToTerminalLatencySeconds: phaseLatency.taskAcceptToTerminal.average, TaskAcceptToTerminalLatencyMaxSeconds: phaseLatency.taskAcceptToTerminal.maximum,
WorkflowStartToTerminalLatencySeconds: phaseLatency.workflowStartToTerminal.average, WorkflowStartToTerminalLatencyMaxSeconds: phaseLatency.workflowStartToTerminal.maximum,
Truncated: taskTruncated || deliveryTruncated || workflowTruncated || inboxTruncated || eventTruncated || taskLatency.truncated || workflowLatency.truncated || phaseLatency.truncated,
}, nil
}
@@ -168,6 +189,122 @@ type terminalLatencySample struct {
truncated bool
}
type phaseLatencySamples struct {
taskAcceptToStart terminalLatencySample
taskAcceptToTerminal terminalLatencySample
workflowStartToTerminal terminalLatencySample
truncated bool
}
type phaseEvent struct {
kind string
id string
typeName string
at time.Time
}
// sampledPhaseLatency pairs only fixed event types in the recent bounded
// window. Missing history, retries and events outside the window are excluded;
// the result is a trend sample rather than an end-to-end SLO.
func sampledPhaseLatency(ctx context.Context, db *sql.DB, cutoff time.Time) (phaseLatencySamples, error) {
placeholders := "?"
args := make([]any, 0, len(phaseEventTypes)+2)
args = append(args, phaseEventTypes[0])
for _, eventType := range phaseEventTypes[1:] {
placeholders += ",?"
args = append(args, eventType)
}
args = append([]any{cutoff}, args...)
args = append(args, operationalMetricSampleLimit+1)
query := "SELECT aggregate_kind,aggregate_id,type,occurred_at FROM orbit_events FORCE INDEX (ix_event_observe_type_occurred) WHERE occurred_at>=? AND type IN (" + placeholders + ") LIMIT ?"
rows, err := db.QueryContext(ctx, query, args...)
if err != nil {
return phaseLatencySamples{}, err
}
defer rows.Close()
tasks := make(map[string][]phaseEvent)
workflows := make(map[string][]phaseEvent)
read := 0
for rows.Next() {
read++
var event phaseEvent
var id []byte
if err := rows.Scan(&event.kind, &id, &event.typeName, &event.at); err != nil {
return phaseLatencySamples{}, err
}
if read <= operationalMetricSampleLimit {
event.id = string(id)
switch event.kind {
case "task":
tasks[event.id] = append(tasks[event.id], event)
case "workflow":
workflows[event.id] = append(workflows[event.id], event)
}
}
}
if err := rows.Err(); err != nil {
return phaseLatencySamples{}, err
}
result := phaseLatencySamples{truncated: read > operationalMetricSampleLimit}
result.taskAcceptToStart = pairPhaseLatencies(tasks, "task.accepted", "task.started")
result.taskAcceptToTerminal = pairPhaseLatencies(tasks, "task.accepted", "task.succeeded", "task.failed", "task.cancelled")
result.workflowStartToTerminal = pairPhaseLatencies(workflows, "workflow.started", "workflow.stopped")
result.taskAcceptToStart.truncated = false
result.taskAcceptToTerminal.truncated = false
result.workflowStartToTerminal.truncated = false
return result, nil
}
func pairPhaseLatencies(groups map[string][]phaseEvent, from string, to ...string) terminalLatencySample {
targets := make(map[string]struct{}, len(to))
for _, eventType := range to {
targets[eventType] = struct{}{}
}
var total, maximum float64
var count int
for _, events := range groups {
sort.Slice(events, func(i, j int) bool {
if events[i].at.Equal(events[j].at) {
return events[i].id < events[j].id
}
return events[i].at.Before(events[j].at)
})
var start *time.Time
var finish *time.Time
for _, event := range events {
if event.typeName == from && start == nil {
at := event.at.UTC()
start = &at
continue
}
if start != nil {
if _, ok := targets[event.typeName]; ok && !event.at.Before(*start) {
at := event.at.UTC()
finish = &at
break
}
}
}
if start == nil || finish == nil {
continue
}
seconds := finish.Sub(*start).Seconds()
if seconds < 0 {
seconds = 0
}
total += seconds
if seconds > maximum {
maximum = seconds
}
count++
}
result := terminalLatencySample{maximum: maximum}
if count > 0 {
result.average = total / float64(count)
}
return result
}
func sampledTerminalLatency(ctx context.Context, db *sql.DB, table, index string, states []string, cutoff time.Time) (terminalLatencySample, error) {
placeholders := "?"
args := make([]any, 0, len(states)+2)

View File

@@ -90,6 +90,12 @@ func TestIntegrationOperationalSnapshot(t *testing.T) {
}
}
f.exec("UPDATE pulse_tasks SET state='SUCCEEDED', completed_at=UTC_TIMESTAMP(6), updated_at=UTC_TIMESTAMP(6), revision=revision+1 WHERE namespace_id=? AND id=?", f.resources.NamespaceID, task.ID)
for _, event := range []struct {
revision uint64
typeName string
}{{2, "task.started"}, {3, "task.succeeded"}} {
f.exec("INSERT INTO orbit_events(namespace_id,id,aggregate_kind,aggregate_id,aggregate_revision,type,payload,occurred_at) VALUES (?,?,'task',?,?,?,'{}',UTC_TIMESTAMP(6))", f.resources.NamespaceID, executionID(t), task.ID, event.revision, event.typeName)
}
completed, err := ReadOperationalSnapshot(ctx, db)
if err != nil {
t.Fatal(err)
@@ -97,6 +103,9 @@ func TestIntegrationOperationalSnapshot(t *testing.T) {
if completed.TaskTerminalLatencySeconds < 0 || completed.TaskTerminalLatencyMaxSeconds < 0 {
t.Fatalf("negative terminal latency: %#v", completed)
}
if completed.TaskAcceptToStartLatencySeconds < 0 || completed.TaskAcceptToTerminalLatencySeconds < 0 {
t.Fatalf("negative task phase latency: %#v", completed)
}
cancelled, cancelNow := context.WithCancel(ctx)
cancelNow()