一次嵌套读锁引发的死锁排查过程 https://mp.weixin.qq.com/s/ea4sq77TQZFdpYuhWly8eg

一次嵌套读锁引发的死锁排查过程 https://mp.weixin.qq.com/s/ea4sq77TQZFdpYuhWly8eg

一次嵌套读锁引发的死锁排查过程

原创 alon、andor 微保技术 2020-09-25 17:00

作者: andorccao(曹灿)、alonlong(龙武)

编辑: mavisxlmeng(蒙雪莲)

并发编程经常需要和锁打交道，读写锁允许并发读和独占写，能提高并发性。但使用不当容易引发死锁问题。

1

背景

微保业务使用的微服务架构。随着业务发展，原有的nginx/haproxy等代理服务无法满足复杂多变的需求，API网关应运而生。API网关主要实现负载均衡、路由、鉴权、控制访问、服务代理、监控等功能。

API网关作为C端的统一入口，对性能和稳定性有很高的要求，一次微小的波动就会成倍放大影响到业务服务。本文以微保API网关为例，逐步剖析读写锁嵌套误用引发的一次死锁bug。

2

发现

微保的核心业务，都有非常完善的监控和告警系统，便于我们快速发现和初步定位问题。本次问题的发现是告警系统发出一连串的超时警告，都指向C端访问后台的config服务超时（超过5秒）。

收到业务告警后，第一反应API网关应该没问题，毕竟网关自身没有收到告警，且API网关作为C端的流量入口，若有问题那其他业务告警早就炸了。打开API网关整体监控视图，并未发现明显异常（其实是监控数据比较分散没有立刻发现）。按照常理，一般超时大概率是网络问题，我们查看了内网网络状态和域名解析情况，均未发现异常。

看来需要根据日志来分析。面对这种大批量超时现象，任意抽一个API网关实例（共8个实例），未发现明显错误日志。

这时候就比较懵了，服务和网关都没有异常。考虑到超时对业务影响非常大，没太多时间深入分析问题。该祭出重启大法了。先重启config服务，未恢复；紧接着重启API网关服务，异常告警终于结束。看来是API网关的问题，接下来我们从多个维度一起分析。

3

分析

查看所有API网关实例日志，发现其中一个实例异常期间没有日志输出。正常情况下API网关每个请求都会打印日志，那么有几个方向值得怀疑：

1. 服务内部有死锁或阻塞
2. 日志库有问题，但日志库作为最常用的组件，不应该此时暴露出来（同时了解到近期没有更新）
3. 服务框架或系统假死，这个是最后验证的方向

由于没有保留现场和任何日志作为参考，定位难度很大，我们从外围熟悉的信息着手分析，缩小范围，然后再根据源码来定位（API网关使用的开源组件很多，这个方向会比较复杂）。

3.1 链路分析

先查API网关上下游的链路信息。有两条数据流：

1. CLB->haproxy->API网关
2. CLB->API网关

CLB是腾讯云提供的负载均衡服务。一般情况下CLB日志处于关闭状态。我们优先看第一条数据流，下图是haproxy的日志。

发现haproxy调用API网关的请求存在60s超时（CLB配置超时时间是60s），说明异常期间是API网关未响应导致的链路超时。

这里有个疑问：CLB有健康检查机制，管理的实例异常后会被CLB踢掉，为啥没有触发？

3.2 CLB健康检查

在CLB官方文档有健康检查的配置说明。

CLB每5秒发送一次GET请求，连续3次未收到就会踢掉异常后端服务，API网关未被踢掉表示这段时间能正常处理GET请求。再来看API网关健康检查适配代码：

这里能正常运行，说明请求已触达业务层面，不是框架层面的问题。其实这里有个关键点忽略了。正常情况要打印Warn日志的，与没日志的现象不符，所以日志库有问题（事后证明符合）。

3.3 监控视图分析

上图是异常实例的基础状态视图，异常期间内存、TCP alloc数明显增加，CPU没啥变化。解释下这些指标的含义：

