mutex 出问题了？强大的 goroutine 诊断工具
争做团队核心程序员，关注「幽鬼」
大家好，我是程序员幽鬼。
想象一下，你的 Go 服务不知何故陷入了困境：无法响应请求而且指标保持不变。出事了！但是你怎么能解决这个难题呢？如果构建中没有包含分析（profiling）工具，首先想到的是生成并分析故障转储文件（coredump）。这听起来像另一个需要你解决的难题吗？不用担心。因为在本文中，我将向你展示如何做到这一点！
Go 生态系统提供了大量分析工具来帮助你识别性能瓶颈并定位潜在的错误。我无法想象 Go 项目中没有 pprof[1] 和 gops[2] 的情况。我在本地环境中开发时，它们给了我很多帮助。然而，在生产环境，我们通常不包括 profiling 代理。当然，有时奇怪的事情只会发生在真实世界中。
最近，我们对生产环境的 AnyCable[3]（我们强大的 WebSocket 服务器，用于 Go 编写的 Ruby 应用程序）进行了压力测试。一切都按计划进行（触发警报、自动缩放 Pod 等等）。但是，在我们的一次测试运行后检查指标时，我注意到了一些可疑的行为：
测试已经完成，但其中一个 pod 仍然报告大量连接的 WebSocket。而且这个数字之后并没有变化。为什么？
我查看了其他指标，发现了更多异常：没有发送外发消息，也没有传输广播。就好像有人刚刚按下了暂停按钮。或者，事实证明，是因为 sync.RWMutex[4].
01 没有互斥锁是不行的
在讨论实际分析之前，让我提供一个有关代码的简化示例。
AnyCable 服务器中有一个 故障点 单元 Hub[5]，负责将消息路由到连接的客户端。每个客户端都有一个唯一的 ID 和一个订阅流的列表。在任何特定的流中，无论何时出现消息，我们都应该获取其关联客户端的列表，然后将消息发送到它们的套接字。我们使用 Go map 来存储流到客户端的映射，并且由于客户端的订阅和数据广播是并发发生的，因此我们需要一个互斥锁来避免在访问此 map 时出现竞争条件。最后，我们知道我们从这个映射中读取比写入它的次数更多，因此使用了读写互斥锁 ( sync.RWMutex)：
type Hub struct {
// Maps client IDs to clients.
clients map[string]*Client
// Maps streams to clients
// (stream -> client id -> struct{}).
streams map[string]map[string]struct{}
// A goroutine pool is used to do the actual broadcasting work.
pool *GoPool
mu sync.RWMutex
}
func NewHub() *Hub {
return &Hub{
clients: make(map[string]*Client),
streams: make(map[string]map[string]struct{}),
// Initialize a pool with 1024 workers.
pool: NewGoPool(1024),
}
}
func (h *Hub) subscribeSession(c *Client, stream string) {
h.mu.Lock()
defer h.mu.Unlock()
if _, ok := h.clients[c.ID]; !ok {
h.clients[c.ID] = c
}
if _, ok := h.streams[stream]; !ok {
h.streams[stream] = make(map[string]map[string]bool)
}
h.streams[stream][c.ID] = struct{}{}
}
func (h *Hub) unsubscribeSession(c *Client, stream string) {
h.mu.Lock()
defer h.mu.Unlock()
if _, ok := h.clients[c.ID]; !ok {
return
}
delete(h.clients, c.ID)
if _, ok := h.streams[stream]; !ok {
return
}
delete(h.streams[stream], c.ID)
}
func (h *Hub) broadcastToStream(stream string, msg string) {
// First, we check if we have a particular stream,
// if not, we return.
// Note that here we use a read lock here.
h.mu.RLock()
defer h.mu.RUnlock()
if _, ok := h.streams[stream]; !ok {
return
}
// If there is a stream, schedule a task.
h.pool.Schedule(func() {
// Here we need to acquire a lock again
// since we're reading from the map.
h.mu.RLock()
defer h.mu.RUnlock()
if _, ok := h.streams[stream]; !ok {
return
}
for id := range h.streams[stream] {
client, ok := h.clients[id]
if !ok {
continue
}
client.Send(msg)
}
})
}
GoPool 的实现超出了本文的范围。如果所有 workers 都忙并且内部池的缓冲区已满，则知道pool.Schedule阻塞就足够了。
仔细看看上面的 Grafana 图表。你可以看到问题发生在我们同时断开数千个连接时（在这种特殊情况下，这是因为内存不足异常导致我们的基准测试客户端崩溃）。
我提取了我们在生产中使用的同一个 Docker 镜像。然后，在本地运行，我开始使用相同的 k6 场景攻击它。经过长时间的围攻，我设法重现了该错误，并且我的 AnyCable 服务器无法响应了。
02 一个 goroutine 转储
有一个问题：我们如何才能看到任意 Go 进程内部发生了什么？或者，更准确地说，我们如何才能看到所有 goroutine 在任何给定时刻都在做什么？如果我们能破解它，它可以帮助我们弄清楚为什么他们不处理我们的请求。
幸运的是，每个 Go 程序都带有一个默认 SIGQUIT 信号处理程序[6]的开箱即用的解决方案 。收到此信号后，程序将堆栈转储打印到 stderr 并退出。
让我们通过一个例子，看看它是如何工作的：
// example.go
package main
func main() {
ch := make(chan (bool), 1)
go func() {
readForever(ch)
}()
writeForever(ch)
}
func readForever(ch chan (bool)) {
for {
<-ch
}
}
func writeForever(ch chan (bool)) {
for {
ch <- true
}
}
运行这个程序并通过 CTRL+\ 发送一个 SIGQUIT 来终止它：
go run example.go
// CTRL+\
^\SIGQUIT: quit
PC=0x1054caa m=0 sigcode=0
goroutine 5 [running]:
main.readForever(...)
/path/to/example.go:15
main.main.func1()
/path/to/example.go:7 +0x2a fp=0xc0000447e0 sp=0xc0000447b8 pc=0x1054caa
runtime.goexit()
/path/to/go/1.17/libexec/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc0000447e8 sp=0xc0000447e0 pc=0x1051f41
created by main.main
/path/to/example.go:6 +0x70
goroutine 1 [chan send]:
main.writeForever(...)
/path/to/example.go:21
main.main()
/path/to/example.go:10 +0x85
// some Assembly registers
exit status 2
我们可以看到一个 goroutine 正在执行 readForever，而另一个 goroutine 正在将数据发送到writeForever，没有惊奇之处。
如果正在运行的 Go 进程没有附加终端，我们可以使用以下 kill命令发送信号：
kill -SIGQUIT <process id>
对于 Docker，我们需要向正在运行的容器发送 SIGQUIT。没问题：
docker kill --signal=SIGQUIT <container_id>
# Then, grab the stack dump from the container logs.
docker logs <container_id>
对于上面的最小示例，Dump（是的，大写的 “D”）仅包含几个 goroutine 和十几行文本。但是，对于我们一直在查看的生产项目，该文件包含 4663 个 goroutines 和大约 70k LOC ——这并不是一个简单的快速消化就可以理解的东西。我们需要找一个机器人来帮忙。
03 介绍 goroutine-inspect 并深入研究 RWMutex 内部
在 GitHub 上快速搜索后，我找到了一个名为 goroutine-inspect[7] 的工具。它是一个 pprof 风格的交互式 CLI，它允许你操作堆栈转储、过滤掉不相关的跟踪或搜索特定功能。
下面是我执行的操作列表，以及最后几个 goroutines，它们最终阐明了这个问题：
# First, we load a dump and store a reference to it in the 'a' variable.
> a = load("tmp/go-crash-1.dump")
# The show() function prints a summary.
> a.show()
\# of goroutines: 4663
IO wait: 7
chan receive: 1029
chan send: 2572
idle: 1
select: 12
semacquire: 1041
syscall: 1
goroutine-inspect 最有用的功能之一 是 dedup()函数，它通过堆栈跟踪对 goroutine 进行分组：
> a.dedup()
# of goroutines: 27
IO wait: 5
chan receive: 5
chan send: 1
idle: 1
select: 8
semacquire: 6
syscall: 1
哇！我们最终只有 27 个独特的堆栈！现在我们可以扫描它们并删除不相关的：
> a.delete(...) # delete many routines by their ids
# of goroutines: 8
chan send: 1
select: 2
semacquire: 5
在删除了所有 安全的goroutine（HTTP 服务器、gRPC 客户端等）之后，我们得到了最后 8 个。我发现了多个包含broadcastToStream和 subscribeSesssion功能的痕迹 。为什么他们没有被删除？让我们仔细看看：
> a.search("contains(trace, 'subscribeSesssion')")
goroutine 461 [semacquire, 14 minutes]: 820 times: [461,...]
sync.runtime_SemacquireMutex(0xc0000b9380, 0x8a, 0xc0035e9b98)
/usr/local/Cellar/go/1.17/libexec/src/runtime/sema.go:71 +0x25
sync.(*Mutex).lockSlow(0xc000105e68)
/usr/local/Cellar/go/1.17/libexec/src/sync/mutex.go:138 +0x165
sync.(*Mutex).Lock(...)
/usr/local/Cellar/go/1.17/libexec/src/sync/mutex.go:81
sync.(*RWMutex).Lock(0x8d27a0)
/usr/local/Cellar/go/1.17/libexec/src/sync/rwmutex.go:111 +0x36
github.com/anycable/anycable-go/node.(*Hub).subscribeSession(0xc000105e00, {0xc003f83bf0, 0x15}, {0xc0021c8b40, 0x478f5e}, {0xc00364b790, 0xc5})
/Users/palkan/dev/anycable/anycable-go/node/hub.go:281 +0x85
goroutine 88 [semacquire, 14 minutes]: 1 times: [88]
sync.runtime_SemacquireMutex(0xc005e6bb60, 0x0, 0xc002e9d1e0)
/usr/local/Cellar/go/1.17/libexec/src/runtime/sema.go:71 +0x25
sync.(*RWMutex).Lock(0x8d27a0)
/usr/local/Cellar/go/1.17/libexec/src/sync/rwmutex.go:116 +0x71
github.com/anycable/anycable-go/node.(*Hub).subscribeSession(0xc000105e00, {0xc003716138, 0x15}, {0xc00231e640, 0x478f5e}, {0xc0035911e0, 0xc5})
/Users/palkan/dev/anycable/anycable-go/node/hub.go:281 +0x85
在这里，820（❗）个例程都在尝试获取写锁，这一切都很好。但是在 rwmutex.go:116唯一的 routine 是什么？我们来看一下 RWMutex 的源代码[8]：
// Wait for active readers.
if r != 0 && atomic.AddInt32(&rw.readerWait, r) != 0 {
runtime_SemacquireMutex(&rw.writerSem, false, 0)
}
它正在等待活跃的读者。🤔 但是为什么我们的读者不释放锁呢？是时候看看 broadcastToStream函数了：
> a.search("contains(trace, 'broadcastToStream')")
goroutine 515 [semacquire, 14 minutes]: 13 times: [515, ...]
sync.runtime_SemacquireMutex(0xc0004e0de0, 0xc0, 0xc0010de318)
/usr/local/Cellar/go/1.17/libexec/src/runtime/sema.go:71 +0x25
sync.(*RWMutex).RLock(...)
/usr/local/Cellar/go/1.17/libexec/src/sync/rwmutex.go:63
github.com/anycable/anycable-go/node.(*Hub).broadcastToStream.func1()
/Users/palkan/dev/anycable/anycable-go/node/hub.go:355 +0x8b
github.com/anycable/anycable-go/utils.(*GoPool).worker(0xc0001fc1b0, 0x0)
/Users/palkan/dev/anycable/anycable-go/utils/gopool.go:106 +0xa8
created by github.com/anycable/anycable-go/utils.(*GoPool).schedule
/Users/palkan/dev/anycable/anycable-go/utils/gopool.go:94 +0x12f
goroutine 418 [select, 14 minutes]: 1 times: [418]
github.com/anycable/anycable-go/utils.(*GoPool).schedule(0xc0001fc1b0, 0xc001e2ff20, 0xc00231e000)
/Users/palkan/dev/anycable/anycable-go/utils/gopool.go:88 +0x94
github.com/anycable/anycable-go/utils.(*GoPool).Schedule(...)
/Users/palkan/dev/anycable/anycable-go/utils/gopool.go:78
github.com/anycable/anycable-go/node.(*Hub).broadcastToStream(0xc000105e00, {0xc00231e000, 0x0}, {0xc0023bc3c0, 0x0})
/Users/palkan/dev/anycable/anycable-go/node/hub.go:354 +0x278
github.com/anycable/anycable-go/node.(*Hub).Run(0xc000105e00)
/Users/palkan/dev/anycable/anycable-go/node/hub.go:114 +0x32e
created by github.com/anycable/anycable-go/node.(*Node).Start
/Users/palkan/dev/anycable/anycable-go/node/node.go:102 +0x68
如果你仔细查看上面的输出，你可能会发现不同之处：node/hub.go:355和 node/hub.go:354。对于我们的简化示例，这将是以下代码行：
func (h *Hub) broadcastToStream(stream string, msg string) {
h.mu.RLock()
defer h.mu.RUnlock()
if _, ok := h.streams[stream]; !ok {
return
}
h.pool.Schedule(func() { // 1 -> hub.go:345
h.mu.RLock() // 2 -> hub.go:346
defer h.mu.RUnlock()
// ...
})
}
等等，什么？在进入池之前，Hub 通过mu.RLock()调用来堵塞自己！但是我们RLock到处都在调用，为什么现在阻塞了？多个读者应该可以正常工作。好吧，除非写者 pending 等待：
if atomic.AddInt32(&rw.readerCount, 1) < 0 {
// A writer is pending, wait for it.
runtime_SemacquireMutex(&rw.readerSem, false, 0)
}
尽管在 broadcastSession 中使用 RLock，我们还引入了另一个潜在的阻塞调用—— pool.Schedule。这个调用发生在锁内！我们 defer 的好习惯在 Unlock 这里失败了。修复起来很简单，我们这样做：
func (h *Hub) broadcastToStream(stream string, msg string) {
h.mu.RLock()
- defer h.mu.RUnlock()
if _, ok := h.streams[stream]; !ok {
+ h.mu.RUnlock()
return
}
+ h.mu.RUnlock()
h.pool.Schedule(func() {
修复错误只需要几行代码，但在追踪它们的过程中，漫长而曲折的道路充满了惊喜和发现。在其他分析工具不可用或未显示全貌的情况下，分析堆栈转储文件可能是一种有用的策略。请记住，不要 panic！
原文链接：https://evilmartians.com/chronicles/what-could-go-wrong-with-a-mutex-or-the-go-profiling-story
参考资料
[1]pprof: https://pkg.go.dev/net/http/pprof
[2]gops: https://github.com/google/gops
[3]AnyCable: https://anycable.io/
[4]sync.RWMutex: https://pkg.go.dev/sync#RWMutex
[5]Hub: https://github.com/anycable/anycable-go/blob/master/node/hub.go
[6]默认 SIGQUIT 信号处理程序: https://pkg.go.dev/os/signal#hdr-Default_behavior_of_signals_in_Go_programs
[7]goroutine-inspect: https://github.com/linuxerwang/goroutine-inspect
[8]RWMutex 的源代码: https://github.com/golang/go/blob/ec5170397c724a8ae440b2bc529f857c86f0e6b1/src/sync/rwmutex.go
往期推荐
欢迎关注「幽鬼」，像她一样做团队的核心。