前段时间同学反映我们活动项目某个服务可用性出现抖动，偷走偶尔低于0.999 。服务虽然看起来3个9的可用可用性相当高 ，但是偷走对于一个 10w+ qps 的服务来讲 ，影响面就会被放大到不可接受的服务状态。最大的可用影响就是调用预约接口在流量高峰期有不少超时 。预约接口是偷走一个qps相对高的接口 ，超时就显得更加严重 ，服务而且这个问题有一段时间 ，源码库可用所以需要尽快排查清楚原因 ，偷走进行解决 。服务服务可用性监控如下 ：
这个服务承载了很多活动逻辑，可用用了很多技术栈如redis,偷走mc,mysql,taishan,es,mongodb,databus等 ，是服务一个特大单体。所以业务与组件的可用复杂给排查问题带来不少挑战 。
了解基本情况后 ，知道可用性降低是由于超时导致 ，非其他错误。进行简要分析 ，能够想出一些可能的原因 ，例如某些业务写法导致性能问题 ，服务器租用异常流量，系统调用 ，网络问题 ，cpu throttle，中间件问题（如redis,mysql） ，go调度 ，gc问题等 。至于是这8名嫌疑犯还是另有其人 ，需要结合实际现象进行排除与论证，所以需要针对性的收集一些线索 。
从上图可以看出 ，这段时间流量比较规律性 ，并没有出现异常波动 ，免费模板似乎这个问题与流量没什么直接关系（背景中提到上游反馈高峰时段超时,可能只是高峰期放大现象） ，所以排除是异常流量导致的 。
可以看出很多接口的999分位都有同样的问题。如果只是某个业务写法有问题 ，仅仅影响该业务的接口。或者可能是业务写法有问题，影响了runtime ，那就具体再看runtime的香港云服务器表现 ，所以当时并没有深入看业务代码。
其实cpu throttle并不高，也问过运维，没啥异常 ，不太像是导致超时的原因。中间有个小插曲 ：当时有同学从cpu throttle导致超时这个猜想出发 ，发现预约业务内存cache占用量比较大（占用大的话可能影响内存的分配与释放） ，尝试减少预约业务内存cache占用量 。观察一段时间 ，cpu throttle稍微有点降低 ，但可用性问题依然没有好转 。云计算
后续通过查看trace ，发现那段时间mysql与redis均有超时 ，细看给mysql的查询时间只有0.01ms ，mysql说这锅我不背的 。
那redis层呢 ，给了21.45ms ，似乎给比较充足的查询时间，且redis有毛刺（不过毛刺时间点与可用性抖动点对不上） ，但是redis内心一万个不服啊 。那行我们找对应时间段 ，再多看几个超时请求的trace ，建站模板发现这些请求给redis的查询时间都比较短，如下图 ：
好吧 ，redis也可以鼓起勇气说 ，这锅我也不背 。
其他组件也同样看过，都没啥异常。那么问题来了 ，组件们都不背 ，那到底谁来背 ？那网络 ，系统调用 ，go调度与gc ，你们自己看着办吧 。
网络说你再仔细想想，不对啊 ，一个请求至少给了250ms的time_quota ，你们最后只留给我和组件们那么点时间 ，redis 0.04ms ，mysql 0.01ms 。请问扣除这点时间 ，剩余是谁“消费”了 ，应该心知肚明了吧 。说到这 ，go调度，系统调用与gc主动跳出来了 。
现在的矛头指向go runtime与系统调用 。根据以往的经验有以下几种主要手段辅助定位：
采集pprof，用cpu profiler查看cpu占用 ，memory profiler查看gc问题开启GODEBUG=gctrace=1 ，可查看程序运行过程中的GC信息 。如果觉得是gc问题 ，可查看服务可用性抖动时间段gctrace是否异常 ，进一步确认问题添加fgprof，辅助排查off-cpu可能性 ，off-cpu例如I/O 、锁 、计时器 、页交换等，具体详看鸟窝大佬文章 ：分析Go程序的Off-CPU性能（https://colobu.com/2020/11/12/analyze-On-CPU-in-go/）采集go trace ，查看go调度问题，例如gc 、抢占调度等 ，真实反映当时调度情况linux strace查看go运行时调用了哪些系统调用导致超时根据以往一些经验 ，gc有时候会影响系统的延时 ，所以先用gctrace看看这块有没有问题 。
从gctrace上可以看出 ，并发标记和扫描的时间占用了860ms（图中红色框0.8+860+0.0668 ms中的860 ，一般gc问题通常看这块区域） ，并发标记和扫描比较占用cpu时间 ，这样可能导致这段时间大多数cpu时间用于扫描，业务协程只能延迟被调度。后续与可用性未抖动时间段的gctrace对比 ，发现并发标记与扫描时间并没有明显增多 ，但从860ms的时长上看 ，感觉也不是很合理 ，但没有证据证明它就能够导致超时抖动 ，这块异常先记着 。
strace分析并未发现异常 ，都是一些正常的系统调用 ，看不出有明显系统导致goroutine超时 ，所以"系统调用"这个嫌疑也暂时排除 。
未见异常 ，结论同strace一样 ，未出现off-cpu的协程堵塞 。
尝试多次(超过20次)抓取go trace文件进行分析 。从trace文件上，可以明显看到发生MARK ASSIST了，顿时心中有谱。多抓trace看看 ，还是有明显的MARK ASSIST了现象，gc问题应该比较明显了 。
go heap 分析如果是gc问题 ，那就和heap息息相关了 。抓一段低峰期的heap ，进行分析 。
inuse_space：
可见grpc连接占用了很大的一块内存 ，但这其实一般不太直接影响gc标记和扫描 ，主要影响内存的释放 。gc标记和扫描还得看inuse_objects 。
inuse_objects ：
可以看到gcache中LFU生产的object数量高达100w+ ，而总共的object才300w 。这块明显有问题，那很可能就是它导致的问题 。
我们找到最大的嫌疑-gcache（该包引入项目已一年多）。看了一下业务中使用gcache的情况及LFU的使用处
从用法上 ，未发现有什么问题 。便把问题转向gcache包本身 。百度，google一顿搜索 ，源码浅看了一下 ，也没发现异常 。github.com issue一搜，发现有人提过类似问题https://github.com/bluele/gcache/issues/71 。gcache LFU策略的Get方法存在内存泄露（内存大概泄露100M ，占总内存占用量2.5% ，主要是产生大量指针对象）。具体bug是如何产生的 ，由于篇幅原因，这里不进行赘述，可参考issue（https://github.com/bluele/gcache/issues/71）。后续将gcahce版本从v0.0.1升级至v0.0.2 ，该问题得以解决 。
gcache竟然是你啊 ，偷走了我0.001的服务可用性。
至此问题排查与解决都告一段落了 ，但有些问题还需总结与复盘。
从上面看 ，你可能想这问题好像也很容易就排查到了 ，实际排查过程中并不顺利 。在进行trace及heap分析时也是抓取了很多次 ，才抓到有效信息 。后面发现某些gcache的过期时间只有5分钟 ，过了这5分钟 ，现场就没了（如果能有自动抓取能力 ，那该多方便） ，这让怀疑是gc问题的我们一段时间在自我肯定与否定中。中间产生更多猜想 ，例如怀疑定时器使用过多(业务代码里面比较多后台刷新配置的定时器) ，导致业务逻辑调度延迟；grpc客户端连接过多(2w+) ，占用较大内存 ，产生较多对象 ，影响gc；也有猜测是机器问题；常驻内存cache过多，内部指针较多，影响gc扫描；甚至想用go ballast 丝滑的控制内存等 。
关于系统稳定性这块的小启示 ：
第三方库的引入还需慎重 。本次问题是第三方包bug导致的，所以引入包时需要考虑合理性 ，避免引入不稳定因素 。第三方包的安全漏洞问题大家一般比较重视 ，bug却常常被忽视 。可制定第三方包的引入标准 、编写工具监测第三方包issue的提出与解决 ，通知开发人员评估风险及更新包版本 ，从而做到第三方包的合理引入 ，快速发现issue以及修复。关于系统稳定性这块 ，基本上都是尽可能的添加监控(包括系统 ，组件，go runtime维度) ，通过报警及时发现问题或隐患 。至于go程序运行时内部的现场？似乎只能出问题时在容器内部或者借助公司自研平台手动抓取pprof ，但多少存在一定的滞后性 ，有时候甚至现场都没了 。当然也有人定时抓取pprof ，但多少有点影响性能，姿势也不够优雅。holmes(MOSN 社区性能分析利器)就显得很有必要 。通过相应的策略 ，例如协程暴涨 ，cpu异常升高 ，内存OOM等情况 ，自动抓取，达到近似"无人值守" 。既能够较好的保留事故现场 ，也能提前暴漏一些隐患 。以上2点启示均已在项目内落地 。
参考文献
<<分析Go程序的Off-CPU性能>> https://colobu.com/2020/11/12/analyze-On-CPU-in-go/<<Holmes 原理浅析>> https://mosn.io/blog/posts/mosn-holmes-design/holmes github ：https://github.com/mosn/holmesgcache github: https://github.com/bluele/gcache<<深度解密Go语言之 pprof>> https://www.cnblogs.com/qcrao-2018/p/11832732.html本期作者
叶性敏
哔哩哔哩资深开发工程师