1. CPU正常大概率表示服务没有死循环
2. TCP alloc一直增加说明服务能正常接收新的请求，但未调用close，无法正常关闭请求
3. 内存异常表示服务有资源未正常释放
4. 异常期间其他实例正常，说明网关转发的后台服务没有异常
5. 异常实例所处的机器其他服务正常，说明机器处于正常状态

综合上面的推论猜测是API网关服务自身处于假死状态，无法正常处理请求，且应该是请求入口处就卡死（没有日志）。

4

定位

常见的假死原因有：机器资源异常（IO异常、CPU、内存 100%），死循环，服务死锁。上面的分析可以排除机器资源问题。接下来重点分析服务假死的情况。

4.1 模拟死循环现象

一般死循环会导致CPU很高，但我们还是需要验证下golang协程死循环的表现是否一致。

上面这份代码。在golang 1.11之前的版本，存在死循环然后触发协程调度后，会导致服务假死。这种状态下TCP alloc，内存都会增加，CPU也会增加，与API网关异常的表现不一样。

到这一步就不得不查看API网关源码了。

4.2 全局资源死锁

先从容易排查定位。我们使用的是golang语言，常见的全局对象锁有sync.Map，如下图sync.Map的使用方式。经验证，即使doSomething函数阻塞也不影响Load函数执行。排除了全局资源不当使用的问题（其他全局资源没有显示使用锁）。

4.3 组件死锁

API网关使用的组件比较多，我们根据已知信息分批查看每个组件的源码。异常期间没有任何日志输出，日志库由我们自己实现，引入了较多的特性，是值得优先排查的方向。仔细阅读后，发现日志库有嵌套锁的使用（新特性误用锁导致嵌套）。众所周知，不同语言的锁机制支持程度有区别。查看golang中读写锁的文档，有明确说明禁止嵌套使用读写锁。

•  
•  
•  
•  
•  

If a goroutine holds a RWMutex for reading and another goroutine might call Lock, no goroutine should expect to be able to acquire a read lock until the initial read lock is released. In particular, this prohibits recursive read locking. This is to ensure that the lock eventually becomes available; a blocked Lock call excludes new readers from acquiring the lock

其实异常期间没有日志，我们早应该怀疑日志库的问题（被常识误导了）。接着对日志库进行压测，证明确实会触发死锁。日志库死锁触发的概率是极低的，需要同时满足下面情况：

1. 服务一个协程写日志时，刚好执行完嵌套读锁的第一个读锁
2. 此时日志库写文件超过限定大小触发写日志翻转，这里会有一个写锁
3. 接着执行嵌套读锁的第二个读锁，这时候形成死锁

至此找到API网关假死的原因，日志死锁满足前面的一切异常现象。

5

读写锁嵌套引发的死锁原理

为什么嵌套读就会触发死锁呢？读写锁实现原理是什么，这里根据官方源码来一起阅读下。读写锁实现代码（仅保留关键逻辑）如下：

图5.1

下面是个简单的死锁demo：

图5.2

结合读写锁代码分析死锁触发原理：

1. 第一次RLock正常运行，对应（图5.1）注释1
2. 第一次Lock时，写锁需要等全部读结束才能继续，此时会等待读解锁，对应（图5.1）注释2
3. 第二次RLock时，已经处于写锁中，需要等待数据写结束才能继续，此时会等待写解锁，对应（图5.1）注释3

4. 这种状态下读锁和写锁互相等待对方发送信号（RUnlock和Unlock会释放信号），产生死锁

   6
   小结

在无现场无关键日志的情况下，我们从多个维度排查，通过不断的抽丝剥茧和逻辑推理，终于找到了问题点。有几点经验同大家分享下。

1. 出现问题后，在初步解决过程中尽量保留现场，这对一些小概率bug的定位很有帮助
2. 核心业务要不断建设监控视图，有效且多角度的监控可以反映问题根源
3. 对于锁的使用，坚持最小粒度原则