DataXceiver本地读异常bug说明(HDFS-11802)

现象描述

用户在读取文件的时候报三台DN都无法取得该文件对应的block,经过fsck检查后没有发现该文件有丢块现象,到对应的dn上去查看日志,发现三台机器已经都处于不可读状态,报错为

2015-11-25 00:01:55,999 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: 10.39.5.160:50010:DataXceiverServer:
java.io.IOException: Xceiver count 4097 exceeds the limit of concurrent xcievers: 4096
    at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:137)
    at java.lang.Thread.run(Thread.java:745)

很明显,这是超过了dataxceiver设置的最大的线程数4096,正常情况下是不可能超过的,所以说明dn有线程泄露的bug或者其它问题。
再检查日志,发现了以下的日志

Exception in thread "Thread-19" java.lang.IllegalStateException: failed to remove c53ce04928d1baa854f5dc1bfc8d565b
    at com.google.common.base.Preconditions.checkState(Preconditions.java:145)
    at org.apache.hadoop.hdfs.server.datanode.ShortCircuitRegistry.removeShm(ShortCircuitRegistry.java:115)
    at org.apache.hadoop.hdfs.server.datanode.ShortCircuitRegistry$RegisteredShm.handle(ShortCircuitRegistry.java:102)
    at org.apache.hadoop.net.unix.DomainSocketWatcher.sendCallback(DomainSocketWatcher.java:371)
    at org.apache.hadoop.net.unix.DomainSocketWatcher.access$1000(DomainSocketWatcher.java:52)
    at org.apache.hadoop.net.unix.DomainSocketWatcher$1.run(DomainSocketWatcher.java:511)
    at java.lang.Thread.run(Thread.java:745)

看到这个日志以后就大概知道了原因,是由于DomainSocketWatcher线程异常退出,导致本地读线程没有回收机制,占满了所有的dataxceiver slot导致的。

问题原因

DomainSocketWatcher线程负责对本地读线程建立的socket进行一些处理和清理等。出问题的代码为

<code>
      try {
        while (true) {
              doSomecleanup.......
        }
      } catch (InterruptedException e) {
        LOG.info(toString() + " terminating on InterruptedException");
      } catch (IOException e) {
        LOG.error(toString() + " terminating on IOException", e);
      } finally {
        lock.lock();
        try {
          kick(); // allow the handler for notificationSockets[0] to read a byte
          Iterator<Entry> iter = entries.values().iterator();
          while(iter.hasNext()) {
            sendCallback("close", iter, fdSet);
          }
          entries.clear();
          fdSet.close();
        } finally {
          lock.unlock();
        }
      }
</code>

正常情况下代码不会走入到finally,而是一直在while中loop。而报出的异常则是remove一个共享内存对象的时候失败,而导致的运行时异常。
经过jira查询和我们集群中机器日志查看,发现原因为在于Client向DataNode申请本地读时候,DataNode建立共享内存对象以及File Descriptor出现异常,导致分配失败,日志为

2015-11-06 04:52:41,080 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: cliID: DFSClient_attempt_1435099124107_5925361_m_000028_0_1777694543_1, src: 127.0.0.1, dest: 127.0.0.1, op: REQUEST_SHORT_CIRCUIT_SHM, shmId: n/a, srvID: 01f352c6-4e63-4158-8ead-3e8146103b6f, success: false

而在DataXceiver的requestShortCircuitShm代码中,如果失败则close连接

      if ((!success) && (peer == null)) {
        // If we failed to pass the shared memory segment to the client,
        // close the UNIX domain socket now.  This will trigger the 
        // DomainSocketWatcher callback, cleaning up the segment.
        IOUtils.cleanup(null, sock);
      }

但是,所有close操作都是通过回调DomainSocketWatcher来做的,这样,当DomainSocketWatcher再次close的时候内存中的共享内存对象由于已经close被释放,而报runtimeerror,这样DomainSocketWatcher线程异常退出,本地读没有清理线程,慢慢占满了slot,最后导致了DataNode不可用。

解决方法

DataXceiver不负责close连接,而只是负责将与client连接shutdown,使client能够快速反应读异常,同时增加更多的catch,如果后续还有异常能够找到原因。