diff --git a/AGENTS.md b/AGENTS.md index 53ebdf9..e653e8e 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -81,7 +81,7 @@ - A04须截留真实task.assign并独立确认LEASED/未授权，再强杀旧节点、Wait确认退出、新节点等原租约自然到期；不能把已送达未开始替代未送达。COMMIT故障工具只在测试二进制：BEFORE阻止COMMIT，AFTER核验真实MySQL成功包后丢确认；独立连接回读，原身份/候选恢复，禁止在生产增加故障开关或将HTTP丢回执替代数据库提交不明。 - W16下一轮时钟只能在PENDING结果已保存等待后存在，三方竞争中的结果参与者是旧结果重放；新结果/未知/冲突另有在途查询回归。保持原受理时间、事件时间、截止与预算，不能凭有限入队顺序声称穷尽线程交错。 -- P6进程观测使用internal/observability固定指标目录，拒绝未知名称、类型和动态标签，不能引入任务/租户/业务键/凭据维度。ORBIT_METRICS_ADDR默认空（关闭），显式启用独立采集监听；业务端口不得暴露全局指标。渲染和网络I/O不持有全局记录锁，每个直方图局部快照保持桶/count/sum一致，最多2个并发抓取。启用指标后的5秒后台采样使用000026–000028固定索引读取任务、交付、流程状态、Weave Inbox状态、固定事件类别和终态耗时，每个状态或事件最多10000条、事件窗口5分钟、900ms数据库截止；采样失败保留最后成功状态并独立记录错误/超时，不能影响业务事务或把有限样本当全局精确数。 +- P6进程观测使用internal/observability固定指标目录，拒绝未知名称、类型和动态标签，不能引入任务/租户/业务键/凭据维度。ORBIT_METRICS_ADDR默认空（关闭），显式启用独立采集监听；业务端口不得暴露全局指标。渲染和网络I/O不持有全局记录锁，每个直方图局部快照保持桶/count/sum一致，最多2个并发抓取。启用指标后的5秒后台采样使用000026–000028固定索引读取任务、交付、流程状态、Weave Inbox状态、固定事件类别、终态耗时和最近窗口内固定事件阶段耗时，每个状态或事件最多10000条、事件窗口5分钟、900ms数据库截止；采样失败保留最后成功状态并独立记录错误/超时，不能影响业务事务或把有限样本当全局精确数。 - HTTP成功升级在Hijack完成时记录握手，WS处理器存续计入独立连接指标；保持1xx临时响应、Flush、Hijack与原panic行为。DB池取本地Stats，抓取不查询业务库；后台批次success不是业务任务成功量。观测丢样或失败不得改变权威事务及恢复决定。 - 进程指标、固定状态采样、格式验证、告警规则和标准回归证据见docs/reports/phase-6-observability.md及docs/reports/phase-6-business-observability.md。仍须补受理/授权/完成与流程推进延迟、持久吞吐/积压的全局聚合、重试/核查/恢复量、发送队列、实际采集告警及负载开销，不能把进程观测通过写成P6已完成。普通清理仍须保护有效幂等、未确认事件、未知结果和未终结流程。 - 凭据轮换保留credential_id及订阅/Worker授权绑定，在同一事务替换摘要、固定到期时间、幂等回执和管理审计；新令牌必须重新建立会话，认证路径每次重新核对凭据状态。撤销必须让认证失效并保留原任务、订阅、交付、会话和审计证据，允许在应用或命名空间停用后执行；重复应用同一固定操作幂等返回。管理CLI先把固定操作文件写成0600，再提交；提交不明时保留文件并用原文件重放，不能重新生成秘密。日志、审计摘要、指标和业务表不得保存秘密原文或摘要。不要把轮换同一凭据ID解释成历史令牌仍有效，也不得级联删除订阅、任务或事件。 diff --git a/cmd/orbit/main.go b/cmd/orbit/main.go index 567059d..26f6676 100644 --- a/cmd/orbit/main.go +++ b/cmd/orbit/main.go @@ -204,6 +204,9 @@ func run() error { RecentEvents: snapshot.RecentEvents, TaskTerminalLatencySeconds: snapshot.TaskTerminalLatencySeconds, TaskTerminalLatencyMaxSeconds: snapshot.TaskTerminalLatencyMaxSeconds, WorkflowTerminalLatencySeconds: snapshot.WorkflowTerminalLatencySeconds, WorkflowTerminalLatencyMaxSeconds: snapshot.WorkflowTerminalLatencyMaxSeconds, + TaskAcceptToStartLatencySeconds: snapshot.TaskAcceptToStartLatencySeconds, TaskAcceptToStartLatencyMaxSeconds: snapshot.TaskAcceptToStartLatencyMaxSeconds, + TaskAcceptToTerminalLatencySeconds: snapshot.TaskAcceptToTerminalLatencySeconds, TaskAcceptToTerminalLatencyMaxSeconds: snapshot.TaskAcceptToTerminalLatencyMaxSeconds, + WorkflowStartToTerminalLatencySeconds: snapshot.WorkflowStartToTerminalLatencySeconds, WorkflowStartToTerminalLatencyMaxSeconds: snapshot.WorkflowStartToTerminalLatencyMaxSeconds, Truncated: snapshot.Truncated, }, started, err) if err != nil && metricsCtx.Err() == nil { diff --git a/docs/08-development-plan.md b/docs/08-development-plan.md index 3970c82..f5707f9 100644 --- a/docs/08-development-plan.md +++ b/docs/08-development-plan.md @@ -59,7 +59,7 @@ P4/P5定时等待与后续查询轮次的实现及回归记录见[时钟报告]( ### P6 首批实施顺序 1. 已补[首批可复现故障工具](reports/phase-6-fault-boundaries.md)：A04“派发已提交但消息尚未送达”、W01/W13事务提交结果不明，以及W16最终回执/旧PENDING结果重放/下一轮竞争。每个切点必须有实际数据库或进程证据，不能用响应错误推断事务是否已提交，也不能用普通SIGNAL竞争替代最终查询场景。 -2. 已实现[基础运行观测](api/observability.md)及[有界业务状态与事件采样](reports/phase-6-business-observability.md)：HTTP/WS、数据库连接池、后台批次、固定任务/交付/流程/Inbox状态计数、最近事件类别、终态耗时样本、最早年龄、截断/新鲜度指标和可离线验证的告警规则；独立采集监听默认关闭，固定指标目录拒绝动态标签；发布前只读结构核验由[`orbit-admin verify`](api/operations.md)提供。仍需受理/授权阶段端到端延迟与全局持久吞吐、Inbox从事件产生到推进完成的阶段延迟、全局发送队列、多节点聚合及生产采集/通知验证。 +2. 已实现[基础运行观测](api/observability.md)及[有界业务状态与事件采样](reports/phase-6-business-observability.md)：HTTP/WS、数据库连接池、后台批次、固定任务/交付/流程/Inbox状态计数、最近事件类别、终态耗时样本、固定事件阶段耗时、最早年龄、截断/新鲜度指标和可离线验证的告警规则；独立采集监听默认关闭，固定指标目录拒绝动态标签；发布前只读结构核验由[`orbit-admin verify`](api/operations.md)提供。仍需端到端外部效果延迟、全局持久吞吐、Inbox从事件产生到推进完成的精确阶段延迟、全局发送队列、多节点聚合及生产采集/通知验证。 3. 已补齐受保护管理环境中的固定凭据操作文件、轮换、撤销、幂等回执和脱敏管理审计；轮换保留授权绑定并要求新令牌重新建立会话，撤销允许在停用范围内执行且不改写历史记录。仍需补齐提交不明故障切点、多节点安全重绑演练、凭据最小权限配置核对和生产密钥托管/审计演练。 4. 已补[`orbit-admin retention inventory`](api/retention.md)只读盘点和[阶段报告](reports/phase-6-retention-inventory.md)，能区分过期幂等、确定终态、未知效果、未终结流程、已确认/未确认交付、已消费/未消费Inbox、事件和审计规模；它不执行归档或删除。后续仍需评审各类保留周期、归档格式、受保护记录核对，再执行备份恢复、兼容升级和六类容量负载。未确认交付、有效幂等身份、当前/历史执行证据和未终结流程不能被普通清理破坏。生产HA及RPO/RTO继续按实际拓扑验证，不缩减为本机多进程检查。 diff --git a/docs/api/observability.md b/docs/api/observability.md index a35944e..fed0f2d 100644 --- a/docs/api/observability.md +++ b/docs/api/observability.md @@ -58,6 +58,9 @@ curl -fsS http://127.0.0.1:9090/metrics | `orbit_business_events_recent{event}` | gauge | 最近5分钟内固定事件类别的有界数量，用于观察受理、完成、核查、恢复和流程推进趋势 | | `orbit_pulse_task_terminal_latency_seconds` / `_max_seconds` | gauge | 最近5分钟终态任务从创建到完成的平均/最大耗时样本，单位秒 | | `orbit_weave_workflow_terminal_latency_seconds` / `_max_seconds` | gauge | 最近5分钟终态流程从创建到完成的平均/最大耗时样本，单位秒 | +| `orbit_pulse_task_accept_to_start_latency_seconds` / `_max_seconds` | gauge | 最近5分钟同时采到 `task.accepted` 与 `task.started` 的任务受理到开始平均/最大耗时样本，单位秒 | +| `orbit_pulse_task_accept_to_terminal_latency_seconds` / `_max_seconds` | gauge | 最近5分钟同时采到任务受理与确定终态事件的平均/最大耗时样本，单位秒 | +| `orbit_weave_workflow_start_to_terminal_latency_seconds` / `_max_seconds` | gauge | 最近5分钟同时采到 `workflow.started` 与 `workflow.stopped` 的流程开始到停止平均/最大耗时样本，单位秒 | | `orbit_business_snapshot_total{outcome}` | counter | 有界业务快照成功、错误或超时次数 | | `orbit_business_snapshot_duration_seconds` | histogram | 有界业务快照耗时；包含数据库读取 | | `orbit_business_snapshot_last_success_timestamp_seconds` | gauge | 最近一次完整成功快照的Unix时间；失败不会推进 | diff --git a/docs/reports/phase-6-business-observability.md b/docs/reports/phase-6-business-observability.md index 630bd7c..16f877b 100644 --- a/docs/reports/phase-6-business-observability.md +++ b/docs/reports/phase-6-business-observability.md @@ -8,6 +8,7 @@ - 迁移 `000027_operational_event_metrics` 为不可变 `orbit_events` 增加 `(type,occurred_at,id)` 固定事件窗口索引；不增加模型字段，不引入外键或级联。 - 迁移 `000028_terminal_latency_metrics` 为任务和流程终态完成时间增加固定索引；采样最近5分钟成功/失败/取消记录，计算从持久化创建到终态的平均/最大耗时，仍不增加模型字段。 - 现有 `weave_inbox` 的固定 `ix_inbox_due` 已纳入采样：输出 `PENDING`、`LEASED`、`PROCESSED`、`QUARANTINED` 四种有界状态以及待消费事件的最早 `available_at` 年龄；不把该年龄误称为流程推进完成延迟。 +- 采样器按固定事件类型在最近5分钟内配对 `task.accepted`→`task.started`、`task.accepted`→确定终态以及 `workflow.started`→`workflow.stopped`，输出平均/最大阶段耗时；事件缺失、跨窗口或超过10000条上限的记录不进入样本。 - [存储采样器](../../internal/storage/mysql/operational_metrics.go)只拼接代码内固定的表、索引、列名、状态和事件集合。每个状态或事件类别使用索引读取最多10001条，再将结果封顶到10000；至少一类封顶时 `orbit_business_snapshot_truncated=1`。 - 采样器先读取数据库UTC时间，再读取任务、结果交付和流程实例固定状态计数、最早未完成年龄及最近5分钟受理/完成/核查/恢复/流程推进事件类别。所有调用由独立900ms上下文限制；取消、数据库错误和超时都返回失败，不修改持久化数据。 - [业务指标记录器](../../internal/observability/business.go)将成功、错误、超时分别计数并记录耗时。失败样本不覆盖最后一次成功状态，同时保留最后成功时间，方便告警区分“旧值可见”和“本轮采集失败”。标签基数和状态取值均在目录中固定。 @@ -19,10 +20,10 @@ - [业务记录器单测](../../internal/observability/metrics_test.go)验证成功状态、年龄、截断、成功计数和失败后保留最后成功值；超时计数单独增加。 - [真实MySQL专项](../../internal/storage/mysql/operational_metrics_integration_test.go)验证三次迁移索引真实存在、数据库外键为0、任务状态、交付状态、流程状态、Inbox状态、`task.accepted`事件和终态耗时被采样、固定状态集合存在，并验证已取消上下文被拒绝。 - `go test ./...`覆盖编译和普通单测；真实MySQL专项由标准`GO=... DOCKER=... sh scripts/test-mysql.sh`执行，未设置`ORBIT_TEST_MYSQL_DSN`时专项会跳过，不能把跳过当通过。最新000028标准脚本在Go 1.27.1、darwin/arm64、Docker MySQL 8.4.10环境退出码为0；存储/迁移/事务组、指标开关进程组、流程运行器全停恢复、SDK与两个独立业务示例均通过。日志确认`TestIntegrationOperationalSnapshot`、`TestIntegrationNoForeignKeysUpgrade`、`TestIntegrationCredentialOperations`、`TestIntegrationCredentialCommitFaults`、`TestIntegrationMetricsProcess`及`TestIntegrationWorkflowRuntimeProcess`均PASS，迁移账本到000028且dirty=false；脚本新增的`orbit-admin verify`实际输出`schema_version=28`、`migration_count=28`、`foreign_key_count=0`、`required_index_count=6`、`complete=true`。 -- 当前固定目录导出的指标夹具为930520字节，包含事件和Inbox标签回归；`promtool check metrics`成功；`promtool check rules deploy/monitoring/orbit.rules.yml`报告7条规则成功，`promtool test rules deploy/monitoring/orbit.rules.test.yml`成功。标准验证镜像仅用于离线检查，平台运行不依赖Prometheus。 +- 当前固定目录导出的指标夹具为932029字节，包含事件、Inbox和阶段耗时指标回归；`promtool check metrics`成功；`promtool check rules deploy/monitoring/orbit.rules.yml`报告7条规则成功，`promtool test rules deploy/monitoring/orbit.rules.test.yml`成功。标准验证镜像仅用于离线检查，平台运行不依赖Prometheus。 ## 解释和边界 每个Orbit节点都读取自己的有限样本；多节点指标不能直接相加获得全局精确积压或吞吐。达到10000上限、采样超时、节点重启或节点间时间不同都会影响解释，必须结合截断标记、最后成功时间、数据库权威查询和审计判断。事件窗口按`occurred_at`统计固定类别，不包含未知类型；它是趋势线索，不是端到端受理、授权或完成延迟。 -当前仍未完成端到端授权/外部效果阶段延迟、全局吞吐聚合、Inbox从事件产生到推进完成的精确阶段延迟、发送队列全局聚合、生产采集通知演练、锁/磁盘/复制指标和多故障域容量验证。此批实现不能替代保留、备份恢复、HA、RPO/RTO及发布验收。 +当前仍未完成端到端授权/外部效果阶段延迟、全局吞吐聚合、Inbox从事件产生到推进完成的精确阶段延迟、发送队列全局聚合、生产采集通知演练、锁/磁盘/复制指标和多故障域容量验证。事件配对阶段耗时是本节点有限趋势样本，不包含外部副作用，也不能替代这些验收。此批实现不能替代保留、备份恢复、HA、RPO/RTO及发布验收。 diff --git a/internal/observability/business.go b/internal/observability/business.go index e37af73..0684104 100644 --- a/internal/observability/business.go +++ b/internal/observability/business.go @@ -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) diff --git a/internal/observability/catalog.go b/internal/observability/catalog.go index ecc0cb9..4066132 100644 --- a/internal/observability/catalog.go +++ b/internal/observability/catalog.go @@ -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} diff --git a/internal/observability/metrics_test.go b/internal/observability/metrics_test.go index 6cdb67b..a44d698 100644 --- a/internal/observability/metrics_test.go +++ b/internal/observability/metrics_test.go @@ -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", diff --git a/internal/storage/mysql/operational_metrics.go b/internal/storage/mysql/operational_metrics.go index 7563b6c..07a53c5 100644 --- a/internal/storage/mysql/operational_metrics.go +++ b/internal/storage/mysql/operational_metrics.go @@ -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) diff --git a/internal/storage/mysql/operational_metrics_integration_test.go b/internal/storage/mysql/operational_metrics_integration_test.go index 38fc811..d60915c 100644 --- a/internal/storage/mysql/operational_metrics_integration_test.go +++ b/internal/storage/mysql/operational_metrics_integration_test.go @@ -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()