storm任务的worker漂移【worker重新分配】通常因为OOM、过长的FullGC以及zookeeper负载过高等原因会导致worker中的executor心跳信息无法更新到zookeeper时发生,这个场景与上面描述的不同,属于操作系统内核Bug导致。
问题描述
- dataVVCount 6月份4-6号发生了3次worker飘移,最近一次是port=5723的worker发生飘移。
- 飘移的worker都发生在a01/a02两台机器
环境检查
- a01/a02操作系统Centos6.6,内核2.6.32-302.el6.x86_64【与其他机器不一致】
- 通过storm平台的监控发现,飘移时段宿主机&整个集群的负载比较低.
任务检查
- worker日志中没有发现任何与zk通讯错误的日志。
- worker进程监控指标没有明显波动。
worker飘移流程
- nimbus 判定executor不存活 [(当前时间 - 最后的心跳时间[2秒更新]) > nimbus.task.timeout.secs=30]
- Nimbus任务做executor重新分配
- supervisor关闭原worker[port=5723]
- 新worker启动
初步结论
根据以上得到的信息没有什么太有价值的信息,仍然在迷茫中。
zookeeper & storm日志
2016-06-04 13:45:06,529 [myid:3] - INFO [CommitProcessor:3:ZooKeeperServer@595] - Established session 0x353df7b6a55026f with negotiated timeout 40000 for client /10.x.x.18:55783
2016-06-06 06:22:13,626 [myid:3] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@354] - Exception causing close of session 0x353df7b6a55026f due to java.io.IOException: Connection reset by peer
2016-06-06 06:22:13,628 [myid:3] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed socket connection for client /10.x.x.18:55783 which had sessionid 0x353df7b6a55026f
2016-06-06 06:22:16,000 [myid:2] - INFO [SessionTracker:ZooKeeperServer@325] - Expiring session 0x353df7b6a55026f, timeout of 40000ms exceeded
2016-06-06 06:22:16,001 [myid:2] - INFO [ProcessThread(sid:2 cport:-1)::PrepRequestProcessor@476] - Processed session termination for sessionid: 0x353df7b6a55026f
2016-06-06 06:22:10 b.s.d.nimbus [INFO] Executor dataVVCount-214-1464683013:[544 544] not alive
2016-06-06 06:22:10 b.s.s.EvenScheduler [INFO] Available slots: ([“8033393c-e639-41a5-a565-066e6bd1748b” 5724]…..
2016-06-06 06:22:10 b.s.d.nimbus [INFO] Reassigning dataVVCcount-214-1464683013 to 20 slots
2016-06-06 06:22:12 b.s.d.supervisor [INFO] Shutting down and clearing state for id 8277aca4-aa83-4a66-b59c-80db17da807e.
2016-06-06 06:22:12 b.s.d.supervisor [INFO] Shutting down 8033393c-e639-41a5-a565-066e6bd1748b:8277aca4-aa83-4a66-b59c-80db17da807e
2016-06-06 06:22:13 b.s.d.supervisor [INFO] Shut down 8033393c-e639-41a5-a565-066e6bd1748b:8277aca4-aa83-4a66-b59c-80db17da807e
日志分析
- zookeeper断开连接发生在worker漂移之后【06:22:16剔除session,06:22:12关闭worker】
- worker飘移之前与zkServer的连接没有断开【worker日志中没有任何与zookeepr的错误信息】
最终结论
worker运行过程中executor正常情况下不会被判定not alive,肯定是由于某种原因executor不发心跳包给zookeeper了,基于之前遇到过java进程挂起的情况,大胆猜测这个worker进程意外挂起了,果断升级内核版本从Centos6.6 2.6.32-504.el6.x86_6升至较高版本【2.6.32-573.el6.x86_64】,经过3-4个月的观察实践证明,worker没有再发生漂移,说明当时的问题的确由于内核Bug导致。
内核挂起bug
Tene是对该缺陷的描述如下:
“这个内核漏洞的影响非常简单:在一些看似不可能的情况下,用户进程会死锁并被挂起。任何一个futex调用等待(即使被正确地唤醒)都有可能永远被阻止执行。就像Java里的Thread.park() 可能会一直阻塞那样,等等。如果足够幸运,你会在dmesg日志中发现soft lockup消息;如果没那么幸运(比如跟我们这样),你将不得不花几个月的人工成本去排查代码中的问题,还有可能一无所获。”
http://www.infoq.com/cn/news/2015/06/redhat-futex