引言
本篇文章只是工作当中的一个简单记录,尽管这次遇到的问题从技术上来讲并不算是特别高深的问题,但是在面临着多方压力的情况下,问题的解决还是有着不小的难度。因此这里LZ就简单的描述一下整个问题从出现到解决所采取的一系列措施,如果有对此经验丰富的猿友,不妨指点一二。倘若是新手猿友,尚未遇到过此类问题,也算是一个小小的引导吧。
东窗事发
9月27号的一天中午,LZ正在悠闲的听着音乐,exception happy的写着增删改查的代码。忽然之间,狂风大作,通讯工具疯狂弹窗,打破了LZ的闲情逸致。消息当中显示,某业务部门在顷刻之间,整个华北地区的营业部的业务无法进行。在问题出现后的半个小时之内,问题已然延伸到整个部门全国的营业部业务都无法进行。这简直是十分可怕的问题,LZ可担待不起。
当时问题的根源就发生在LZ所负责的系统当中,而很巧的是,我们的项目经理刚好请假了,于是这一重任就落在了LZ的肩上。不过LZ所负责的系统类似于一个窗口,其实在这之后,还有很多项目组在幕后默默的提供着服务,当然,也可能在默默的制造着错误。当时LZ在受到反馈之后,就立马找到运维组同事查看后台日志,结果发现出现了大量的“unable to create new native thread”。
好在LZ对JVM的运行机制以及参数配置还比较熟悉,一看到这个错误,LZ就断定,问题基本上只有两个可能。第一个是,Xss参数太大,导致每个线程的栈太大,从而减少了整体可创建的线程数量。第二个可能是,有大批量的线程一直在进行,但却一直不终止,最终导致线程数量过大。
对于这两个可能,LZ很干脆的就排除掉了第一个,因为我们的系统运行了三年之多,怎么可能将JVM的参数配置错误。所以问题的根源,一定是有一些线程,一直在运行,类似于while(true)的情况。可是很显然,系统当中不可能出现这么多while(true)的线程,那么这些线程究竟为何一直在运行呢?
正在LZ一筹莫展的时候,DBA组的同事给了一个十分有用的线索,DBA组的同事发现,我们系统的数据库当中,出现了大量的行级锁,而且这些锁的数量还在不断增加,导致数据库连接数巨大,压力剧增几近崩溃。由于数据库的服务器上不只运行着一个数据库实例,所以DBA组的同事强烈要求LZ停止系统运行。
这一下信息量有点大,LZ一时也很难快速定位问题的所在,因此只能妥协,暂停了整个系统的运行。在问题出现的前一天晚上,LZ的系统刚刚上线了一大批功能。此时在业务部门的极力催促之下,LZ在短时间内也无法找到问题根源,尽管不甘,但迫于各方面的压力,LZ最终只能采取了回退策略。而且在案发现场,公司的CTO已经到场,因为LZ系统给数据库造成的压力已经影响到了很多系统。
在回退之后,系统终于恢复了正常,从出问题到恢复,共历时一个半小时。不过这也等于失去了排错的机会,只能留着一些比较模糊的信息,私底下自己排查。这些模糊的信息主要包括以下几点。
1、代码回退之后,问题解决,因此可能是代码的问题。
2、数据库产生行级锁,因此与事务有关。
3、线程数量剧增,说明有线程被长时间挂起。
之后LZ私底下也进行了排查,经查之后,代码没有发现任何问题,但第一条的情况却表明,很可能是代码所造成的问题。出现问题的一段代码,只是一个普通的service层的方法,这类方法在系统中大批量存在,LZ实在看不出来哪里有问题。之后在LZ的系统再次上线时,也并未再出现上一次所出现的问题,因此这个问题有点不了了之的意思了。【后话:其实现在这样一分析,从上面三点已经可以找出一些蛛丝马迹了。只是LZ在当时当局者迷,加上俗务缠身,所以才忽略了这个重要的线索】
缠人梦魇
10月31日,今天本来是特别悠闲的一天,尽管LZ手中有着不少开发任务,但时间还算是比较宽裕,因此也算是不慌不忙。然而事情往往会发生在你预料之外,就在LZ刚吃完午饭,享受着人生最美好的时刻的时候(饭后一支烟,你懂的),却被一个小小的噩耗猛然间打断。而噩耗的根源,正是上一次不了了之的那个问题,如今已经时隔一个多月,这充分说明了,“出来混,迟早是要还的”。
当LZ从冒烟处回到工位上时,已然收到无数同事的批判,大体上的意思都是说,LZ的系统中一个依赖于MQ的接口再次出现了问题(与上次出现的问题的地方是一样的),导致业务流程无法进行,业务部门已经炸锅。LZ的通讯软件一根烟的功夫就弹出来N(N>=10)个窗口,邮箱也几近爆满。批判的同事更是来自四面八方,有运维组的,有业务部门的,有研发部门的,有DBA组的,全部都在问同样一个问题,“你们系统怎么回事?现在所有XX部门(某业务部门,由于业务办理周期很短,所以有什么问题都比较火急火燎)都无法正常开展业务了!”。
冷静对待
经过了上次的阵仗,LZ这一次更加蛋定了,轻咳一声,开始挨个仔细的询问各个组(不包括业务部门)的同事一个问题,“有什么异常情况吗?”。对于业务部门,LZ只能采取安抚策略,于是只好扔过去一句“放心,问题应该不大,请稍等一下,我看看是怎么回事!”。接下来LZ收到的,便是技术部各个组同事的一系列反馈,以及来自业务部门的错误截图和描述。
业务人员的反馈:在点某个按钮的时候(此按钮背后是由MQ包装的接口,业务人员自然是不知道的,他们只知道是这个按钮造成的问题),网页似乎一直在提交(就是无限读进度条),也不提示错误,但是也不提示成功,导致业务流程无法进行,后果严重。
运维组的反馈:后台会有异常信息出现,显示为“无返回结果”。(收到此反馈后,尝试了一下,LZ发现并不是对请求没有响应,而是时间很长,最终会产生无返回结果的异常)
开发人员的反馈:这里的开发人员是我们出问题的这个接口的服务端开发人员,他们表示系统无异常信息。
DBA组的反馈:数据库有行级锁,而且数量一直在堆积,导致数据库随时面临被压垮的危险。(这个表现与上次一模一样)
这次之所以可以蛋定的收集信息,是因为项目经理在压阵,否则就LZ一个人,身份低微,扛不住业务部门以及技术部各个组的压力,只能像之前那次一样,放弃治疗,先让系统恢复再说。而这一次有项目经理抗着就不一样了,LZ可以随时再现问题,这样就可以更好的定位问题了。
随机应变
由于数据库的行级锁问题,导致数据库压力太大,随时面临崩溃的可能,而且数据库的服务器上并不只有一个数据库,这还可能导致其它业务系统的崩溃。因此数据库的问题是当下之急,为此DBA组特意派专员及时帮我们杀掉产生的行级锁,释放数据库的session连接,避免了数据库服务器压力骤增而宕机的问题(上次导致好几个系统的数据库全部崩溃)。
抗着业务部门以及技术部各个组同事的压力,LZ与另外一个项目组A组(也就是出问题的接口的服务端,以下都简称A组)的核心开发以及项目经理,开始排查问题出现的可能性。从数据库的表现上来看,问题基本已经断定在接口这个service层的方法当中,而出现问题的应该是方法当中的事务没有及时的提交或回滚,接下来便是一系列排查问题的过程。
日志查询
日志的作用不需要多说,LZ先从服务器上down下来了发生问题的时间段的日志,开始一一检查当中出现的异常。结果却令人十分不满意,因为日志当中并没有什么可用的信息,唯一的一类异常,还是我们自己抛出来的(如下),而且业务人员的反馈是页面长时间没有响应,并不是系统报错(事实证明,业务人员的话一般是不可信的,不是因为他们说谎,而是因为他们的世界与我们是不一样的)。
if(result == null){ throw new RuntimeException(); }
上面这个异常是因为MQ监听消息通道时,接收的结果为空所抛出的,当时写这一段代码的开发人员的目的,应该是希望通过unchecked异常使得事务管理器将事务回滚。但是可惜的是,事务很显然没有正常回滚,也没有正常提交。
代码审查
日志查询并没有发现什么有用的信息,因为程序的显示是正常的,虽然抛出了运行时异常,但这属于事务失败而回滚的正常情况。接下来,我们就只能排查出问题的service层的方法,不过从spring事务管理器的使用惯例上来看,这一段代码并没有任何问题,只是简单的update、insert以及消息发送。
在看代码的时候我们不能忘了一点,那就是这个问题是忽然出现的,如果代码的逻辑或者事务管理是有问题的,那么在测试的时候,或者上一次上线的时候,就应该出现问题。事实上,这一段代码已经很久没有更改,并成功运行了很久(代码的极度缩减版如下所示)。
public class XXXService{ private XXXDao XXXdao; public void methodWithAProblem(){ XXXDao.update();
sendMessage();
}
}
在此次出问题的方法当中,代码的量其实并不大,因此代码审查的时间并没有使用太多。不过可惜的是,代码的审查与日志的查询一样,都没有取得实质性的效果,因此LZ就不得不拿出了必杀技。
疯狂的日志
既然代码看上去没有明显的事务管理问题,而且事实上这段代码也成功运行了很久,因此在代码审查上花费再长时间,也很难定位问题。LZ当机立断,只能采取最卑劣的做法,将这个方法当中,任何一个有关数据库操作的后面都加入日志,并打印详细的参数信息,可以说是一句代码一句日志。
之后LZ便联系运维组的同事,将修改后并编译好的class文件放到服务器上去,并采取了重启的措施。重启其实是挺有压力的,因为很多业务人员在用,毕竟此次出问题的,只是系统中某一个规模相对中等部门的业务,其它大部分的业务还是可以正常进行的。
不过既然冒险重启了,收获就必定是可观的。在系统重启之后,LZ便再次详细查看了本次打印的日志,终于找到了一些蛛丝马迹,问题很可能出现在消息中间件上面了。但是此时还依旧不能够定性问题的根源,因为日志只是将问题缩小到了很小的范围,但具体系统与消息中间件的传输过程以及消息中间件与接口服务端的传输过程都还是不太明确的。
况且,令人纠结的是,就算与消息中间件的通信出现了问题,那也应该可以获得一个unchecked异常,从而导致事务回滚,而不是产生行级锁。而且行级锁的出现,一定是有很多人在修改一条数据,这从业务上来讲是不可能出现的,因为这些数据都是业务人员的业绩,有严格的权限控制,彼此之间都是互斥的。
水落石出
最终LZ从时间上发现了问题,从等待A组系统返回消息开始,到LZ的系统得到“无返回结果”(无返回结果的原因是消息的响应为null,而LZ也专门看了API的说明,上面的return项很清晰的写着null if time out)的异常为止,时间刚好是30秒,而LZ发现我们的MQ设置的超时时间恰好是30秒。这绝对不是一种巧合,因此LZ此时已经基本断定,是服务端(也就是A组系统)没有及时响应产生的问题。
在LZ跟项目经理说了原因之后,项目经理还问了LZ一句,“既然是超时引起的,为何会有行级锁?难道业务人员会操作一条数据?”。LZ脑子一转,忽然想到一种可能,就是业务人员很可能在等待时寂寞难耐,从而F5刷新之后再次点击,这样一来,由于上一个请求还在等待,并且将事务挂起,接下来的请求就需要等待行级锁,如果多次进行这种操作,那么最终挂起来的线程将会越多越多。如果有很多业务人员如此操作,产生的行级锁也将会越来越多。这是LZ能想到的唯一可以完美解释一切的原因。
这样一分析,上次的“unable to create new native thread”异常也就可以解释了。因为很多请求由于行级锁被挂起,这些线程都在等待数据库的行级锁,因此堆积了大量的线程,导致线程数巨大,最终无法再创建。
后续花絮
问题既然已经找到,那么接下来就是LZ找到A组项目经理以及开发人员,然后让他们检查一下监听消息中间件的线程是不是被什么意外给打断了,导致服务端不会再去处理任何消息。最终在后续的排查中,发现消息队列当中,确实堆积了大量的消息没有处理,而服务端的代码当中,是使用线程池处理的消息,目前还没有定论。不过LZ基本断定,这些监听的线程肯定在某种情况下会被终止。
之后LZ就只需要等待A组人员的排查结果了,事实证明,LZ的系统其实是没有问题的。不过有一点是应该改进的,那就是行级锁的问题。因此后来LZ将消息的发送和数据的更新调换了次序,这样可以彻底避免行级锁的产生,哪怕是再次出现这个问题,至少不会因为行级锁造成的数据库压力,而压垮整个数据库服务器。
未完待续
尽管此次基本上已经掌握了问题出现的原因,但其实最根源的地方还是没找到,那就是A组系统当中,究竟何时会中断监听线程。只要这个问题找到了,那么以后就可以防患于未然了。至今为止,A组成员还在寻找问题根源,不过最终的结果可能是,像LZ第一次碰到的时候一样,不了了之。但是还是那句话,“出来混,迟早是要还的”。