Zookeeper运维小结--CancelledKeyException

96
sheen口开河
2016.11.21 15:24* 字数 2638

项目中用到storm+kafka+zookeeper,在实际应用中zk和kafka常出问题,这里记录下在使用zk过程中的问题。

注:zk版本是3.4.8,kafka是0.8.2.0。zk、storm和kafka都是运行在同一个集群的三台机器上。

CancelledKeyException

在开发环境测试的时候,一直没有问题,后来原样移植到测试环境下,zk总是出异常,导致kafka和storm连接丢失并重新发起连接请求。有时候重新连接成功而有时候链接失败,导致kafka或者storm服务挂起甚至挂掉。看了下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 

注:之所以说是大概的异常信息,是因为自己集群上的日志在一次重新部署的过程中忘了备份,已经丢失,这里是网上找的别人家的异常日志,所以时间和一些环境信息可能不一致,不过异常类型是一致的。

关于zk的CancelledKeyException,其实很久就发现了,后来网上找到说是zk的一个版本bug,由于不影响使用,所以一直没理会,也不觉得是个致命的bug。所以在看到上述日志之后,首先关注的是下面的warn,显示同步数据延迟非常大,导致服务挂起,于是根据提示

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

去官网查了下。官方在此处给出了提示,

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.

意思大概是

拥有专用的日志设备对吞吐量和稳定延迟有很大的影响。 强烈建议您使用一个日志设备,并将dataLogDir设置为指向该设备上的目录,然后确保将dataDir指向不在该设备上的目录。

以上翻译来自Google translate。意思是希望用单独的设备来记日志,且并将dataLogDir和dataDir分开配置,以防止由于日志落地磁盘与其他进程产生竞争。

说的好像很有道理,因为zk的确日志信息比较多,动不动就打,加上我一开始只配置了dataDir,这样就会使得zk的事务日志和快照存储在同一路径下,所以是不是真的会引起磁盘竞争!再加上,开发环境没问题,测试环境有问题,配置一样,所以是不是测试机器的性能不行,使得这个问题暴露的更明显呢?

于是我去将dataDir和dataLogDir分开配置了,当然这的确是有必要的,而且逻辑上更为清晰,尽管实际证明没有解决自己的问题,但是还是应该这么做。

好吧,我已经说了,实际证明并没有什么卵用。于是注意力再次移到这个CancelledKeyException上了。发现在测试环境上,伴随着同步延迟问题,有大量的CancelledKeyException日志,莫非是CancelledKeyException引起的同步延迟太高?于是准备去解决一下这个bug。

在官网上,我们看到了解释,地址如下:https://issues.apache.org/jira/browse/ZOOKEEPER-1237

官网中(具体信息请点击链接去看下)提到,这个bug影响的版本有3.3.4, 3.4.0, 3.5.0,我用到是3.4.8,不太清楚这是包含在内还是不包含?(对开源项目的bug跟踪不太懂),显示在版本3.5.3, 3.6.0中得到修复。然而官网上并没有给出它这里说的版本!!!!也许是内测版本吧,汗。

好在下方给出了patch的链接,也就是说我可以自己去打补丁。虽然从来没有任何关于软件打补丁的经验,但好歹提供了解决方式,去看一下,然而又是血崩:

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() = " +

这简直是惨绝人寰的补丁啊,不是可执行程序也不是压缩包,而是源码,还是对比之后的部分源码……这尼玛是要我自己去修改源码然后编译啊~~~

走投无路的我,去搜了一下zk编译,然后果然有教程~~不过都是把zk源码编译成eclipse工程的教程,也就是说,跟着网上的步骤,我成功的将zookeeper编译成eclipse工程,然后导入到eclipse中。接着,我看着上面的patch神代码,认真的改了下代码。然后怎么办???网上并没有人说,于是我想既然是个ant的java project,应该也是用ant编译吧,于是进了build.xml中讲jdk版本从1.5换成1.7,然后cmd下进入到该工程,执行ant,然后显示编译成功。接着我去build路径下找编译后的jar包,果然有个新的zookeeper-3.4.8.jar,显示日期是刚刚编译时候的日期,但是大小比原来的小了一丢丢。

