Go 36：trace 与阻塞 profile 怎样拆开等待时间

上篇用 CPU/heap 采样找函数和分配热点；任务卡在队列和锁上时，CPU profile 的低样本不表示请求没有延迟。本篇沿用同一任务服务制造两个可定位的等待点。原始 trace 和源码包、SHA-256、独立复跑步骤包含完整双流、退出码和可重新解析的二进制文件。

在两个任务 ID 上固定先后

TestTaskWaitProfiles 的执行器只有一个 worker、一个排队槽。task[0] 的分析器在 channel 闸门等待，主测试确认它进入 RUNNING 后提交 task[1]；第二条被接受但只能排队。第三次提交触发 503，并断言 task[2] 根本不存在。随后主测试短暂持有当前 TaskStore.mu，另一 goroutine 发出 GET task[0]，真实栈显示该 GET 卡在 TaskStore.Lookup 的 sync.Mutex.Lock。它不是“看见 GET 被调用就推测会阻塞”：测试必须看见该锁等待栈才解锁，超时则失败。

释放 channel 后调用 service.Close() 等 worker 退出，再检查两条记录均为 SUCCEEDED words=1。trace 事件记录 task[0] RUNNING、task[1] QUEUED、各自终态；worker 的 region 名称是 task[0] analyzer wait。这些可读名字在 go tool trace -d=parsed 原始输出中能逐条查到。region 的上下文来自 worker，Log 事件的 trace task 上下文来自测试；标签有同一个业务 ID，并不代表它们共享 trace 库内部的同一个 Task 编号。

三种 profile 记录的不是同一个时间

冻结 Go 1.27.1 的 SetBlockProfileRate(1) 让阻塞事件尽可能全部入样，SetMutexProfileFraction(1) 记录竞争事件；runtime/trace.Start 同时保存 trace.out。在本轮原始场景日志中，从确认 worker 检查点到查询解除锁等待的 blockedWall=5.296968ms；等两个任务退出的 completionWall=5.445355ms。这是墙钟，包含测试读取栈、跟踪记录与进程调度，不是 CPU 活跃时间，更不是生产单请求响应时长。

block.pprof 用 go tool pprof -top 可看到 TaskStore.Lookup 经 sync.(*Mutex).Lock 累积约 3.70ms，同一 profile 还记录 runtime.chanrecv1 约 6.79ms。这是不同 goroutine 的阻塞累计值，事件时间可能重叠，不能相加得到一次请求耗时。mutex.pprof 将竞争归于解锁侧：如果只看到一个 sync.(*Mutex).Unlock 热点，还需结合 lock 栈和业务闸门，才知道是哪个请求在等。go tool trace -pprof=sync 导出同步阻塞，-pprof=sched 导出调度延迟；二者和第 35 篇的 CPU 样本类型不同，不能把 sched 的微秒值叫作 worker 的 CPU 时间。采样、跟踪和日志都附加开销，本章不据此比较两种线上锁实现优劣。

练习：① task[1] 202 后排在队列里，能否推断它已经消耗了一个 CPU worker？不能，唯一 worker 正停在 task[0] 的 channel 闸门；只有 Close 后的终态证明第二条最终执行。② block profile 两个 5ms 等待，任务必定耗时 10ms 吗？不能，它们可并发重叠，且记录范围包含不同 goroutine。③ 锁的 mutex top 中一个 Unlock 样本可以定位业务 ID 吗？不能，先用 Lookup 的受控等待栈和 trace 里的任务 ID 对齐，再说明代码路径；单靠扁平 top 不够。

本章在真实 PostgreSQL 16.15 下另跑了累计 SQL 回归、两包测试和 race 实际路径，也独立解包重跑了三种 profile 及原始 trace 的解析；本次排队/锁场景本身不经 SQL 或真实网络。无 race 报告只限已跑路径，202 与 worker 完成、数据库提交与外部副作用都分别判定。远程网络、其他平台、含 36 的全站构建与发布 NOT_RUN。下一篇固定一条源码调用链，从公开入口追到状态变化与唤醒，再回到这个可复现实验。