Go并发大坑：inconsistent mutex state 解决及心得体会

皇家茶壶

已于 2022-12-22 10:05:27 修改

阅读量940

点赞数 3

分类专栏： golang 并发文章标签： golang

于 2022-12-21 23:43:12 首次发布

本文链接：https://blog.csdn.net/breavo_raw/article/details/127833293

版权

golang 同时被 2 个专栏收录

2 篇文章 0 订阅

订阅专栏

并发

1 篇文章 0 订阅

订阅专栏

文章目录

前言
首次排查（未重视）
问题逐渐严重
加大排查力度
- 增加锁日志
- race detector
一次意外的复现
写在最后
- 解决问题所必需的品格

前言

大概在这篇文章发布数个月之前，某天，线上稳定运行的Go服务突然毫无征兆的发生了一次重启（系统框架是能够兜住普通的panic的），查看线上panic日志后，发现这段异常栈是在底层的标准库中抛出的，异常栈大概长这样：

fatal error: sync: inconsistent mutex state

goroutine 3571787 [running]:
runtime.throw(0x4e6ccbc, 0x1e)
        /usr/local/go/src/runtime/panic.go:1116 +0x72 fp=0xc0021dd378 sp=0xc0021dd348 pc=0x439512
sync.throw(0x4e6ccbc, 0x1e)
        /usr/local/go/src/runtime/panic.go:1102 +0x35 fp=0xc0021dd398 sp=0xc0021dd378 pc=0x46cbb5
sync.(*Mutex).lockSlow(0x8313a38)
        /usr/local/go/src/sync/mutex.go:147 +0x165 fp=0xc0021dd3e0 sp=0xc0021dd398 pc=0x47d2a5
sync.(*Mutex).Lock(...)
        /usr/local/go/src/sync/mutex.go:81
sync.(*Pool).pinSlow(0xc00007ec68, 0x0, 0x0)
        /usr/local/go/src/sync/pool.go:213 +0x271 fp=0xc0021dd460 sp=0xc0021dd3e0 pc=0x47de31
sync.(*Pool).pin(0xc00007ec68, 0xc00bb1fab2, 0x4)
        /usr/local/go/src/sync/pool.go:206 +0x65 fp=0xc0021dd488 sp=0xc0021dd460 pc=0x47db85
sync.(*Pool).Get(0xc00007ec68, 0x113, 0x1)
        /usr/local/go/src/sync/pool.go:128 +0x2f fp=0xc0021dd4d0 sp=0xc0021dd488 pc=0x47d82f
...
再往下就是一些更上层的代码，因为不是重点所以这里省略掉。

本以为就是一个普通的线上问题，很快就能修复，没想到之后就开启了为时2周的异常排查之路…（本篇省去了一些排查过程中走过的弯路）

首次排查（未重视）

出现问题后，笔者和同事们立马组织了排查工作。

第一次看到这串异常栈还是比较懵逼的，因为从异常栈里无法判断是哪里出错了，单从栈信息上看，发现是第三方库调用标准库sync.Pool的时候引发了一个锁异常（这个例子里第三方库是grpc，不是重点，因为后面其他用到sync.Pool的第三方库都会抛出这个异常）。

这时候同事们怀疑是第三方库或者物理机出现了问题（虽然之后证明不是），于是乎，开始有针对性的排查服务中有大量grpc并发调用的地方，并进行了一些尝试，比如将grpc调用切换成http，另一方面联系运维对服务运行的物理机进行排查。

最后的结果是，这段异常栈不在grpc上报了，变成在其他第三方库抛出（比如json-iterator，还有其他的，就不一一列举了）。而运维那边排查下来的结果，也是没有问题。这下笔者和同事们开始犯难了。由于该异常出现的频率较少（刚开始大概一周1～2次实例），加上暂时没有什么排查思路，故而再排查一段时间未果后，只能先记个todo了（毕竟还有其他工作）

另一个阻碍排查进度的问题是，线上的这个异常无法在其他环境复现，这才是要老命的。无法复现的问题只能纯靠经（瞎）验（猜）来排查，运气不好的话，可能几周都查不出来。

