1.发现问题
早上7点40左右收到告警信息,这时还未有大量用户在线使用,查看服务调用链的时候发现很多请求失败,提示拒绝请求:
ThreadProtectedRequestRouter reject request: request_method=com.xxx.xxx.model.service.rpc.busiRpcService.getInfoById request_counter=51 =186 max_thread=200
看拒绝服务的这个服务器没有任何的报错,跟其他异常,数据库也没有慢查询,查看调用链每个请求耗时都很短,可以说是服务应该算很稳,然而线程池却堆满了,为啥呢?? 想去昨天有发版,赶紧看了下发版的工程,确实是发了,而且有优化服务的代码上线了,猜想很可能是这次发版的问题。
2.恢复线上问题
由于马上到上班高峰期,一上班将会有大量用户需要使用系统,为了不影响使用,马上联系运维将代码回滚了(太着急也把自己坑了,忘了dump当时线程日志了),回滚后系统马上恢复了。基本上确定是昨天发版的问题,接下来就是漫长的找原因过程了。。。
3.找系统异常原因
首先从Pinpoint上看调用链,这边假设B服务是线程池满的服务,以下图是A服务,A服务调用B服务的时候,先是看到了有一部分调用超时了,过了一段时间,发现全部拒绝访问(此时B服务的线程池已经满了,而且一直没释放,已经完全不能接收请求)。拒绝的请求可以从B服务中看到拒绝的日志,想着从超时的这些请求分析是不是这些请求的某些操作将线程堵塞了,然而跟踪这些请求也并未发现B服务有任何响应缓慢的情况。这个时候就已经很蒙了,调用方发请求,被调用方看服务看日志都很正常,为啥就线程池满了?
(下面的图第一个是被调用方B服务,2.3是调用方A服务的,4是B服务的当时服务器cpu.内存,活动线程等情况)
从图4可以看出, B服务是在5点多的时候,活动线程就一直不断增加,从没减过,我们服务配的最大线程数是200,最后就一直维持在200没增没减。再下这个节点的日志看,线程数也是一直在增加,但是却看不到异常,到线程数达到200之后一段时间,后面的请求就没再进来了。这个时候这个节点就完全不能接收外部任何请求了,因为线程池满了,实际上这个服务进程是还很正常存活的,还能处理其他比如像Mq之类的任务(使用的是其他线程池)。
服务日志看不到有慢的调用,也看不到任何异常信息,线程池中的线程却全部耗尽了,这时已经没法从日志看出东西了。这个时候就想当时线程是都在干什么,为何看不到任何异常,线程就都不见了,这时就很后悔重启服务前没有将当时的进程dump下来,完全不知道到底发生了什么。只能根据异常信息去跟踪代码,但是从代码上只能看出,为何会拒绝请求了,即使线程数未满的情况下,也出现过拒绝请求。
ThreadProtectedRequestRouter reject request: request_method=com.xxx.xxx.model.service.rpc.busiRpcService.getInfoById request_counter=51 =186 max_thread=200
这个异常就是说明当前有186个线程在运行,还未达到最大线程数200,但是已经拒绝了。原因是request_counter=51 这个数值, 这个是某个方法当前正在处理数量统计,在代码上可以看出当某个方法正在处理达到一定数量也会拒绝请求(我们使用的是motan rpc),而且发现打印拒绝的是都是同样的方法,猜想是不是这个方法的逻辑有问题,跟踪代码却也发现不到任何问题。
感觉已经没有办法找出问题来了,想着这个代码我们开发环境已经用很久了,也没有发现问题,是不是请求量不够大,所以不能触发那个请求呢,所以想着模仿并发量比较高的来请求刚刚怀疑的那个方法,然后请求量已经很大也没重现这个问题。
这个时候想着,这样猜也不是办法了,只有重现了当时的情景猜可以看出问题。开发环境重现不了, 就想着在线上部署一个节点来重现这个问题,所以让运维上了一个节点,因为这个不是立马就能触发的,原来也是发版一个晚上之后第二天才触发,猜想这个也要等到第二天才能看到效果,只能叮嘱运维明天再出现问题一定要先dump再回滚代码了!
就在放弃了查这个问题,等明天重现之后再看,去处理其他事情,在开发环境测试的时候,意外发现那个问题居然重现了,太惊喜了。马上用jstack将当前进程dump下来,分析原因。
最终发现是获取redis连接获取不到,又没有配置等待时间,就一直等下去,所以一个个线程进来都在等待获取redis连接,都耗尽了。为什么会获取不到redis连接呢? 是有哪些连接没有关闭吗? 去找了这次发版的代码,发现了一个地方获取了redis连接之后没有关闭连接,至此终于真正找到原因所在了。
4.总结
系统监控:监控系统很重要,有监控系统才能更早发现问题
pinpoint等调用链能给分析系统运行情况带来很大帮助
经验:若是线程池满了,一定得记得将当时进程的状态dump下来之后再重启服务,才有办法分析具体原因(要熟悉jstack的使用)
类似获取redis等连接一定要记得关闭,释放资源。。
保持敬畏:生产发布,一定要保持敬畏,做好review