今天元宵节，新年即将结束，年前由于每天在观察服务器日志和维护，没有出现过什么大问题。但是在过年放假期间，出现了日志过大的情况。平时每天产生1M的日志是正常的，但是年中有一天我查看服务器的时候，发现已经有42G日志了，线上功能也有些不正常，暗自心中一紧，迅速开启了这次排查之旅。

一、 备份服务器异常日志，恢复线上功能
使用linux系统cp命令，将异常日志复制备份。

cp [OPTION]... SOURCE... DIRECTORY

重启服务器进程，功能恢复正常。

二、 查看日志，初步定位

功能恢复以后，开始寻找异常原因。由于异常日志过大，下载很慢，于是再使用split命令分割日志文件，每块大小1G。但是1个G还是很大，我再次对第一个小块再次分割，每块100M。

split -b 100M mylog.txt

最后再下载第一个100M文件进行查看。
最后下载下来的日志显示如下：

java.net.SocketException: Too many open files
at sun.nio.ch.Net.socket0(Native Method)
at sun.nio.ch.Net.socket(Net.java:411)
at sun.nio.ch.DatagramChannelImpl.<init>(DatagramChannelImpl.java:142)
at sun.nio.ch.SelectorProviderImpl.openDatagramChannel(SelectorProviderImpl.java:46)
at java.nio.channels.DatagramChannel.open(DatagramChannel.java:182)
at lbms.plugins.mldht.kad.utils.AddressUtils.getDefaultRoute(AddressUtils.java:254)
at lbms.plugins.mldht.kad.RPCServerManager.startNewServers(RPCServerManager.java:147)
at lbms.plugins.mldht.kad.RPCServerManager.refresh(RPCServerManager.java:51)
at lbms.plugins.mldht.kad.DHT.update(DHT.java:929)
at lbms.plugins.mldht.kad.DHT.lambda$started$11(DHT.java:767)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

java.net.SocketException: Too many open files
at sun.nio.ch.Net.socket0(Native Method)
at sun.nio.ch.Net.socket(Net.java:411)
at sun.nio.ch.DatagramChannelImpl.<init>(DatagramChannelImpl.java:142)
at sun.nio.ch.SelectorProviderImpl.openDatagramChannel(SelectorProviderImpl.java:46)
at java.nio.channels.DatagramChannel.open(DatagramChannel.java:182)
at lbms.plugins.mldht.kad.utils.AddressUtils.getDefaultRoute(AddressUtils.java:254)
at lbms.plugins.mldht.kad.RPCServerManager.startNewServers(RPCServerManager.java:147)
at lbms.plugins.mldht.kad.RPCServerManager.refresh(RPCServerManager.java:51)
at lbms.plugins.mldht.kad.DHT.update(DHT.java:929)
at lbms.plugins.mldht.kad.DHT.lambda$started$11(DHT.java:767)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
...

如上所示，日志中不断在循环写入java.net.SocketException: Too many open files异常，并且一直未停止。于是到各大IT网站上搜索了相关问题，并尝试了一些方案解决。
大概的描述就是说：
linux系统文件句柄不够，已经被使用完了。
按照网上的方案，使用ulimit -a查询和永久修改了文件句柄配置文件，再次查询数量设置为了65535.

我想这下应该可以了。

三、 猜想泄漏，印证猜想
然而，事情并非如此。服务器继续运行一周以后，再次出现了这个异常。
于是重新思考了这个异常，可能是句柄泄漏造成的，并根据这个网址提供的思路进行排查。
侦测程序句柄泄露的统计方法
根据提示，在linux系统上编写了监控进程句柄的后台程序进行监控：

其中下面的命令是查询该进程当前占用的句柄数量。

 ls -l /proc/进程ID/fd |wc -l 

设置每600秒做一次句柄占用统计，等待一天，并用excel表格做出了折现走势图：

通过该折线图，进一步印证了是句柄泄漏的原因。

四、 定位泄漏位置，解决问题

句柄泄漏肯定是程序引起的。句柄通常是指文件、socket或者其他，句柄泄漏肯定是java中的文件操作流或者socket未关闭导致的。于是再次反复检查每一个设置文件操作的位置，发现并没有未关闭的情况。
将战地转移到本地IDE，使用windows任务进程管理器调试，反复测试每一个业务，并观察句柄和线程使用情况。

在反复测试每项业务的过程中，各项业务的线程和句柄占用在业务结束后都会释放，只有一项业务，即使结束了，线程和句柄占用数也一直未释放。因此，再次深入测试这项业务，并使用JVM栈命令查询各个线程的使用情况：

	jstack -l 进程ID

在这项业务结束后，我发现大量的线程依然处于RUNNABLE状态，并且在执行接收socket数据包，如下：

根据这些线程的提示，重新回到代码上，最终发现是在项目的该业务逻辑分支过程中，runtime对象执行超时情况下，并未做关闭处理，导致了许多用户在使用这项业务过程中，即使出现了超时，前端返回了提示，后端也并没有进行关闭回收，一直处于运行状态。

五、 验证泄漏解决
在打好这个补丁后，重新发布线上观察，并画出折线图：

句柄占用稳定在600以内，本次句柄泄漏排查告一段落。

六、 总结
通过本次经历，重新敬仰代码。遇到问题也不可怕，深入研究，一点一点啃也能解决。
但愿我的经历能给遇到问题的人提供一些排查思路和参考。