Zookeeper的CancelledKeyException异常问题

矫情吗；* 2022-05-13 06:18 69阅读 0赞

项目中用到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][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，也可以接受，何况此处的我，别无选择~~~

转载：[https://www.jianshu.com/p/73eec030db86][https_www.jianshu.com_p_73eec030db86]

[https_issues.apache.org_jira_browse_ZOOKEEPER-1237]: https://link.jianshu.com?t=https://issues.apache.org/jira/browse/ZOOKEEPER-1237
[https_www.jianshu.com_p_73eec030db86]: https://www.jianshu.com/p/73eec030db86