Zookeeper運(yùn)維小結(jié)--CancelledKeyException

項(xiàng)目中用到storm+kafka+zookeeper，在實(shí)際應(yīng)用中zk和kafka常出問(wèn)題，這里記錄下在使用zk過(guò)程中的問(wèn)題。

注：zk版本是3.4.8，kafka是0.8.2.0。zk、storm和kafka都是運(yùn)行在同一個(gè)集群的三臺(tái)機(jī)器上。

CancelledKeyException

在開(kāi)發(fā)環(huán)境測(cè)試的時(shí)候，一直沒(méi)有問(wèn)題，后來(lái)原樣移植到測(cè)試環(huán)境下，zk總是出異常，導(dǎo)致kafka和storm連接丟失并重新發(fā)起連接請(qǐng)求。有時(shí)候重新連接成功而有時(shí)候鏈接失敗，導(dǎo)致kafka或者storm服務(wù)掛起甚至掛掉?？戳讼耴afka和storm的日志，最終確定問(wèn)題處在zk身上，查看zk日志，大概的異常信息如下：

ERROR [CommitProcessor:0:NIOServerCnxn@445] - Unexpected Exception:
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
at
org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:418)
at
org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1509)
at
org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:171)
at
org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:73)

2013-08-09 07:06:52,280 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsync-ing the write ahead log in SyncThread:0 took 1724ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide 
2013-08-09 07:06:58,315 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsync-ing the write ahead log in SyncThread:0 took 2378ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide 
2013-08-09 07:07:01,389 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsync-ing the write ahead log in SyncThread:0 took 1113ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide 
2013-08-09 07:07:06,580 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsync-ing the write ahead log in SyncThread:0 took 2291ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide 
2013-08-09 07:07:21,583 [myid:] - WARN  [SyncThread:0:FileTxnLog@321] - fsync-ing the write ahead log in SyncThread:0 took 8001ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide

注：之所以說(shuō)是大概的異常信息，是因?yàn)樽约杭荷系娜罩驹谝淮沃匦虏渴鸬倪^(guò)程中忘了備份，已經(jīng)丟失，這里是網(wǎng)上找的別人家的異常日志，所以時(shí)間和一些環(huán)境信息可能不一致，不過(guò)異常類型是一致的。

關(guān)于zk的CancelledKeyException，其實(shí)很久就發(fā)現(xiàn)了，后來(lái)網(wǎng)上找到說(shuō)是zk的一個(gè)版本bug，由于不影響使用，所以一直沒(méi)理會(huì)，也不覺(jué)得是個(gè)致命的bug。所以在看到上述日志之后，首先關(guān)注的是下面的warn，顯示同步數(shù)據(jù)延遲非常大，導(dǎo)致服務(wù)掛起，于是根據(jù)提示

fsync-ing the write ahead log in SyncThread:0 took 8001ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide

去官網(wǎng)查了下。官方在此處給出了提示，

Having a dedicated log device has a large impact on throughput and stable latencies. It is highly recommened to dedicate a log device and set dataLogDir to point to a directory on that device, and then make sure to point dataDir to a directory not residing on that device.

意思大概是

擁有專用的日志設(shè)備對(duì)吞吐量和穩(wěn)定延遲有很大的影響。 強(qiáng)烈建議您使用一個(gè)日志設(shè)備，并將dataLogDir設(shè)置為指向該設(shè)備上的目錄，然后確保將dataDir指向不在該設(shè)備上的目錄。

以上翻譯來(lái)自Google translate。意思是希望用單獨(dú)的設(shè)備來(lái)記日志，且并將dataLogDir和dataDir分開(kāi)配置，以防止由于日志落地磁盤(pán)與其他進(jìn)程產(chǎn)生競(jìng)爭(zhēng)。

說(shuō)的好像很有道理，因?yàn)閦k的確日志信息比較多，動(dòng)不動(dòng)就打，加上我一開(kāi)始只配置了dataDir，這樣就會(huì)使得zk的事務(wù)日志和快照存儲(chǔ)在同一路徑下，所以是不是真的會(huì)引起磁盤(pán)競(jìng)爭(zhēng)！再加上，開(kāi)發(fā)環(huán)境沒(méi)問(wèn)題，測(cè)試環(huán)境有問(wèn)題，配置一樣，所以是不是測(cè)試機(jī)器的性能不行，使得這個(gè)問(wèn)題暴露的更明顯呢？