问题逐渐严重

刚开始由于上述问题在生产环境出现的不是很频繁（可能一周1～2次），加上在其他环境难以复现，排查的脚步在逐渐放缓（说的直白一点，就是有点麻木了，现在回过头来看，这是一个很不好的现象）。

但可以肯定的是，问题还一直存在着，并且不会自己消失。随着后面项目的迭代速度变快，直到某个周末，inconsistent mutex state 问题出现的更加频繁（这个时候异常崩溃重启已经达到一天5～8次），这直接影响到了我们线上系统的可用性（运维统计下来已经低于可用性4个9的标准），问题解决迫在眉睫。

加大排查力度

后续的时间里，我们加大了对该问题的排查力度，力求能够在尽可能短的时间内解决问题。笔者在这里将会一一介绍排查问题过程中的思路与手段

增加锁日志

首先，我们考虑以最简单直接的方式来排查线上问题——加日志。虽然程序的异常栈基本各不相同，但都在使用sync.pool途中加锁的代码处出现了异常，那我们就通过加日志的方法来查看加锁过程中哪些数据出现了异常。

这里排查的方法没有问题，但是思路出现了偏差，笔者小伙伴们一度认为是Go的锁代码逻辑可能有问题（其实是业务并发引起的，这个下面会讲到），于是便有了后面的梳理go mutex源码的过程。

既然要排查锁代码的问题（后面证明其实没问题），首先就需要理解go mutex的实现逻辑，我们进到mutex.go标准库文件中查看代码，可以看到整个锁的实现加上注释大概不到200行，可以说go锁的实现十分简洁明了。

这里简单介绍下Go语言中锁的实现逻辑，在 Go 语言中，互斥锁是通过 sync 包中的 Mutex 类型来实现的。这个类型定义如下：

type Mutex struct {
	// 内部存储互斥量和其他信息的结构体
	state int32
	sema uint32
}

Mutex 类型内部存储了一个状态值和一个信号量。状态值用于记录互斥体的当前状态，例如是否被锁定等。信号量则用于在互斥体被锁定时，将其他线程或协程阻塞。

源代码中暴露出去给外面使用的方法就更少了，只有两个：Lock()和Unlock()，分别对应加锁和解锁，完整的代码解析已经超出了本篇的范畴，感兴趣了的话可以自行查询资料学习，这里给出一片参考文章。

刚才提到的加日志主要是为了观察互斥锁中state值的变化，由于state记录了Mutex的四种状态（这里感叹一下state的巧妙设计，如果对与state还不理解的话建议先理解一下）：

是否被锁定
是否有协程被唤醒
是否处于饥饿状态
等待的协程数量

所以我们需要了解哪部分加锁过程导致了锁状态异常。由于这个异常是不可逆的，一旦出现，系统会直接崩溃，也就会导致本篇开头提到的实例重启，影响可用性

// mutex.go
...
// throw出来的异常无法通过recover包掉
throw("sync: inconsistent mutex state")
...

通过日志我们得知报错发生在程序尝试获取锁失败之后到进入阻塞之前，因为我们观测到state值在程序崩溃之前变成非常的大，如果按照state的设计来解读的话，我们能够得出当前有上亿个协程在阻塞队列中，这显然是一个错误的结论；

// 这是在 mutex.go中打的日志 old和new是state的某个瞬时状态
cas fail: old = 8, new = 9
cas fail: old = 8, new = 2
cas fail: old = 16, new = 17
cas fail: old = 8, new = 9
cas fail: old = 8, new = 9
...
fatal error: inconsistent mutex state, new = 692768617

可以看到state在某一时刻突变，导致加锁程序异常奔溃。

但是，在梳理过mutex.go的代码后，我们最终确信锁状态的异常还是大概率由外部引起，只是最终在互斥锁代码这里被程序捕捉到并最终抛出。

至于为什么state的会变成日志中的异常值，我们推测是不规范的并发逻辑写引发了 memory corruption（后视镜角度看的话，目前对于问题的诱因已经判断的比较准确了）

那么剩下的就是继续朝着并发异常的路子继续往下排查啦～

