Reference: https://blog.csdn.net/xjping0794/article/details/77784171
1.1 操作系統信息
1.1.1 CPU信息
從上述可以看出在問題點CPU使用率並不高，故排除CPU問題。
1.1.2 內存信息
CM監控界面並無內存信息，無法提供圖片。
但問題期間，監控機器內存，發現還有剩余，故排除內存問題。
1.2 ZKFAILOVER日志信息
2017-09-0109:45:57,390 INFO org.apache.zookeeper.ClientCnxn: Client session timed out,have not heard from server in 1668ms for sessionid 0x0, closing socketconnection and attempting reconnect
2017-09-01 09:45:58,224 ERRORorg.apache.hadoop.ha.ActiveStandbyElector: Connection timed out: couldn'tconnect to ZooKeeper in 5000 milliseconds
2017-09-0109:45:58,450 INFO org.apache.zookeeper.ZooKeeper: Session: 0x0 closed
2017-09-0109:45:58,450 INFO org.apache.zookeeper.ClientCnxn: EventThread shut down
2017-09-0109:45:58,451 WARN org.apache.hadoop.ha.ActiveStandbyElector:org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode =ConnectionLoss
2017-09-0109:46:03,453 INFO org.apache.zookeeper.ZooKeeper: Initiating client connection,connectString=test-ssps-s-02:2181,test-ssps-s-03:2181,test-ssps-s-04:2181sessionTimeout=5000watcher=org.apache.hadoop.ha.ActiveStandbyElector$WatcherWithClientRef@7f0d36c
2017-09-0109:46:03,455 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection toserver test-ssps-s-04/10.117.210.216:2181. Will not attempt to authenticateusing SASL (unknown error)
2017-09-0109:46:03,463 INFO org.apache.zookeeper.ClientCnxn: Socket connectionestablished to test-ssps-s-04/10.117.210.216:2181, initiating session
2017-09-0109:46:05,131 INFO org.apache.zookeeper.ClientCnxn: Client session timed out,have not heard from server in 1668ms for sessionid 0x0, closing socketconnection and attempting reconnect
2017-09-0109:46:05,885 INFO org.apache.zookeeper.ClientCnxn: Opening socket connection toserver test-ssps-s-03/10.51.20.155:2181. Will not attempt to authenticate usingSASL (unknown error)
2017-09-0109:46:06,626 INFO org.apache.zookeeper.ClientCnxn: Socket connectionestablished to test-ssps-s-03/10.51.20.155:2181, initiating session
2017-09-0109:46:08,293 INFO org.apache.zookeeper.ClientCnxn: Client session timed out,have not heard from server in 1667ms for sessionid 0x0, closing socketconnection and attempting reconnect
2017-09-01 09:46:08,454 ERROR org.apache.hadoop.ha.ActiveStandbyElector:Connection timed out: couldn't connect to ZooKeeper in 5000 milliseconds
2017-09-0109:46:09,157 INFO org.apache.zookeeper.ZooKeeper: Session: 0x0 closed
2017-09-01 09:46:09,157 INFO org.apache.zookeeper.ClientCnxn:EventThread shut down
2017-09-0109:46:09,158 WARN org.apache.hadoop.ha.ActiveStandbyElector:org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode =ConnectionLoss
標紅日志，顯示無法與zk建立連接，導致failover終止。
1.3 YARN RESOURCEMANAGER日志信息
具體日志信息未保留，但均是由於ZK異常，導致服務掛掉。
1.4 ZOOKEEPER服務日志
摘取leader和follower 服務日志分析。
1.4.1 leader日志
分析異常時間點9點40到9點50日志，發現以下報錯信息：
2017-09-0109:45:49,754 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Acceptedsocket connection from /10.51.20.155:40713
2017-09-0109:45:49,754 INFO org.apache.zookeeper.server.ZooKeeperServer: Clientattempting to establish new session at /10.51.20.155:40713
2017-09-0109:45:51,090 INFO org.apache.zookeeper.server.PrepRequestProcessor: Gotuser-level KeeperException when processing sessionid:0x15e2a2922a213b5type:setData cxid:0x21 zxid:0x6d00050f33 txntype:-1 reqpath:n/a ErrorPath:/yarn-leader-election/yarnRM/ActiveBreadCrumb Error:KeeperErrorCode =BadVersion for /yarn-leader-election/yarnRM/ActiveBreadCrumb
2017-09-0109:45:52,000 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x35e2a2922671668, timeout of 5000ms exceeded
2017-09-0109:45:52,001 INFO org.apache.zookeeper.server.PrepRequestProcessor: Processedsession termination for sessionid: 0x35e2a2922671668
2017-09-0109:45:52,482 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Acceptedsocket connection from /10.117.68.10:33589
2017-09-0109:45:52,484 INFO org.apache.zookeeper.server.ZooKeeperServer: Clientattempting to renew session 0x15e2a2922a21870 at /10.117.68.10:33589
2017-09-0109:45:52,484 INFO org.apache.zookeeper.server.ZooKeeperServer: Establishedsession 0x15e2a2922a21870 with negotiated timeout 5000 for client/10.117.68.10:33589
2017-09-0109:45:52,884 WARN org.apache.zookeeper.server.NIOServerCnxn: caught end ofstream exception
2017-09-0109:45:52,884 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socketconnection for client /10.51.20.155:40712 which had sessionid 0x15de73379b60000
2017-09-0109:45:53,244 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Acceptedsocket connection from /10.51.20.155:40730
2017-09-0109:46:36,520 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Acceptedsocket connection from /10.51.20.155:40749
2017-09-01 09:46:29,773 WARN org.apache.zookeeper.server.persistence.FileTxnLog:fsync-ing the write ahead log in SyncThread:3 took53812ms which will adversely effect operation latency. See theZooKeeper troubleshooting guide
2017-09-01 09:46:17,239 INFOorg.apache.zookeeper.server.quorum.Leader: Shutting down
2017-09-0109:45:58,000 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x15e2a2922a21870, timeout of 5000ms exceeded
2017-09-01 09:45:53,439 ERRORorg.apache.zookeeper.server.NIOServerCnxn: Unexpected Exception:
java.nio.channels.CancelledKeyException atsun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73) atsun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77) atorg.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:418) atorg.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1509)atorg.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:171)atorg.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:73)
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x15e2a2922a21871, timeout of 10000ms exceeded
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x15e2a2922a213b5, timeout of 10000ms exceeded
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x15de73379b60000, timeout of 6000ms exceeded
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x25de7337bb00000, timeout of 6000ms exceeded
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x35e2a2922671890, timeout of 10000ms exceeded
2017-09-0109:46:36,648 INFO org.apache.zookeeper.server.ZooKeeperServer: Expiring session0x15e2a2922a213b6, timeout of 10000ms exceeded
2017-09-01 09:46:36,647 INFOorg.apache.zookeeper.server.quorum.Leader: Shutdown called
從標紅日志信息可以看出，zookeerper 服務在同步日志過程中耗時太長，花了53812ms（正常應該在3秒內），同步日志會導致ZK無法響應外部請求，進而引發session過期，進而引發zk 服務端shut down。
另外，CancelledKeyException錯誤，是由於session失效后，socket已關閉，但服務端仍往該session發送回復信號，引發該錯誤，該錯誤並不致命，影響不大。是zookeeper版本（3.4.5）bug所致，已在ZK新版本中優化掉。
其他點日志報同樣問題，尤其10點33分，zk刷新日志竟然花了將近2分鍾，導致服務異常退出。
1.4.2 Follower日志
分析異常時間點13點00到13點10日志，發現以下報錯信息：
2017-09-0113:08:55,526 INFO org.apache.zookeeper.server.ZooKeeperServer: Establishedsession 0x15e3b4962bc0000 with negotiated timeout 6000 for client/10.117.210.216:39709
2017-09-0113:08:57,259 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: Acceptedsocket connection from /10.51.20.155:53325
2017-09-0113:08:57,260 INFO org.apache.zookeeper.server.ZooKeeperServer: Clientattempting to renew session 0x25e3b531e84006e at /10.51.20.155:53325
2017-09-0113:08:57,261 INFO org.apache.zookeeper.server.ZooKeeperServer: Established session0x25e3b531e84006e with negotiated timeout 6000 for client /10.51.20.155:53325
2017-09-0113:08:57,261 INFO org.apache.zookeeper.server.PrepRequestProcessor: Gotuser-level KeeperException when processing sessionid:0x25e3b531e84006etype:delete cxid:0x11e3d zxid:0x7000006e8f txntype:-1 reqpath:n/a ErrorPath:/admin/preferred_replica_election Error:KeeperErrorCode = NoNode for/admin/preferred_replica_election
2017-09-0113:08:59,525 WARN org.apache.zookeeper.server.NIOServerCnxn: caught end ofstream exception
2017-09-0113:08:59,526 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socketconnection for client /10.117.210.216:39709 which had sessionid0x15e3b4962bc0000
2017-09-01 13:09:00,302 WARNorg.apache.zookeeper.server.persistence.FileTxnLog: fsync-ing the write aheadlog in SyncThread:3 took 35356ms which will adversely effect operation latency.See the ZooKeeper troubleshooting guide
2017-09-0113:09:01,263 WARN org.apache.zookeeper.server.NIOServerCnxn: caught end ofstream exception
2017-09-0113:09:01,264 INFO org.apache.zookeeper.server.NIOServerCnxn: Closed socketconnection for client /10.51.20.155:53325 which had sessionid 0x25e3b531e84006e
原因同上。
1.5 磁盤
在問題點，發現IO使用很高。
9點46分，問題出現后，基於當時的集群IO值分析，發現IO達到200M/s，同樣，10點33分IO也達到了將近200M/s，磁盤IO可能是一個瓶頸。
1.6 網絡
網絡正常。
2 總結及建議
從監控及分析結果來看，均屬ZK服務端在fsync-ing the write ahead log日志時超長引起。從問題產生時間段的IO來分析，發現磁盤IO較正常點高了很多，達到200M/s，證明問題發生時，有大作業在進行磁盤IO，與開發人員楊儀軍確認，其今天確實較以往跑了大數據的作業。頸，需進一步通過專業工具測試磁盤IO能力。
2.1.1 官網建議
關於ZK日志存放，官網給出如下建議:
Having a dedicated log devicehas a large impact on throughput and stable latencies. It is highly recommenedto dedicate a log device and set dataLogDir to point to a directory on thatdevice, and then make sure to point dataDir to a directory not residing on thatdevice.
故為避免此類問題，dataLogDir存放目錄應該與dataDir分開，可單獨采用一套存儲設備來存放ZK日志。
2.1.2 磁盤IO
從今天觀察情況來看，磁盤IO嚴重不行，200M/s即達到瓶頸，需進一步通過專業工具測試磁盤IO能力。
2.1.3 關閉forceSync參數
在ZOO.CFG中增加：
forceSync=no
默認是開啟的，為避免同步延遲問題，ZK接收到數據后會立刻去講當前狀態信息同步到磁盤日志文件中，同步完成后才會應答。將此項關閉后，客戶端連接可以得到快速響應。Zk涮日志源碼如下圖：
關閉forceSync選項后，會存在潛在風險，雖然依舊會刷磁盤（log.flush()首先被執行），但因為操作系統為提高寫磁盤效率，會先寫緩存，當機器異常后，可能導致一些zk狀態信息沒有同步到磁盤，從而帶來ZK前后信息不一樣問題。
2.1.4 解決CancelledKeyException
該問題，已在ZooKeeper 3.4.8版本中得到修復。
如需解決該版本問題，可打補丁https://issues.apache.org/jira/browse/ZOOKEEPER-1237
然后重新編譯ZK並使用。
---------------------
作者：jimmyxyalj
來源：CSDN
原文：https://blog.csdn.net/xjping0794/article/details/77784171
版權聲明：本文為博主原創文章，轉載請附上博文鏈接！