于是我去將dataDir和dataLogDir分開(kāi)配置了，當(dāng)然這的確是有必要的，而且邏輯上更為清晰，盡管實(shí)際證明沒(méi)有解決自己的問(wèn)題，但是還是應(yīng)該這么做。

好吧，我已經(jīng)說(shuō)了，實(shí)際證明并沒(méi)有什么卵用。于是注意力再次移到這個(gè)CancelledKeyException上了。發(fā)現(xiàn)在測(cè)試環(huán)境上，伴隨著同步延遲問(wèn)題，有大量的CancelledKeyException日志，莫非是CancelledKeyException引起的同步延遲太高？于是準(zhǔn)備去解決一下這個(gè)bug。

在官網(wǎng)上，我們看到了解釋，地址如下：https://issues.apache.org/jira/browse/ZOOKEEPER-1237

官網(wǎng)中（具體信息請(qǐng)點(diǎn)擊鏈接去看下）提到，這個(gè)bug影響的版本有3.3.4, 3.4.0, 3.5.0，我用到是3.4.8，不太清楚這是包含在內(nèi)還是不包含？（對(duì)開(kāi)源項(xiàng)目的bug跟蹤不太懂），顯示在版本3.5.3, 3.6.0中得到修復(fù)。然而官網(wǎng)上并沒(méi)有給出它這里說(shuō)的版本?。。。∫苍S是內(nèi)測(cè)版本吧，汗。

好在下方給出了patch的鏈接，也就是說(shuō)我可以自己去打補(bǔ)丁。雖然從來(lái)沒(méi)有任何關(guān)于軟件打補(bǔ)丁的經(jīng)驗(yàn)，但好歹提供了解決方式，去看一下，然而又是血崩：

diff -uwp zookeeper-3.4.5/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java.ZK1237 zookeeper-3.4.5/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java
--- zookeeper-3.4.5/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java.ZK1237    2012-09-30 10:53:32.000000000 -0700
+++ zookeeper-3.4.5/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java    2013-08-07 13:20:19.227152865 -0700
@@ -150,7 +150,8 @@ public class NIOServerCnxn extends Serve
                 // We check if write interest here because if it is NOT set,
                 // nothing is queued, so we can try to send the buffer right
                 // away without waking up the selector
