項(xiàng)目中用到storm+kafka+zookeeper嗅绰，在實(shí)際應(yīng)用中zk和kafka常出問題，這里記錄下在使用zk過程中的問題严衬。
注：zk版本是3.4.8织中，kafka是0.8.2.0。zk病游、storm和kafka都是運(yùn)行在同一個(gè)集群的三臺(tái)機(jī)器上唇跨。
CancelledKeyException
在開發(fā)環(huán)境測(cè)試的時(shí)候，一直沒有問題衬衬，后來原樣移植到測(cè)試環(huán)境下买猖，zk總是出異常，導(dǎo)致kafka和storm連接丟失并重新發(fā)起連接請(qǐng)求滋尉。有時(shí)候重新連接成功而有時(shí)候鏈接失敗玉控，導(dǎo)致kafka或者storm服務(wù)掛起甚至掛掉∈ㄏВ看了下kafka和storm的日志高诺，最終確定問題處在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
注：之所以說是大概的異常信息虱而，是因?yàn)樽约杭荷系娜罩驹谝淮沃匦虏渴鸬倪^程中忘了備份，已經(jīng)丟失耽梅，這里是網(wǎng)上找的別人家的異常日志薛窥，所以時(shí)間和一些環(huán)境信息可能不一致，不過異常類型是一致的。
關(guān)于zk的CancelledKeyException诅迷，其實(shí)很久就發(fā)現(xiàn)了佩番，后來網(wǎng)上找到說是zk的一個(gè)版本bug，由于不影響使用罢杉，所以一直沒理會(huì)趟畏，也不覺得是個(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è)備上的目錄而叼。
以上翻譯來自Google translate身笤。意思是希望用單獨(dú)的設(shè)備來記日志，且并將dataLogDir和dataDir分開配置葵陵，以防止由于日志落地磁盤與其他進(jìn)程產(chǎn)生競(jìng)爭(zhēng)液荸。
說的好像很有道理，因?yàn)閦k的確日志信息比較多脱篙，動(dòng)不動(dòng)就打娇钱，加上我一開始只配置了dataDir，這樣就會(huì)使得zk的事務(wù)日志和快照存儲(chǔ)在同一路徑下涡尘，所以是不是真的會(huì)引起磁盤競(jìng)爭(zhēng)忍弛！再加上响迂，開發(fā)環(huán)境沒問題考抄，測(cè)試環(huán)境有問題，配置一樣蔗彤，所以是不是測(cè)試機(jī)器的性能不行川梅，使得這個(gè)問題暴露的更明顯呢？
于是我去將dataDir和dataLogDir分開配置了然遏，當(dāng)然這的確是有必要的贫途，而且邏輯上更為清晰，盡管實(shí)際證明沒有解決自己的問題待侵，但是還是應(yīng)該這么做丢早。
好吧，我已經(jīng)說了，實(shí)際證明并沒有什么卵用怨酝。于是注意力再次移到這個(gè)CancelledKeyException上了傀缩。發(fā)現(xiàn)在測(cè)試環(huá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ì)開源項(xiàng)目的bug跟蹤不太懂）梆砸，顯示在版本3.5.3, 3.6.0中得到修復(fù)日矫。然而官網(wǎng)上并沒有給出它這里說的版本Ｏ柙酢！３嗵住飘痛！也許是內(nèi)測(cè)版本吧，汗容握。
好在下方給出了patch的鏈接宣脉，也就是說我可以自己去打補(bǔ)丁。雖然從來沒有任何關(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ì)比之后的部分源碼……這尼瑪是要我自己去修改源碼然后編譯啊~~~
走投無路的我感憾，去搜了一下zk編譯蜡励，然后果然有教程~~不過都是把zk源碼編譯成eclipse工程的教程，也就是說吹菱，跟著網(wǎng)上的步驟巍虫，我成功的將zookeeper編譯成eclipse工程彭则，然后導(dǎo)入到eclipse中鳍刷。接著，我看著上面的patch神代碼俯抖，認(rèn)真的改了下代碼输瓜。然后怎么辦？？尤揣？網(wǎng)上并沒有人說搔啊，于是我想既然是個(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í)候的日期锨天，但是大小比原來的小了一丟丟。
其實(shí)內(nèi)心是比較懵逼的剃毒，看上面的patch應(yīng)該是加了代碼啊病袄，咋編譯后變小了？不是丟了什么文件吧~~~官方的編譯流程是這樣的嗎赘阀？益缠？？帶著這些疑問基公，我選擇了先不管左刽，直接把新的jar包拿去替換原來的jar包，zk重啟酌媒。
于是奇跡出現(xiàn)了欠痴，果然沒有CancelledKeyException了！Ｃ胱伞喇辽！雖然現(xiàn)在距離這個(gè)更換已經(jīng)幾天了，但我仍然不敢說雨席，解決了這個(gè)bug菩咨，成功的打上了補(bǔ)丁，因?yàn)檫@一切只是我想當(dāng)然去做的~
當(dāng)然不用高興的太早陡厘，CancelledKeyException是沒有了抽米，但是同步延遲的問題仍然沒有解決。同時(shí)我也將打了patch后自己變異的jar提交到了開發(fā)環(huán)境糙置，也沒有啥問題云茸。只是延遲的問題在測(cè)試環(huán)境中仍然存在。
這著實(shí)讓人發(fā)狂谤饭，有點(diǎn)不知所措标捺。把能找到的相關(guān)的網(wǎng)頁都看了懊纳，基本就是按照官網(wǎng)說的，用專門的設(shè)備來存儲(chǔ)日志亡容，但是這個(gè)不現(xiàn)實(shí)嗤疯，而且開發(fā)環(huán)境也沒問題啊。
有一些網(wǎng)友給了一些解決方案闺兢，就是在zk配置中增加時(shí)間單元茂缚，使得連接的超時(shí)時(shí)間變大，從而保證同步延遲不會(huì)超過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ù)來確定的，這里是4s戴而。原來的配置是
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í)間不是特別的長所意，還是能在session過期之前返回淮逊，這樣連接勉強(qiáng)還可以維持。但是實(shí)際應(yīng)用中扶踊，還是會(huì)不斷的報(bào)同步延遲過高的警告：
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ì)掛备籽，但說明問題還是沒有解決。
最后無奈之下采用了一個(gè)網(wǎng)友的建議：在zoo.cfg配置文件中新增一項(xiàng)配置
forceSync=no
的確解決了問題分井，不再出現(xiàn)同步延遲太高的問題车猬，日志里不再有之前的warn~
當(dāng)然從該配置的意思上，我們就知道這并不是一個(gè)完美的解決方案尺锚，因?yàn)樗鼘⒛J(rèn)為yes的forceSync改為了no珠闰。這誠然可以解決同步延遲的問題，因?yàn)樗沟胒orceSync不再執(zhí)行Ｌ北纭７取！
我們可以這樣理解：zk的forceSync默認(rèn)為yes伐厌，意思是承绸，每次zk接收到一些數(shù)據(jù)之后，由于forceSync=yes挣轨，所以會(huì)立刻去將當(dāng)前的狀態(tài)信息同步到磁盤日志文件中军熏，同步完成之后才會(huì)給出應(yīng)答。在正常的情況下刃唐，這沒有是什么問題羞迷，但是在我的測(cè)試環(huá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)超過了連接的超時(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一定是先保證記錄日志到磁盤祖搓，再做應(yīng)答狱意，在任何一刻如果zk掛掉，重啟后都是不久之前的狀態(tài)拯欧，對(duì)集群的影響可以很小详囤。將此配置關(guān)閉，kafka或者storm看可以快速的得到應(yīng)答镐作，因?yàn)椴粫?huì)立刻同步到磁盤日志藏姐，但是如果某一刻zk掛掉，依賴zk的組件以為狀態(tài)信息已經(jīng)被zk記錄该贾，而zk實(shí)際在記錄之前已經(jīng)down了包各，則會(huì)出現(xiàn)一定的同步問題。
從源碼里我們看到靶庙， log.flush()首先被執(zhí)行问畅，所以一般而言日志文件還是寫進(jìn)了磁盤的。只不過操作系統(tǒng)為了提升寫磁盤的性能六荒，可能會(huì)有一些寫緩存护姆，導(dǎo)致雖然提交了flush，但是沒有真正的寫入磁盤掏击，如果使用
log.getChannel().force(false);
則保證一定會(huì)立刻寫入磁盤卵皂。可以看出這樣的確更加的健壯和安全砚亭，但是也帶來一些問題灯变，比如延遲殴玛。個(gè)人覺得，我們storm和kafka在業(yè)務(wù)上沒有直接以來zk添祸，所以滚粟，此處設(shè)置強(qiáng)制同步為no，也可以接受刃泌，何況此處的我凡壤，別無選擇~~~
然而我知道，問題并沒有真正的解決耙替，此處先標(biāo)記一下亚侠，以表敬意~~~
