背景

前段时间同学反映我们活动项目某个服务可用性出现抖动，偶尔低于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主动跳出来了。

排查思路

1. 采集pprof，用cpu profiler查看cpu占用，memory profiler查看gc问题

2. 开启GODEBUG=gctrace=1 ，可查看程序运行过程中的GC信息。如果觉得是gc问题，可查看服务可用性抖动时间段gctrace是否异常，进一步确认问题

3. 添加fgprof，辅助排查off-cpu可能性，off-cpu例如I/O、锁、计时器、页交换等，具体详看鸟窝大佬文章：分析Go程序的Off-CPU性能（https://colobu.com/2020/11/12/analyze-On-CPU-in-go/）

4. 采集go trace，查看go调度问题，例如gc、抢占调度等，真实反映当时调度情况

5. linux strace查看go运行时调用了哪些系统调用导致超时

分析

gctrace分析

根据以往一些经验，gc有时候会影响系统的延时，所以先用gctrace看看这块有没有问题。

从gctrace上可以看出，并发标记和扫描的时间占用了860ms（图中红色框0.8+860+0.0668 ms中的860，一般gc问题通常看这块区域），并发标记和扫描比较占用cpu时间，这样可能导致这段时间大多数cpu时间用于扫描，业务协程只能延迟被调度。后续与可用性未抖动时间段的gctrace对比，发现并发标记与扫描时间并没有明显增多，但从860ms的时长上看，感觉也不是很合理，但没有证据证明它就能够导致超时抖动，这块异常先记着。

strace分析

并未发现异常，都是一些正常的系统调用，看不出有明显系统导致goroutine超时，所以”系统调用”这个嫌疑也暂时排除。

fgprof分析

未见异常，结论同 strace 一样，未出现 off-cpu 的协程堵塞。

go trace分析

尝试多次(超过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/holmes

• gcache github: https://github.com/bluele/gcache

• <<深度解密Go语言之 pprof>> https://www.cnblogs.com/qcrao-2018/p/11832732.html

来源：本文转自公众号哔哩哔哩技术，点击查看原文。

还不过瘾？10月下旬，GOPS 全球运维大会 2023 · 上海站，早鸟票火热预售中~

联系我们

商务赞助及合作：

周静：130 7118 2180（微信同号）

任怡：132 6958 7068（微信同号） 

门票咨询：

李伟：130 2108 2989（微信同号） 

张娜：132 6188 5689（微信同号）

渠道合作：

刘欣：158 0111 5386（微信同号）

王子翰：185 4893 3915（微信同号）

议题申报：

刘杰：156 5212 7323（微信同号）

高婉莹：185 1087 3635（微信同号）

近期好文：

Kubernetes 网络排错“狂飙”级指南，你学会了吗

“高效运维”公众号诚邀广大技术人员投稿

投稿邮箱：jiachen@greatops.net，或添加联系人微信：greatops1118。

点个“在看”，一年不宕机