-                if ((sk.interestOps() & SelectionKey.OP_WRITE) == 0) {
+                if (sk.isValid() &&
+                    (sk.interestOps() & SelectionKey.OP_WRITE) == 0) {
                     try {
                         sock.write(bb);
                     } catch (IOException e) {
@@ -214,14 +215,18 @@ public class NIOServerCnxn extends Serve
 
                 return;
             }
-            if (k.isReadable()) {
+            if (k.isValid() && k.isReadable()) {
                 int rc = sock.read(incomingBuffer);
                 if (rc < 0) {
-                    throw new EndOfStreamException(
+                    if (LOG.isDebugEnabled()) {
+                        LOG.debug(
                             "Unable to read additional data from client sessionid 0x"
                             + Long.toHexString(sessionId)
                             + ", likely client has closed socket");
                 }
+                    close();
+                    return;
+                }
                 if (incomingBuffer.remaining() == 0) {
                     boolean isPayload;
                     if (incomingBuffer == lenBuffer) { // start of next request
@@ -242,7 +247,7 @@ public class NIOServerCnxn extends Serve
                     }
                 }
             }
-            if (k.isWritable()) {
+            if (k.isValid() && k.isWritable()) {
                 // ZooLog.logTraceMessage(LOG,
                 // ZooLog.CLIENT_DATA_PACKET_TRACE_MASK
                 // "outgoingBuffers.size() = " +

這簡(jiǎn)直是慘絕人寰的補(bǔ)丁啊，不是可執(zhí)行程序也不是壓縮包，而是源碼，還是對(duì)比之后的部分源碼……這尼瑪是要我自己去修改源碼然后編譯啊~~~

走投無(wú)路的我，去搜了一下zk編譯，然后果然有教程~~不過(guò)都是把zk源碼編譯成eclipse工程的教程，也就是說(shuō)，跟著網(wǎng)上的步驟，我成功的將zookeeper編譯成eclipse工程，然后導(dǎo)入到eclipse中。接著，我看著上面的patch神代碼，認(rèn)真的改了下代碼。然后怎么辦？？？網(wǎng)上并沒(méi)有人說(shuō)，于是我想既然是個(gè)ant的java project，應(yīng)該也是用ant編譯吧，于是進(jìn)了build.xml中講jdk版本從1.5換成1.7，然后cmd下進(jìn)入到該工程，執(zhí)行ant，然后顯示編譯成功。接著我去build路徑下找編譯后的jar包，果然有個(gè)新的zookeeper-3.4.8.jar，顯示日期是剛剛編譯時(shí)候的日期，但是大小比原來(lái)的小了一丟丟。

其實(shí)內(nèi)心是比較懵逼的，看上面的patch應(yīng)該是加了代碼啊，咋編譯后變小了？不是丟了什么文件吧~~~官方的編譯流程是這樣的嗎？？？帶著這些疑問(wèn)，我選擇了先不管，直接把新的jar包拿去替換原來(lái)的jar包，zk重啟。

于是奇跡出現(xiàn)了，果然沒(méi)有CancelledKeyException了！??！雖然現(xiàn)在距離這個(gè)更換已經(jīng)幾天了，但我仍然不敢說(shuō)，解決了這個(gè)bug，成功的打上了補(bǔ)丁，因?yàn)檫@一切只是我想當(dāng)然去做的~

當(dāng)然不用高興的太早，CancelledKeyException是沒(méi)有了，但是同步延遲的問(wèn)題仍然沒(méi)有解決。同時(shí)我也將打了patch后自己變異的jar提交到了開(kāi)發(fā)環(huán)境，也沒(méi)有啥問(wèn)題。只是延遲的問(wèn)題在測(cè)試環(huán)境中仍然存在。

這著實(shí)讓人發(fā)狂，有點(diǎn)不知所措。把能找到的相關(guān)的網(wǎng)頁(yè)都看了，基本就是按照官網(wǎng)說(shuō)的，用專門(mén)的設(shè)備來(lái)存儲(chǔ)日志，但是這個(gè)不現(xiàn)實(shí)，而且開(kāi)發(fā)環(huán)境也沒(méi)問(wèn)題啊。

有一些網(wǎng)友給了一些解決方案，就是在zk配置中增加時(shí)間單元，使得連接的超時(shí)時(shí)間變大，從而保證同步延遲不會(huì)超過(guò)session的超時(shí)時(shí)間。于是我嘗試修改了配置：

tickTime=4000
# The number of ticks that the initial 
# synchronization phase can take
initLimit=20
# The number of ticks that can pass between 
# sending a request and getting an acknowledgement
syncLimit=10

tickTime是zk中的時(shí)間單元，其他時(shí)間設(shè)置都是按照其倍數(shù)來(lái)確定的，這里是4s。原來(lái)的配置是

tickTime=2000
# The number of ticks that the initial 
# synchronization phase can take
initLimit=10
# The number of ticks that can pass between 
# sending a request and getting an acknowledgement
syncLimit=5

我都增加了一倍。這樣，如果zk的forceSync消耗的時(shí)間不是特別的長(zhǎng)，還是能在session過(guò)期之前返回，這樣連接勉強(qiáng)還可以維持。但是實(shí)際應(yīng)用中，還是會(huì)不斷的報(bào)同步延遲過(guò)高的警告：

fsync-ing the write ahead log in SyncThread:0 took 8001ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide

去查了下storm和kafka的日志，還是動(dòng)不動(dòng)就檢測(cè)到disconnected、session time out等日志，雖然服務(wù)基本不會(huì)掛，但說(shuō)明問(wèn)題還是沒(méi)有解決。

最后無(wú)奈之下采用了一個(gè)網(wǎng)友的建議：在zoo.cfg配置文件中新增一項(xiàng)配置

 forceSync=no

的確解決了問(wèn)題，不再出現(xiàn)同步延遲太高的問(wèn)題，日志里不再有之前的warn~

當(dāng)然從該配置的意思上，我們就知道這并不是一個(gè)完美的解決方案，因?yàn)樗鼘⒛J(rèn)為yes的forceSync改為了no。這誠(chéng)然可以解決同步延遲的問(wèn)題，因?yàn)樗沟胒orceSync不再執(zhí)行?。。?/p>

我們可以這樣理解：zk的forceSync默認(rèn)為yes，意思是，每次zk接收到一些數(shù)據(jù)之后，由于forceSync=yes，所以會(huì)立刻去將當(dāng)前的狀態(tài)信息同步到磁盤(pán)日志文件中，同步完成之后才會(huì)給出應(yīng)答。在正常的情況下，這沒(méi)有是什么問(wèn)題，但是在我的測(cè)試環(huán)境下，由于某種我未知的原因，使得寫(xiě)入日志到磁盤(pán)非常的慢，于是在這期間，zk的日志出現(xiàn)了

fsync-ing the write ahead log in SyncThread:0 took 8001ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide

然后由于同步日志耗時(shí)太久，連接得不到回復(fù)，如果已經(jīng)超過(guò)了連接的超時(shí)時(shí)間設(shè)置，那么連接（比如kafka）會(huì)認(rèn)為，該連接已經(jīng)失效，將重新申請(qǐng)建立~于是kafka和storm不斷的報(bào)錯(cuò)，不斷的重連，偶爾還會(huì)掛掉。

看了下zk里關(guān)于這里的源碼：

 for (FileOutputStream log : streamsToFlush) {
        log.flush();
        if (forceSync) {
            long startSyncNS = System.nanoTime();

            log.getChannel().force(false);

            long syncElapsedMS =
                TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startSyncNS);
            if (syncElapsedMS > fsyncWarningThresholdMS) {
                LOG.warn("fsync-ing the write ahead log in "
                        + Thread.currentThread().getName()
                        + " took " + syncElapsedMS
                        + "ms which will adversely effect operation latency. "
                        + "See the ZooKeeper troubleshooting guide");
            }
        }
    }

可以看出，這種配置為forceSync=no的多少有潛在的風(fēng)險(xiǎn)：zk默認(rèn)此項(xiàng)配置為yes，就是為了保證在任何時(shí)刻，只要有狀態(tài)改變，zk一定是先保證記錄日志到磁盤(pán)，再做應(yīng)答，在任何一刻如果zk掛掉，重啟后都是不久之前的狀態(tài)，對(duì)集群的影響可以很小。將此配置關(guān)閉，kafka或者storm看可以快速的得到應(yīng)答，因?yàn)椴粫?huì)立刻同步到磁盤(pán)日志，但是如果某一刻zk掛掉，依賴zk的組件以為狀態(tài)信息已經(jīng)被zk記錄，而zk實(shí)際在記錄之前已經(jīng)down了，則會(huì)出現(xiàn)一定的同步問(wèn)題。