race detector

要检查并发问题，go 语言有一个专门的工具，叫做 race detector。它可以帮助我们发现 go 程序中的数据竞争问题。

race detector的使用非常简单，只需要在项目启动时在命令中加入-race参数即可，像这样

// xxx.go 是项目启动入口
go run -race xxx.go

如果在执行过程中发现了数据竞争问题，race detector 会在命令行中输出错误信息，包括并发异常的位置、发生的时间、以及相关的 goroutine 信息。

这里举一个简单的例子看一看，在以下这段代码中，定义了一个全局变量 x，并在两个 goroutine 中同时对其进行修改：

package main

import (
	"fmt"
	"sync"
	"time"
)

var x int

func main() {
	wg := sync.WaitGroup{}
	wg.Add(2)

	go func() {
		defer wg.Done()
		for i := 0; i < 10; i++ {
			x++
			time.Sleep(time.Millisecond * 100)
		}
	}()

	go func() {
		defer wg.Done()
		for i := 0; i < 10; i++ {
			x++
			time.Sleep(time.Millisecond * 100)
		}
	}()

	wg.Wait()
	fmt.Println(x)
}

执行 go run -race main.go 命令启动这段程序，如果存在数据竞争问题，则会看到如下输出：

==================
WARNING: DATA RACE
Read at 0x00c420086008 by goroutine 7:
  main.main.func2()
      /path/to/main.go:15 +0x7c

Previous write at 0x00c420086008 by goroutine 6:
  main.main.func1()
      /path/to/main.go:9 +0x7c

Goroutine 7 (running) created at:
  main.main()
      /path/to/main.go:14 +0x7b

Goroutine 6 (running) created at:
  main.main()
      /path/to/main.go:10 +0x7b

Found 1 data race(s)
exit status 66

从输出结果可以看出，在程序执行过程中发生了并发写问题。race detector 告诉我们，发生问题的位置在 main.go 文件的第 15 行，是由 goroutine 7 执行的修改全局变量x，而之前这个全局变量 x 又被 goroutine 6 修改了。

那么回到项目上，我们在开发环境开启race detector之后（千万别再生产环境开启，不然会严重拖慢服务），通过脚本模拟线上请求，确实发现了大量数据竞争（十几个人维护了几年的项目，出现问题也并不奇怪）。

由于问题发生已经不是在第一现场（距离第一次出现问题大概过去了1～2个月），不知道是哪一块的数据竞争导致了memory corruption 进而引发inconsistent mutex state，于是乎只能开始吭哧吭哧的一个一个改，这个过程是缓慢且令人沮丧的。

一次意外的复现

由于这个问题无法在开发环境复现，我们也就无法精准定位到具体哪一段代码会出现问题。

而这样的情况，在某个下午突然被打破了，某个同事在测试一个新的定时任务时，在开发环境触发了这个问题，这简直就是溺水之人的救命稻草。

根据同事的任务逻辑，我们在尝试多次执行，并能够稳定复现问题之后，将可疑点缩小到了某个特定的接口。后面，我们通过race detector加代码走查的方式，很快定位到了有问题的代码：一个记录代码耗时日志的方法中并发写了一个公共数组。

将这段代码修复上线后观察了1天，之前的问题没有再出现过，至此，inconsistent mutex state的问题终于得以解决，可以睡个好觉啦！！

写在最后

解决问题所必需的品格

回顾一下解决问题的过程可以发现，在问题出现后，未能引起小伙伴们足够的重视，以至于后面问题严重后需要投入更多的人力和时间去解决，这一点在今后的工作中要尽量避免。

另外必须提到的是，尽管这个问题很棘手（Google搜索inconsistent mutex state几乎没有好的解决方案，甚至相关的github issue还停留在一年前且仍未解决），但笔者的同事们依旧迎难而上，坚持寻找解决方案的精神让笔者受益匪浅。虽然过程比较辛苦，但是最终问题解决后的收获是足以让人欣喜的（解决问题的经验，go mutex源代码的理解等等）。

也许这就是咱互联网工作者所必需具备的品格吧：）

在这里插入图片描述