Worker 启动后异常退出问题的排查解决

最近应用升级之后，有个机器上的 worker 总会在启动一段时间后挂掉。worker 日志如下：

 2015-06-18T17:19:19.931+0800 o.a.s.c.ConnectionState [ERROR] Connection timed out for connection string (z124:2181,z128:2181,z168:2181/storm) and timeout (15000) / elapsed (16172)
492856 org.apache.storm.curator.CuratorConnectionLossException: KeeperErrorCode = ConnectionLoss
492857         at org.apache.storm.curator.ConnectionState.checkTimeouts(ConnectionState.java:198) [storm-core-0.9.3.jar:0.9.3]
492858         at org.apache.storm.curator.ConnectionState.getZooKeeper(ConnectionState.java:88) [storm-core-0.9.3.jar:0.9.3]
492859         at org.apache.storm.curator.CuratorZookeeperClient.getZooKeeper(CuratorZookeeperClient.java:115) [storm-core-0.9.3.jar:0.9.3]
492860         at org.apache.storm.curator.framework.imps.CuratorFrameworkImpl.getZooKeeper(CuratorFrameworkImpl.java:488) [storm-core-0.9.3.jar:0.9.3]
492861         at org.apache.storm.curator.framework.imps.ExistsBuilderImpl$2.call(ExistsBuilderImpl.java:168) [storm-core-0.9.3.jar:0.9.3]
492862         at org.apache.storm.curator.framework.imps.ExistsBuilderImpl$2.call(ExistsBuilderImpl.java:161) [storm-core-0.9.3.jar:0.9.3]492863         at org.apache.storm.curator.RetryLoop.callWithRetry(RetryLoop.java:107) [storm-core-0.9.3.jar:0.9.3]492864         at org.apache.storm.curator.framework.imps.ExistsBuilderImpl.pathInForeground(ExistsBuilderImpl.java:157) [storm-core-0.9.3.jar:0.9.3]
492865         at org.apache.storm.curator.framework.imps.ExistsBuilderImpl.forPath(ExistsBuilderImpl.java:148) [storm-core-0.9.3.jar:0.9.3]492866         at org.apache.storm.curator.framework.imps.ExistsBuilderImpl.forPath(ExistsBuilderImpl.java:36) [storm-core-0.9.3.jar:0.9.3]
492867         at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source) ~[na:na]
492868         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_71]
492869         at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_71]
492870         at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93) [clojure-1.5.1.jar:na]
492871         at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:28) [clojure-1.5.1.jar:na]
492872         at backtype.storm.zookeeper$get_version.invoke(zookeeper.clj:156) [storm-core-0.9.3.jar:0.9.3]
492873         at backtype.storm.cluster$mk_distributed_cluster_state$reify__1915.get_version(cluster.clj:111) [storm-core-0.9.3.jar:0.9.3]
492874         at backtype.storm.cluster$mk_storm_cluster_state$reify__2372.assignment_version(cluster.clj:287) [storm-core-0.9.3.jar:0.9.3]
492875         at sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source) ~[na:na]
492876         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_71]
492877         at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_71]
492878         at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:93) [clojure-1.5.1.jar:na]
492879         at clojure.lang.Reflector.invokeInstanceMethod(Reflector.java:28) [clojure-1.5.1.jar:na]
492880         at backtype.storm.daemon.worker$mk_refresh_connections$this__3690.invoke(worker.clj:255) [storm-core-0.9.3.jar:0.9.3]
492881         at backtype.storm.daemon.worker$mk_refresh_connections$this__3690.invoke(worker.clj:253) [storm-core-0.9.3.jar:0.9.3]
492882         at backtype.storm.timer$schedule_recurring$this__1649.invoke(timer.clj:99) [storm-core-0.9.3.jar:0.9.3]
492883         at backtype.storm.timer$mk_timer$fn__1632$fn__1633.invoke(timer.clj:50) [storm-core-0.9.3.jar:0.9.3]
492884         at backtype.storm.timer$mk_timer$fn__1632.invoke(timer.clj:42) [storm-core-0.9.3.jar:0.9.3]
492885         at clojure.lang.AFn.run(AFn.java:24) [clojure-1.5.1.jar:na]
492886         at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]

而同一时间的 supervisor 不停地提示 “{id} still hasn't started”

2015-06-18T17:14:56.752+0800 b.s.d.supervisor [INFO] 2376a892-2a8a-401e-9bd6-85059ab57586 still hasn't started
646 2015-06-18T17:14:57.254+0800 b.s.d.supervisor [INFO] 2376a892-2a8a-401e-9bd6-85059ab57586 still hasn't started
647 2015-06-18T17:14:57.756+0800 b.s.d.supervisor [INFO] 2376a892-2a8a-401e-9bd6-85059ab57586 still hasn't started
...（若干条重复的信息）

当然，正常情况下 supervisor 在刚启动 worker 的时候也会报这个信息，只不过会在 worker 正常运行之后恢复正常。但是这里的 supervisor 之后仍然会不停地尝试重连，并且最终在超时后放弃这个 worker，这个就不属于正常情况了。