從源碼里我們看到， log.flush()首先被執(zhí)行，所以一般而言日志文件還是寫(xiě)進(jìn)了磁盤(pán)的。只不過(guò)操作系統(tǒng)為了提升寫(xiě)磁盤(pán)的性能，可能會(huì)有一些寫(xiě)緩存，導(dǎo)致雖然提交了flush，但是沒(méi)有真正的寫(xiě)入磁盤(pán)，如果使用

log.getChannel().force(false);

則保證一定會(huì)立刻寫(xiě)入磁盤(pán)。可以看出這樣的確更加的健壯和安全，但是也帶來(lái)一些問(wèn)題，比如延遲。個(gè)人覺(jué)得，我們storm和kafka在業(yè)務(wù)上沒(méi)有直接以來(lái)zk，所以，此處設(shè)置強(qiáng)制同步為no，也可以接受，何況此處的我，別無(wú)選擇~~~

然而我知道，問(wèn)題并沒(méi)有真正的解決，此處先標(biāo)記一下，以表敬意~~~

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點(diǎn)，簡(jiǎn)書(shū)系信息發(fā)布平臺(tái)，僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

  • kafka的定義:是一個(gè)分布式消息系統(tǒng)，由LinkedIn使用Scala編寫(xiě)，用作LinkedIn的活動(dòng)流（Act...
    時(shí)待吾閱讀 5,537評(píng)論 1贊 15
  • Spring Cloud為開(kāi)發(fā)人員提供了快速構(gòu)建分布式系統(tǒng)中一些常見(jiàn)模式的工具（例如配置管理，服務(wù)發(fā)現(xiàn)，斷路器，智...
    卡卡羅2017閱讀 136,506評(píng)論 19贊 139
  • 前提: 只針對(duì)Kafka 0.9.0.1版本; 說(shuō)是運(yùn)維,其實(shí)偏重于問(wèn)題解決; 大部分解決方案都是google而來(lái)...
    掃帚的影子閱讀 32,701評(píng)論 7贊 20
  • 本文轉(zhuǎn)載自http://dataunion.org/?p=9307 背景介紹Kafka簡(jiǎn)介Kafka是一種分布式的...
    Bottle丶Fish閱讀 5,582評(píng)論 0贊 34
  • Design 1. Motivation 我們?cè)O(shè)計(jì)Kafka用來(lái)作為統(tǒng)一的平臺(tái)來(lái)處理大公司可能擁有的所有實(shí)時(shí)數(shù)據(jù)源...
    BlackManba_24閱讀 1,640評(píng)論 0贊 8

友情鏈接更多精彩內(nèi)容