bigywater.tech
Go · 68

block 与 mutex profile:锁等待是怎么被记录的

block profile 和 mutex profile 都和锁有关,但记录的位置不同:一个记在等待的人那里,一个记在持锁释放的人那里。这篇用 8 个 goroutine 争同一把锁,把两个 profile 并排看,再看采样设置会让读数偏到多离谱。

1363.67 vs 1363.74 ms
block 记在 Lock 上、mutex 记在 Unlock 上的锁竞争总延迟
0–1761 ms
mutex fraction=100 时 5 次读数的范围,事件数 0–200
7 ns
无竞争的 Lock+Unlock,打开 profile 前后都是这个数

同一件事,两个视角

实测 · 本机执行输出
  TOTAL 0.201
  -- block profile(-top,delay):
    Type: delay
    Showing nodes accounting for 1564.82ms, 100% of 1564.82ms total
          flat  flat%   sum%        cum   cum%
     1363.67ms 87.15% 87.15%  1363.67ms 87.15%  sync.(*Mutex).Lock (inline)
      201.15ms 12.85%   100%   201.15ms 12.85%  sync.(*WaitGroup).Wait
             0     0%   100%  1363.67ms 87.15%  main.critical
             0     0%   100%   201.15ms 12.85%  main.main
             0     0%   100%  1363.67ms 87.15%  main.main.func1
             0     0%   100%   201.15ms 12.85%  runtime.main
  -- mutex profile(-top,delay):
    Type: delay
    Showing nodes accounting for 1363.74ms, 100% of 1363.74ms total
          flat  flat%   sum%        cum   cum%
     1363.74ms   100%   100%  1363.74ms   100%  sync.(*Mutex).Unlock (inline)
             0     0%   100%  1363.74ms   100%  main.critical
             0     0%   100%  1363.74ms   100%  main.main.func1

8 个 goroutine 每个在锁里睡 1 ms,共 160 次。block profile 里等待的时间记在 sync.(*Mutex).Lock(1363.67 ms),mutex profile 里同一段延迟记在 sync.(*Mutex).Unlock(1363.74 ms)。前者告诉你谁在等,后者告诉你谁占着锁耽误了别人。block profile 里还多了 WaitGroup.Wait 的 201.15 ms,是 main 在等。

只有 block 记 channel

实测 · 本机执行输出
  block profile:1 次事件,累计延迟 302 ms
  mutex profile:0 次事件,累计延迟 0 ms

main 在 channel 上等了 300 ms,block profile 记了 1 次事件 302 ms,mutex profile 是 0。所以“阻塞 profile 里什么都有”,而 mutex profile 专指 sync.Mutex/RWMutex 的竞争(本文只实验了 Mutex)。

采样会让读数飘

实测 · 本机执行输出
  block rate=        1, mutex fraction=  1:block 延迟   1568–  1571 ms(事件 160–160 次);mutex 延迟   1367–  1369 ms(事件 159–159 次)
  block rate=  1000000, mutex fraction= 10:block 延迟   1569–  1571 ms(事件 160–160 次);mutex 延迟    957–  1595 ms(事件 120–190 次)
  block rate=100000000, mutex fraction=100:block 延迟   1002–  2001 ms(事件 91–208 次);mutex 延迟      0–  1761 ms(事件 0–200 次)

全采样时读数稳定(160 次、1568–1571 ms)。mutex fraction=10 时事件数 120–190 次、延迟 957–1595 ms;fraction=100 时有的运行读到 0。线上为了省开销用 1/100 之类的比例,要多取几次再下结论。

代价不明显

实测 · 本机执行输出
  速率 0(无竞争的 Lock+Unlock):7 ns/次
  速率 0(8 个 goroutine 争同一把锁,各 200000 次):平均每次 125 ns
  速率 1(无竞争的 Lock+Unlock):7 ns/次
  速率 1(8 个 goroutine 争同一把锁,各 200000 次):平均每次 105 ns

这次测量里打开速率 1 没有让无竞争加锁变慢(7 ns 对 7 ns),争锁的情形还略快(125 对 105 ns,差在噪声里)。我只测了一次,不能据此说“零开销”,只能说在这个测法下没看到。

速率的含义不同

实测 · 本机执行输出
  SetBlockProfileRate controls the fraction of goroutine blocking events that
  are reported in the blocking profile. The profiler aims to sample an average
  of one blocking event per rate nanoseconds spent blocked.
  To include every blocking event in the profile, pass rate = 1. To turn off
  profiling entirely, pass rate <= 0.
  SetMutexProfileFraction controls the fraction of mutex contention events
  that are reported in the mutex profile. On average 1/rate events are
  reported. The previous rate is returned.
  To turn off profiling entirely, pass rate 0. To just read the current rate,
  pass rate < 0. (For n>1 the details of sampling may change.)

block 的 rate 是“每多少纳秒的阻塞采一个”,mutex 的 fraction 是“平均每多少个事件采一个”,文档还提示 n>1 时采样细节可能改变。两个数字别混着调。

分步演示

block 与 mutex profile
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / Go 1.27.1(brew);用 go run / go build / go test 直接编译运行,需要第三方库时经代理从 proxy.golang.org 下载;计时用 time.Now / testing.B,数字每次运行会有小幅抖动。被测程序:8 个 goroutine×20 次,每次在 sync.Mutex 里 time.Sleep(1ms);事件数与延迟用 go tool pprof -raw 读出再相加;第三节每种设置 5 次;读过的文档:go doc runtime.SetBlockProfileRate / SetMutexProfileFraction
    • 没有验证:RWMutex 的 mutex profile 记法、锁在 Unlock 处记账的具体机制(没有读源码)、Linux 上的结果、fraction 为其它值的行为、profile 开启对大量 goroutine 争锁的影响(只测了 8 个)
    京ICP备2026067502号-1京公网安备11010502063487号