一个获取IP地址引发的线程阻塞

余潇越

上午运维平台robert测试环境发现应用访问非常慢,长时间页面没有响应,看应用日志抛出一个获取主机Ip的例外:

Caused by: java.net.UnknownHostException: dwb-xxx: unknown error

因为这个异常以前也报过,是traceclient组件中针对mybatis调用链路的预处理器TraceMonitorMyBatisInterceptor程序中执行InetAddress.getLocalHost().getHostAddress()时,获取不到主机对应IP所导致的异常,这通常发生在没有在/etc/hosts中配置主机和ip的对应条目的情况下。

一开始并没有注意这个问题,怀疑是有大对象导致的内存堆积,于是调用jstat -gcutil pid 4000 30来查看内存和GC情况,发现内存和GC都很正常,GC频度很低,内存中各个分代也很稳定。

于是排查线程堆栈情况,把应用的stack拿下来分析,结果发现线程阻塞,贴图如下(图片看不清楚请放大字体):

图中可以看出来一个线程(http-bio-24880-exec-3)在调用InetAddress.getLocalHost的时候占用了对象0x00000000c08a3398的锁没释放,另外两个线程(taskScheduler-1和http-bio-24880-exec-4)也调用了InetAddress.getLocalHost,但是却阻塞在Waiting for Monitor Lock on 0x00000000c08a3398,也就是第一个线程所持有的资源,根据线程堆栈提示继续看InetAddress.getLocalHost的相应行代码,发现有对象锁的同步代码段,如下图所示:

问题大体上就定位于此了,概括来说,发生异常时,第一个持有锁的线程并没有释放锁,导致后来的线程阻塞在这里,于是找运维把主机ip对应的/etc/hosts加上对应条目,重启系统,问题解决,恢复正常!

那么问题来了,为何线程(http-bio-24880-exec-3)一直不释放锁或者很久才释放锁(具体哪个无法判断,因为我没有采样多个时间段内的stack,看不到持锁线程的变化情况,但可以肯定至少属于hold了很长的时间),因为根本没有高并发,QA环境下应用刚启动之后打开浏览器访问页面,就算发生例外,抛出异常,也应该释放cacheLock了,时间关系没有继续测试下去,有感兴趣的同学可以继续测试一下。

备注:这个问题很严重,因为我们几乎所有的系统都接入了traceclient,一旦所部署主机没有配置hosts,将导致严重的线程阻塞,这个问题我已反馈给运维同学。这也是我们工具组当初设计仪表盘项目时采用离线日志上报的原因,尽量不占用生产系统工作线程,尽可能解耦和非侵入。

PS:网上有个小伙也发生的类似的问题,URL见:

http://blog.csdn.net/puma_dong/article/details/53096149