其实内心是比较懵逼的,看上面的patch应该是加了代码啊,咋编译后变小了?不是丢了什么文件吧~~~官方的编译流程是这样的吗???带着这些疑问,我选择了先不管,直接把新的jar包拿去替换原来的jar包,zk重启。

于是奇迹出现了,果然没有CancelledKeyException了!!!虽然现在距离这个更换已经几天了,但我仍然不敢说,解决了这个bug,成功的打上了补丁,因为这一切只是我想当然去做的~

当然不用高兴的太早,CancelledKeyException是没有了,但是同步延迟的问题仍然没有解决。同时我也将打了patch后自己变异的jar提交到了开发环境,也没有啥问题。只是延迟的问题在测试环境中仍然存在。

这着实让人发狂,有点不知所措。把能找到的相关的网页都看了,基本就是按照官网说的,用专门的设备来存储日志,但是这个不现实,而且开发环境也没问题啊。

有一些网友给了一些解决方案,就是在zk配置中增加时间单元,使得连接的超时时间变大,从而保证同步延迟不会超过session的超时时间。于是我尝试修改了配置:

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中的时间单元,其他时间设置都是按照其倍数来确定的,这里是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消耗的时间不是特别的长,还是能在session过期之前返回,这样连接勉强还可以维持。但是实际应用中,还是会不断的报同步延迟过高的警告:

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

去查了下storm和kafka的日志,还是动不动就检测到disconnected、session time out等日志,虽然服务基本不会挂,但说明问题还是没有解决。

最后无奈之下采用了一个网友的建议:在zoo.cfg配置文件中新增一项配置

 forceSync=no

的确解决了问题,不再出现同步延迟太高的问题,日志里不再有之前的warn~

当然从该配置的意思上,我们就知道这并不是一个完美的解决方案,因为它将默认为yes的forceSync改为了no。这诚然可以解决同步延迟的问题,因为它使得forceSync不再执行!!!

我们可以这样理解:zk的forceSync默认为yes,意思是,每次zk接收到一些数据之后,由于forceSync=yes,所以会立刻去将当前的状态信息同步到磁盘日志文件中,同步完成之后才会给出应答。在正常的情况下,这没有是什么问题,但是在我的测试环境下,由于某种我未知的原因,使得写入日志到磁盘非常的慢,于是在这期间,zk的日志出现了

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

然后由于同步日志耗时太久,连接得不到回复,如果已经超过了连接的超时时间设置,那么连接(比如kafka)会认为,该连接已经失效,将重新申请建立~于是kafka和storm不断的报错,不断的重连,偶尔还会挂掉。

看了下zk里关于这里的源码:

 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的多少有潜在的风险:zk默认此项配置为yes,就是为了保证在任何时刻,只要有状态改变,zk一定是先保证记录日志到磁盘,再做应答,在任何一刻如果zk挂掉,重启后都是不久之前的状态,对集群的影响可以很小。将此配置关闭,kafka或者storm看可以快速的得到应答,因为不会立刻同步到磁盘日志,但是如果某一刻zk挂掉,依赖zk的组件以为状态信息已经被zk记录,而zk实际在记录之前已经down了,则会出现一定的同步问题。

从源码里我们看到, log.flush()首先被执行,所以一般而言日志文件还是写进了磁盘的。只不过操作系统为了提升写磁盘的性能,可能会有一些写缓存,导致虽然提交了flush,但是没有真正的写入磁盘,如果使用

log.getChannel().force(false);

则保证一定会立刻写入磁盘。可以看出这样的确更加的健壮和安全,但是也带来一些问题,比如延迟。个人觉得,我们storm和kafka在业务上没有直接以来zk,所以,此处设置强制同步为no,也可以接受,何况此处的我,别无选择~~~

然而我知道,问题并没有真正的解决,此处先标记一下,以表敬意~~~

Zookeeper
Web note ad 1