本文的技术细节并不具通用性,但是排查的思路过程值得自己mark下,上次遇到这样的刺激线上故障已经是今年3月了~~~这次排查花了3个小时,还算快啦,也算最近的一个小彩蛋。
昨天在公司coding,测试组的同事突然来找我,告知预发环境的系统挂了,请求都是异常,打开业务日志和tomcat的日志排查,满屏的Too many open files,果然 lsof -p pid 预发机器,已经打满到了65535个,很多都是anon_inode pipe FIFO REG,真的不知道这是什么鬼:
内心一紧,赶紧用lsof -p pid 查看了下线上所有生产机器的文件描述符个数,所幸都在正常范围,这才放下心对预发环境的故障进行排查。
首先保存事故现场,用新端口给qa紧急部署了一个新的环境,nginx转发到新的端口。
接下来就是jstack对堆栈进行检查。jstack的结果是有10个左右的线程处于innative的状态,其他线程都是处于blocked的状态。处于innative状态的线程,有一个明显是tomcat的主线程,有6,7个处于epoll的epoll_wait状态,还有一个是我们开启的内部端口监听,也是wait状态,剩下的数百个blocked线程都在tomcat的quene take的wait状态。我想了想,又谷歌了下,会不会是epoll_wait的bug呢,记得jdk1.6有一个epoll_wait的bug一直没解决。于是定位的天平往jdk bug的方向倾斜,应该是这样想会轻松一点吧。
转念一想,如果是epoll_wait的bug,不会导致文件描述符被打满呀。又陷入了焦灼状态。。
接下来开始尝试翻日志,业务日志是看不出什么问题了,但是想起来tomcat报错的时间是下午2点,2点有什么操作么?查看业务日志,2点有刷新缓存的操作,看起来有了一条靠谱的线!
快速搭建了一个测试环境。先lsof一下,大概是400个,刷了一下缓存,变成600个,再刷一下,800个......65535个,问题到这里已经能够复现了,能复现就好办。查到了这里,我给自己泡了一杯普洱茶。
测试了刷新缓存的各个接口,问题基本上已经定位到了刷新通讯缓存,我们作为server端采用mina代码部分的问题,这个时候远程debug就派上了用场。基本上是在怀疑的代码块附近,每debug一步,我就lsof一下文件描述符的个数,终于找到一句可疑的话:
acceptor = new NioSocketAcceptor(CommunicationThreadPool.getSeperatorPool(networkConfig),
new SimpleIoProcessorPool(NioProcessor.class, availableProcessors +1));
调试的时候发现,每次执行到 new SimpleIoProcessorPool(NioProcessor.class, availableProcessors +1)) ,文件描述符会增加20,在刷新缓存的时候,会有10次这样的动作,加起来就是180个描述符的增长,基本符合我们观察到的现象.接着谷歌了一下这个类,果然我们的代码里面对mina的使用是不正确的,我们在刷新缓存的时候,对上一次的SimpleIoProcessorPool需要进行卸载。也即,我们需要将SimpleIoProcessorPool记录下来,再调用sessionSimpleIoProcessorPool.dispose();进行卸载。
最后的代码长成这样:
/**
* 停止监听服务
*/
public void dispose() {
if (acceptor !=null) {
acceptor.unbind();
acceptor.dispose();
CommunicationConfig networkConfig =configs.get(0);
LoggerUtil.info(logger, "销毁channelCode:" + networkConfig.getChannelCode() +"端口:"
+ networkConfig.getPort() +"成功!");
}
if (sessionSimpleIoProcessorPool !=null) {
sessionSimpleIoProcessorPool.dispose();
}
}
/**
* 启动服务端监听
*
* @param listener
* @throws IOException
*/
public void startup()throws IOException {
CommunicationConfig networkConfig =configs.get(0);
/* 设置内存获取方式 */
IoBuffer.allocate(1024, false).setAutoExpand(true);
int availableProcessors = Runtime.getRuntime().availableProcessors();
sessionSimpleIoProcessorPool =new SimpleIoProcessorPool(NioProcessor.class, availableProcessors +1);
acceptor =new NioSocketAcceptor(CommunicationThreadPool.getSeperatorPool(networkConfig),
sessionSimpleIoProcessorPool);
// SSL连接属性设置,责任链模式,必须在解码器链前面
initSSLConfig(networkConfig);
// 初始化Socket接收连接
initSocketAcceptorConfig(networkConfig);
acceptor.setReuseAddress(true);
acceptor.setHandler(TcpServerListenerContext.getListener(ConfigUtil
.getTcpKey(networkConfig)));
acceptor.bind(new InetSocketAddress(networkConfig.getPort()));
LoggerUtil.info(logger, "启动channelCode:" + networkConfig.getChannelCode() +"端口:"
+ networkConfig.getPort() +"成功!");
}