又两个case(偶尔超时、恶性循环)

Case I
有个应用出现集群里有部分服务器访问DB超时比其他机器多很多的现象,而且诡异的是时间基本都是200ms多一点点。

排查时首先想到的是确认下是不是这些机器在处理网卡中断的时候不够给力造成的,但看到的现象是这些服务器的cpu消耗都非常的低,另外也确认了网卡是支持多队列的并且已开启了的。

接着排查是不是网络上的问题,对比了正常的机器和这些超时多的机器在网络上的表现状况,发现超时多的这些机器在tcp重传上会稍高一些,大概在0.2左右,而正常的机器则基本都在0,于是猜想是网络上出问题了。

于是将现象交给网络同事进行排查,在折腾了几次后确认是其中的一个交换机在处理某些包的时候会出现这样的现象,更换交换机后一切回归正常。

这个case值得说说的一点是为什么看到超时的时候访问时间都是200ms多一点点,tcp在重传时会采用避让策略,就是每次重传重试的时间会逐步拉长,重传的具体时间间隔取决于RTO,但因为是内网环境,所以RTO都会很低,在linux上,有一个最小的重传间隔时间,这个时间刚好是200ms,so…具体大家可以参阅此文(有可能要备梯子)。

Case II
有个应用出现了重启后load一直高的现象,页面上访问返回502或504。

排查的时候首先看到的现象是cpu消耗非常严重,按照一贯的惯例,先扫一眼gc log,就看到cms gc非常频繁,大概1分钟1次,young gc大概2秒1次,每次大概需要消耗掉90ms+,按照这种现象,基本上cpu就一直耗在gc上了,因此应用的响应时间非常糟糕。

从观察到的现象来看,是内存占用很严重,于是dump内存,在等待分析的过程中,决定先增大了一点heap size,但仍然无法解决,因为内存消耗的实在是太快了。

dump内存分析的结果是一切正常,这就有点悲催了..

临时扩容了几台机器,然后就突然恢复了…

继续排查,由于内存dump分析的结果一切正常,猜想这些内存的消耗完全就是正常的请求处理的消耗,而仅仅是因为响应时间慢,导致了内存中存活的对象比较多,从而导致gc频繁,于是模拟做了一次压测,但按照差不多的qps去压,发现一切正常。

回想出问题的时候刚好是发布重启,因此猜测可能是刚启动的时间性能不佳,而qps又不低造成的,于是按照这个思路在压测过程中做了一次重启,果然重现了之前的现象…

这是个极度悲催的恶性循环的问题,刚启动的时候Java性能比较糟糕,请求处理慢,内存中存活对象比较多,而这个时候如果请求较多的话,直接就会导致gc频繁,gc频繁后又会导致搞不好大部分时候在做GC,于是响应时间更加糟糕,存活的对象更多,就进入了一个恶性循环,因此还是要控制刚启动的时候进来的请求不要太多(这就意味着对发布有要求了)。

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

两起“蝴蝶效应”Cases

最近碰到了两个case,一个是一个系统变慢了一点,导致另外一个系统暴露出ThreadLocal使用不当造成的小的故障;另外一个是一个小的边缘系统出现问题导致的严重故障。

Case One
有一个系统突然出现频繁的cms gc,dump内存后看到主要的消耗是在ThreadLocal里的一个对象,经过排查发现主要原因是在处理过程中有一个地方往ThreadLocal里塞了一个用来做cache的对象,但悲催的是每次会从ThreadLocal里先获取这个对象实例,然后塞一些对象到这个实例里的HashMap,而线程又是复用的,从而导致了HashMap里的对象不断的堆积,于是导致了故障。

这个Case最诡异的是突然出现,之前一直都运行的好好的,结果发现之所以出现是因为刚好这个系统依赖的后端一个系统变慢,而变慢后导致存活的线程变多,ThreadLocal里堆积的这些对象累积占用的内存也就变多了,刚好变多了后把本来剩余的那点内存给耗光了,所以频繁cms gc。

还有一种在线程复用下错误用ThreadLocal的方式是每次new ThreadLocal,在线程复用的情况下这会导致堆积很多的ThreadLocal对象,同样很容易导致内存用满。

所以通常我们都建议要慎重使用ThreadLocal,能不用最好是别用。

Case Two
一个超级重要的系统,突然出现vip挂掉,导致外部用户全部访问不到,在排查时突然又恢复了。

继续排查时,首先发现vip做健康检查时失败,对应的vip下的机器的访问日志里看到返回的http状态码是499,按照之前的经验,返回499都是因为后端处理慢导致的,而健康检查的文件是个静态文件,没任何逻辑,所以要造成这里处理慢只有一个原因,就是http的处理线程全部被耗光了。

于是观察那个时候这个系统依赖的几个主要点的响应时间,发现没什么变化。

http处理线程全部耗光,要知道原因最好的办法是在当时有问题的时候dump线程信息,但悲催的是当时没做dump,于是一摸黑,期望着通过系统日志来排查,结果是排查了一圈也没发现任何问题。

还好在这个时候某同学告知在故障出来之前有系统不太正常的现象,于是做了线程dump,捞到这个线程dump一看,http的处理线程大部分都在发起一个http请求,等待结果返回。

和业务方同学确认了下是什么请求,确认这只是一个页面发起的异步请求,而且很不重要,但从线程dump来看有可能是这个地方的问题,于是就找人去确认当时这个url对应的系统发生了什么,结果是在那个时间点刚好这个url对应的系统做了个动作,导致没有响应,而出故障的这个系统在发起这个http的请求时没设置超时,于是悲催了,所有处理线程被耗光,导致了vip健康检查失败。

这个故障聚集了以前出现过的严重故障的几个特征:
1. 一个不重要的系统出问题了导致了重要系统的故障,这主要原因就是隔离没做好,例如这种不重要的url的处理应该放在一个不重要的系统上去做,这样最多也就是那个不重要的系统挂掉;
2. 远程访问的超时,在高并发的系统里,任何的远程操作都必须设置超时(不过在上面的案例中仅仅设置超时是没用的,还是要靠隔离),而且超时不能设置太长(我做的服务框架第一个版本上线时就由于默认超时时间60s导致了严重故障)。

上面的这两起case其实都是一个系统的问题导致另外一个系统也出问题,这是互联网这类高可用性系统中最害怕的蝴蝶效应。

=============================
题图来源于:http://i2.sinaimg.cn/dy/w/2008-10-10/U2342P1T1D16429263F21DT20081010075908.jpg
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。