API单位误解造成的严重故障

这是之前碰到的一个严重故障,当时的现象是整个集群全挂,一个比较重要的页面访问不了,会提示系统繁忙,因为故障比较严重,当时是直接重启的,没做线程dump,直接导致了查这个问题绕了不少路。

提示系统繁忙的原因是活跃线程数超过了设定的阈值,如果有线程dump的话就很容易看这些线程当时在做什么,还好万幸的时候当时有另外一组同样的集群当时也出了问题,而那组机器里有一台当时做了内存dump,用mat的人会知道通过分析内存dump也能看到线程的堆栈信息,只是分析起来会非常痛苦。

用mat打开后,点击一个类似数据库样的图标,在下拉中选择Java Basics–>Thread Overview and Stacks,可以看到所有的线程以及堆栈信息,但因为不在一个文件里,所以分析起来远没有jstack出来的thread dump那么简单,因为是活跃线程数超过了阈值,于是看了下活跃的线程的堆栈信息,发现所有的线程都在等待httpclient MultiThreadedHttpConnectionManager.doGetConnection的一把锁(在mat里因为不能导出,所以只能苦逼的一个一个线程点开来看..),代码类似如下:
synchronized(connectionPool){

}
而奇怪的是看不到哪个线程hold了这把锁,于是google了下httpclient是否会出现死锁的现象,发现有可能是因为启动了IdleConnectionTimeoutThread,于是在mat里搜了下这个线程,发现还真有,并且这个线程持有了connectionPool,但这个线程停在了PlainSocketImpl.socketClose0,这非常奇怪,理论上这个地方完全不可能被卡住。

想了想去都想不出什么原因,这个时候开发同学想起了他在代码里调用过setLinger,当时设这个参数是为了更优雅的关闭连接,代码里写的是setLinger(1000),于是我查了下这个api的单位,结果发现这个api的单位是s,而开发认为这里是ms,这也就意味着有可能会出现socketClose0这个地方卡住16分钟。

但理论上也仍然不太应该出现这现象,于是问了下对应的关闭连接的机器当时发生了什么,确认在这个时间段内刚好机器在停机维修,而机器停机维修就会导致socketClose0那个地方卡住,而这个地方卡住就自然导致了其他需要这把锁的线程卡住,10多分钟很容易就跑到了活跃线程数的阈值,这样的话就可以解释通了。

可见上面这个严重的故障造成的主要原因是api单位的误解,话说这也是为什么通常都要求在调用java的api要仔细看具体的说明,大家可以看到java新的一些api在传时间的这种接口基本都改成了需要开发自己传时间的单位,应该也是为了避免误用。

而说到api单位误解造成的严重故障,我印象最深的是《登陆火星》这本书里讲的一个故事,就是在机遇号之前有一个版本的机器人(貌似是叫雅典娜)在登陆火星的时候,由于两个团队对单位理解的不一致,提供这个api的好像是英国团队,而调用这个api的好像是美国团队,美国团队认为这个api的单位是kg,但实际这个单位是英镑,导致机器人在降落的时候重量等计算错误,直接烧毁,这估计是api单位误解造成的最大的损失吧,貌似上亿美金…

=============================
题图来源于:http://img1.gtimg.com/4/458/45879/4587955_980x1200_0.jpg
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。