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

系统背景介绍

用户系统负责用户生命周期管理,包括注册、登陆、用户信息获取等,其作为基础服务只提供内网服务,简称为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,触发了潜在的系统设计漏洞。 

故障处理路线图

 

posted @ 2017-05-01 17:08 倒骑的驴 阅读(...) 评论(...) 编辑 收藏