线上故障处理——大量异常堆栈日志输出影响服务可用性

系统背景介绍

用户系统负责用户生命周期管理，包括注册、登陆、用户信息获取等，其作为基础服务只提供内网服务，简称为service；application组件包装service的服务对app渠道提供服务；service前面使用F5作为负载均衡器。

架构简图如下：

线上故障事件描述

上午9点50分，监控系统发出application组件可访问性故障告警，一半的实例均有告警；无业务告警；无生产事件上报。运维将系统告警转发相关开发负责人。

线上故障确定

告警属于服务器告警，一半服务器实例均有告警；同时，发现告警服务器的TCP CLOSE_WAIT连接数暴增到10k，且application服务时延增大；可以断定是线上故障，且可能已经影响到了业务服务。

线上故障定位

上半场

9:52 开发人员通过服务器监控，发现application告警服务器TCP CLOSE_WAIT连接数最近几天暴增；开发人员提出疑问：最近是否有新功能上线？

9:53 运维人员贴出最近一次application版本内容，未有大的改动；

9:57 开发人员通过服务监控，发现application组件的服务时延均增大；服务访问量中，getUserHeadPhoto服务的访问量相比之前增加了100倍；同时发现getUserHeadPhoto服务时延最大，平均达到了5000ms，正常情况下20ms以下；

初步怀疑：可能和getUserHeadPhoto服务有关。getUserHeadPhoto服务的提供方是service。

9:59 开发人员发现application告警服务器上大部分CLOSE_WAIT连接都是到service F5上的；

怀疑：很有可能使由于service服务出现异常，导致application长时间等待service响应直到客户端timeout，所以出现大量CLOSE_WAIT。但不一定是getUserHeadPhoto的原因，因为application包装了service的很多服务。

10:00 开发人员通过service服务器监控，发现相比上周同时段，cpu使用率增加了1倍（10%-->20%）， TCP连接数增加了10倍以上，达到了7K，且伴有1.2k左右的CLOSE_WAIT，且IO读写均增加了10倍以上，内存使用率增加了一倍多；service的服务还能正常响应，但是时延均增高。

10:01 开发人员发现getUserHeadPhoto服务在service系统的时延为60ms，但是在application系统的时延为6000ms，差了10倍；

10:02 其他调用方陆续报警说service的时延增大；

10:03 开发人员检查service tomcat error日志，发现有异常输出，但是都是业务异常输出，大部分是‘头像不存在’的输出，故忽略。

确定：通过service自身服务监控及上游系统的监控信息可以确定是service服务出现了问题，服务时延增大，导致上游的application受牵连；service服务时延增大，导致frontent调用超时，出现大量CLOSE_WAIT；很大可能和getUserHeadPhoto服务有关，现在还不确定。

10:04 开发人员确定service上周版本没有大的变更，且并未更改getUserHeadPhoto服务。排除和service新版本发布的关系。

10:05 IOS开发同事确认前两天上线的app X.0版本中，更改了getUserHeadPhoto服务调用的逻辑，导致getUserHeadPhoto服务的访问量增加了100倍以上。原逻辑：用户设置了头像且更改过头像才会从服务端请求getUserHeadPhoto获取头像信息；更改后不再有上述判定，用户每次进个人中心，都会到服务端来拉取，带来了100倍+的访问量增加；刚好IOS app x.0版本是在上周五下班后发布市场，今天是周一，用户量最多；而早ios一周发布一周的android没有这个bug，上周也没有此类故障告警。

重新梳理下getUserHeadPhoto服务的处理逻辑：如果用户有头像，则从NAS存储中获取头像文件，转换为二进制数组返回；如果不存在，则直接返回‘头像不存在’的错误码。IOS头像拉取bug会导致有头像的用户不断从服务端拉取头像，现在app日活在200万左右，ios大概占据100万，按照5%比例的用户设置了头像，大概5万日活用户会拥有头像，这会导致‘从存储读取文件’增多，从而导致磁盘IO读增大，‘内存中完成文件流到二进制数组的转化’导致service服务器内存使用增大。另一方面，ios剩下的95%没有设置头像的用户也会不断请求getUserHeadPhoto服务，从而导致getUserHeadPhoto服务的访问量暴增100倍。此时getUserHeadPhoto的qps峰值达到了2000qps左右，但是按照之前性能测试得到的的性能曲线，这个压力，service系统是完全可以抗住的，不应当出现故障。且这个压力值下，不应当出现service系统cpu飙高一倍的现象。

所以这时候仍然不能确定故障的具体原因，也不能确定根本原因就一定是getUserHeadPhoto服务访问量的暴涨。还有有两个现象解释不通：磁盘写IO飙高10倍，service系统cpu飙高一倍。 getUserHeadPhoto服务只是io读操作，怎么会造成这么大的IO写呢？

