作者: andorccao(曹灿)、alonlong(龙武)并发编程经常需要和锁打交道，读写锁允许并发读和独占写，能提高并发性。但使用不当容易引发死锁问题。微保业务使用的微服务架构。随着业务发展，原有的nginx/haproxy等代理服务无法满足复杂多变的需求，API网关应运而生。API网关主要实现负载均衡、路由、鉴权、控制访问、服务代理、监控等功能。API网关作为C端的统一入口，对性能和稳定性有很高的要求，一次微小的波动就会成倍放大影响到业务服务。本文以微保API网关为例，逐步剖析读写锁嵌套误用引发的一次死锁bug。微保的核心业务，都有非常完善的监控和告警系统，便于我们快速发现和初步定位问题。本次问题的发现是告警系统发出一连串的超时警告，都指向C端访问后台的config服务超时（超过5秒）。收到业务告警后，第一反应API网关应该没问题，毕竟网关自身没有收到告警，且API网关作为C端的流量入口，若有问题那其他业务告警早就炸了。打开API网关整体监控视图，并未发现明显异常（其实是监控数据比较分散没有立刻发现）。按照常理，一般超时大概率是网络问题，我们查看了内网网络状态和域名解析情况，均未发现异常。
看来需要根据日志来分析。面对这种大批量超时现象，任意抽一个API网关实例（共8个实例），未发现明显错误日志。这时候就比较懵了，服务和网关都没有异常。考虑到超时对业务影响非常大，没太多时间深入分析问题。该祭出重启大法了。先重启config服务，未恢复；紧接着重启API网关服务，异常告警终于结束。看来是API网关的问题，接下来我们从多个维度一起分析。查看所有API网关实例日志，发现其中一个实例异常期间没有日志输出。正常情况下API网关每个请求都会打印日志，那么有几个方向值得怀疑：- 日志库有问题，但日志库作为最常用的组件，不应该此时暴露出来（同时了解到近期没有更新）
由于没有保留现场和任何日志作为参考，定位难度很大，我们从外围熟悉的信息着手分析，缩小范围，然后再根据源码来定位（API网关使用的开源组件很多，这个方向会比较复杂）。3.1 链路分析
CLB是腾讯云提供的负载均衡服务。一般情况下CLB日志处于关闭状态。我们优先看第一条数据流，下图是haproxy的日志。发现haproxy调用API网关的请求存在60s超时（CLB配置超时时间是60s），说明异常期间是API网关未响应导致的链路超时。这里有个疑问：CLB有健康检查机制，管理的实例异常后会被CLB踢掉，为啥没有触发？3.2 CLB健康检查
CLB每5秒发送一次GET请求，连续3次未收到就会踢掉异常后端服务，API网关未被踢掉表示这段时间能正常处理GET请求。再来看API网关健康检查适配代码：这里能正常运行，说明请求已触达业务层面，不是框架层面的问题。其实这里有个关键点忽略了。正常情况要打印Warn日志的，与没日志的现象不符，所以日志库有问题（事后证明符合）。3.3 监控视图分析
上图是异常实例的基础状态视图，异常期间内存、TCP alloc数明显增加，CPU没啥变化。解释下这些指标的含义：
- TCP alloc一直增加说明服务能正常接收新的请求，但未调用close，无法正常关闭请求
- 异常期间其他实例正常，说明网关转发的后台服务没有异常
- 异常实例所处的机器其他服务正常，说明机器处于正常状态
综合上面的推论猜测是API网关服务自身处于假死状态，无法正常处理请求，且应该是请求入口处就卡死（没有日志）。常见的假死原因有：机器资源异常（IO异常、CPU、内存 100%），死循环，服务死锁。上面的分析可以排除机器资源问题。接下来重点分析服务假死的情况。4.1 模拟死循环现象
一般死循环会导致CPU很高，但我们还是需要验证下golang协程死循环的表现是否一致。上面这份代码。在golang 1.11之前的版本，存在死循环然后触发协程调度后，会导致服务假死。这种状态下TCP alloc，内存都会增加，CPU也会增加，与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
其实异常期间没有日志，我们早应该怀疑日志库的问题（被常识误导了）。接着对日志库进行压测，证明确实会触发死锁。日志库死锁触发的概率是极低的，需要同时满足下面情况：
- 服务一个协程写日志时，刚好执行完嵌套读锁的第一个读锁
- 此时日志库写文件超过限定大小触发写日志翻转，这里会有一个写锁
至此找到API网关假死的原因，日志死锁满足前面的一切异常现象。为什么嵌套读就会触发死锁呢？读写锁实现原理是什么，这里根据官方源码来一起阅读下。读写锁实现代码（仅保留关键逻辑）如下：- 第一次Lock时，写锁需要等全部读结束才能继续，此时会等待读解锁，对应（图5.1）注释2
- 第二次RLock时，已经处于写锁中，需要等待数据写结束才能继续，此时会等待写解锁，对应（图5.1）注释3
这种状态下读锁和写锁互相等待对方发送信号（RUnlock和Unlock会释放信号），产生死锁
在无现场无关键日志的情况下，我们从多个维度排查，通过不断的抽丝剥茧和逻辑推理，终于找到了问题点。有几点经验同大家分享下。- 出现问题后，在初步解决过程中尽量保留现场，这对一些小概率bug的定位很有帮助
- 核心业务要不断建设监控视图，有效且多角度的监控可以反映问题根源