2015-06-18T17:17:07.880+0800 o.a.s.z.ClientCnxn [INFO] Unable to read additional data from server sessionid 0x804de6f8a15a0000, likely server has closed socket, closing socket connection and attempting reco    nnect
668 2015-06-18T17:17:19.491+0800 o.a.s.z.ClientCnxn [INFO] Opening socket connection to server hd124/192.168.91.124:2181. Will not attempt to authenticate using SASL (unknown error)
669 2015-06-18T17:17:19.492+0800 o.a.s.z.ClientCnxn [INFO] Socket connection established to hd124/192.168.91.124:2181, initiating session
670 2015-06-18T17:17:19.495+0800 o.a.s.z.ClientCnxn [INFO] Session establishment complete on server hd124/192.168.91.124:2181, sessionid = 0x804de6f8a15a0000, negotiated timeout = 20000671 2015-06-18T17:17:27.913+0800 o.a.s.c.f.s.ConnectionStateManager [INFO] State change: SUSPENDED
672 2015-06-18T17:17:27.918+0800 b.s.cluster [WARN] Received event :disconnected::none: with disconnected Zookeeper.
673 2015-06-18T17:17:27.918+0800 o.a.s.c.f.s.ConnectionStateManager [INFO] State change: RECONNECTED

...

689 2015-06-18T17:18:21.492+0800 o.a.s.z.ClientCnxn [INFO] Unable to reconnect to ZooKeeper service, session 0x804de6f8a15a0000 has expired, closing socket connection
690 2015-06-18T17:18:21.492+0800 o.a.s.c.f.s.ConnectionStateManager [INFO] State change: LOST

这个问题乍一看是网络问题，而且很多帖子也这么说，比如http://blog.csdn.net/jmppok/article/details/17073397 还有 SO 上面搜到的几篇答案说的都是 hosts 配置问题。不过这里的配置并没有问题，网络也没有问题，Storm 的元数据也正常。

另外也有说是 JVM 配置问题（http://macrochen.iteye.com/blog/1428093），但实际上机器的内存一直很稳定，而且 JVM 的日志记录也正常。由于我是在执行 DRPC 的时候出现问题的，还特意检查/重启了 DRPC 服务器，发现也不是 DRPC 的问题。

这些都没问题，那就有可能是 CPU 的问题了，top 看一下（没有装 sar 和 iostat 就先这么凑合了）

top - 09:36:52 up 17 days, 21:16,  1 user,  load average: 20.31, 19.13, 11.12
Tasks: 128 total,   6 running, 122 sleeping,   0 stopped,   0 zombie
Cpu(s): 27.0%us, 73.0%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   2075036k total,  2021612k used,    53424k free,   131148k buffers
Swap:  4128760k total,       68k used,  4128692k free,   722616k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                             
 4950 root      18   0  698m 573m  13m S 99.2 28.3  10:50.45 java

果然，99.2% 的 CPU 占用，系统不能长时间承受这么高的负载，就中断了 worker 进程。这个理由可以解释，因为确实我们在新版本应用里把吞吐量加大了一倍，从 Storm UI 中可以看出，在拓扑刚上线的时候，处理量较大的 bolt 的 capacity 会瞬间飙升到接近 1 的程度，虽然在后面数据流平稳下来之后可以慢慢降低，但是这个过程还是有很大的不确定性。所以，暂时需要先把吞吐量降下来，再考虑慢慢调整。不过，这个问题还没这么简单。因为我发现集群中同配置的另一个机器就没有这个问题，而且即使在这台机器 worker 挂掉，nimbus 将这台机器的 worker 分配到另外那台机器的情况下，那台机器上的 CPU 也只有 80+%。同样配置同样的网络运行同样的进程怎么会有这么大的差异？

对这个问题苦思了半天不得其解，最后想想还是要看看 CPU 设备信息有没有什么问题。然后，就没有然后了，额，不对，说顺口了，然后应该就是出现真相的地方了

[root@s2 /home/storm/apache-storm-0.9.3/logs]$>cat /proc/cpuinfo 
processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 62
model name  : Intel(R) Xeon(R) CPU E5-2620 v2 @ 2.10GHz

这里只有一个 CPU。真是让人哭笑不得，我们的服务器都是用的分配的虚拟机，也不知道谁把这台机器只分了个单核的 CPU，数据流压力稍微高点当然会扛不住。但是也没办法，现在服务器资源还紧张，只能这么凑合着用，然后继续等着新服务器的申请什么时候能批下来……

当然，除了硬件方面的问题之外，拓扑本身也还有可以优化的地方。一方面，从 Storm UI 上观察到的某些负载较大的 bolt 也确实需要调整下并发度；另一方面，数据流优先进入的部分 bolt 也需要优化下处理方法。这样双管齐下才能真正地解决好问题。

彩蛋 # get 到的新技能 - 在 worker 没有日志的时候可以手动执行 supervisor 中的启动命令（就是 “java xxx” 那个大长串）来启动 worker

Reference

Comments

comments powered by Disqus