半个小时过去了，仍未定位了故障根本原因，且getUserHeadPhoto服务还不支持服务降级，故暂无紧急措施可以实施；好在10点30分过后，用户访问量（业务规律）下来后，application服务逐渐恢复正常。现在，大家可以有大半天的时间来重新定位问题。

下半场

经过邮件讨论，梳理出如下已有的信息：

故障出在service系统，service服务时延增大，导致上游的application出现调用超时，并出现大量的CLOSE_WAIT；

service故障可能和getUserHeadPhoto访问量暴涨有关；但还不确定具体原因；

仍然无法解释现象：service系统cpu飙高一倍、磁盘写IO飙高10倍

得到的两个怀疑点如下：

运维人员怀疑service前面的F5的7层代理模式有性能问题，因为有一个现象是：同一次请求service耗时在60ms，而application的耗时却为6000ms，他们怀疑是F5转发时延过大；

开发人员怀疑getUserHeadPhoto访问量暴增出发了service系统的某个bug；

鉴于线上故障已经得到缓和，拟在测试环境进行问题重现后，针对两个怀疑点进行尝试。

测试人员使用jmeter压测工具对application发起线上同等压力qps的getUserHeadPhoto调用，重现了线上问题：application时延在1500ms，service时延在20ms，service系统cpu使用率偏高。但io写入偏高，tcp的CLOS_WAIT未大量出现。

验证怀疑点一：将测试环境的F5转发从7层模式更改为4层模式，再次压测，问题仍然存在，application时延没有得到好转。

验证怀疑点二：直接对service系统的getUserHeadPhoto进行同等qps的压力测试，问题复现：service服务器cpu高，io写入高。使用jmx监控，发现cpu50%时间消耗在log4j2的写入操作上；查看service tomcat error日志，发现大量的堆栈信息写入，这些异常会在用户不存在头像文件时抛出，并输出到.out文件。

可能exception堆栈大量输出导致io成为瓶颈，cpu切换频繁，从而影响了服务。于是做如下尝试：更改log4j2配置，将.out屏蔽，不再输出日志，只输出trace日志。重新测试，发现cpu降下来了，io写入也降下来了。

再次从application发起压力测试，服务恢复正常，时延降低到80ms，service时延为20ms。

至此，找到了故障的根本原因：service系统将异常堆栈输出到.out日志，当getUserHeadPhoto访问量暴增100倍且95%的访问因为没有头像报出业务异常时，会大量输出堆栈到.out日志，io成为瓶颈，cpu在线程切换增加，影响到服务响应，使得服务时延增加，在业务访问量不减反增的情况下，service服务器的tcp连接数也增加。

线上故障排除

找到根本原因后，拟定了如下临时和长期解决方案：

临时方案——紧急更改线上service组件log4j2配置，将.out日志输出屏蔽，带来的异常堆栈丢失可以接受，因为trace日志会记录异常码，通常可以通过业务异常码推测问

长期方案——修改service组件日志记录逻辑，对于业务类异常（像这次的‘头像不存在’）不再输出堆栈信息到.out文件，因为业务异常不是程序bug，堆栈信息并无益处。本周版本上线。

更改头像获取方式，不再使用二进制数组方式的传递形式，改为接入新建的统一图片服务，以外网url方式提供头像。

　　长期方案也早已发布生产。

总结

这次线上故障并不是深奥的技术疑难杂症导致的，而是在某种小概率事件发生后，激发了线上应用的两个不当设计——将业务一场堆栈输出到.out文件+使用二进制数组传递文件内容，且这些不当设计在正常情况下看来是没有什么大的害处的，比较隐蔽，所以排障过程也不是那么顺利。

做的好的地方

运维、开发人员及时响应告警，并行查找线索，汇总信息；确保线上服务安全的前提下，冷静彻底查清故障原因，并找到临时方案紧急排除故障；同时，对不合理的设计进行改正。

做的不好的地方

故障确定在service后，未能及时获取线上tomcat的dump文件并作分析；

在查看service组件error日志，发现大量堆栈输出时，认为是业务异常，未引起警惕。

特别的教训

墨菲定律，永远不要小瞧小概率事件，莫名其妙的bug不知道在什么时候就出来了。

技术债迟早是要还的，晚还不如早还。当初上线service时，由于没有统一图片服务的基础设施，为了赶项目工期，只能临时采用二进制数组传递文件内容的方式实现头像文件拉取，按照前后端约定的设计逻辑，没有太大问题，毕竟更新头像的人很少，但是经过两个app版本迭代，一次大的重构就带入了bug，触发了潜在的系统设计漏洞。

故障处理路线图