写RCFile不停报的ArrayIndexOutOfBoundsException错误 

场景：使用flume＋自主开发的形式将数据按系统的要求写入hdfs中，并生成相应的索引
最近在一个试运行集群中经常发生数据无法入库情况，然后看了一下系统日志，发现日志在不停的抛出如下异常。

步骤1

登录及其的查看异常（不停歇的报此错）如下

1
2
3
4
java.lang.ArrayIndexOutOfBoundsException: 7107
   at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:76)
   at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:50)
   at java.io.DataOutputStream.writeInt(DataOutputStream.java:197)

首先，我看到此日志，我内心第一反应，这错真是奇葩，没想到定位和解决这个问题用了好几天。

步骤2

看到此异常后，我第一反应是得先找到第一个报错的地方并且查看的此报错的原因。然后我就开始看此处涉及到hdfs的代码，想看看为什么会报错。

1
2
3
4
5
6
7
public void sync() throws IOException {
	if (sync != null && lastSyncPos != out.getPos()) {
		out.writeInt(SYNC_ESCAPE); // mark the start of the sync
		out.write(sync); // write sync
		lastSyncPos = out.getPos(); // update lastSyncPos
	}
}

RCFile.java中如上代码，程序在out.writeInt就开始报错了，lastSyncPos无法的更新。但是在上层使用如下代码的判断的调用sync。

1
2
3
4
5
private void checkAndWriteSync() throws IOException {
	if (sync != null && out.getPos() >= lastSyncPos + SYNC_INTERVAL) {
		sync();
	}
}

好吧，这writeInt报错了，对于这个我真是醉了。

步骤3

发现了此处无法理解的地方后，我将重点转向了第一个报错的地方。因为他是不确定时间报错，我就开始启动程序后，时常的查看日志，终于在之后的某个早上，我在查看日志时，我发现了第一个报错的地方。然后在那上面看到了如下异常。

1
2
3
4
java.io.IOException: All datanodes ...:50010 are bad. Aborting...
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.setupPipelineForAppendOrRecovery(DFSOutputStream.java:1147)
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.processDatanodeError(DFSOutputStream.java:945)
    at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:496)

然后在日志中找第一个报次错的地方，还发现了其他的报错

1
2
3
4
5
6
7
[ShortCircuitCache_SlotReleaser] (org.apache.hadoop.hdfs.shortcircuit.ShortCircuitCache$SlotReleaser.run:215)  - ShortCircuitCache(0x3fbdc007): failed to release short-circuit shared memory slot Slot(slotIdx=1, shm=DfsClientShm(7bf35643718a2bf0a9d85884afb8f4f8)) by sending ReleaseShortCircuitAccessRequestProto to /var/run/hdfs-sockets/dn.  Closing shared memory segment.

java.net.ConnectException: connect(2) error: Connection refused when trying to connect to '/var/run/hdfs-sockets/dn'

29 七月 2016 10:14:17,390 WARN  [ShortCircuitCache_SlotReleaser] (org.apache.hadoop.hdfs.shortcircuit.DfsClientShmManager$EndpointShmManager.shutdown:380)  - EndpointShmManager(10.139.90.136:50010, parent=ShortCircuitShmManager(5c89577b)): error shutting down shm: got IOException calling shutdown(SHUT_RDWR)

java.nio.channels.ClosedChannelException

步骤4

看到这些日志后，我感觉在10:14一定发生了什么，于是我开始寻找datanode中相关时间点日志STARTUP_MSG: Starting DataNode这种datanode启动信息，我内心一万只草泥马飘过。
在此日志的上面我看到了诸如的的日志。

1
2
2016-07-29 10:14:12,374 INFO org.apache.hadoop.util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 4519ms
No GCs detected

然后就是

1
2016-07-29 10:14:36,720 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: STARTUP_MSG:

中间隔了三十秒。
从这种情况看感觉应该是datanode进程死了，然后又重启了。

步骤5

然后我就开始全力找为什么此datanode会挂。列出几点信息，这些信息是感觉有点头疼。

  1. supervisord.log的日志中有2016-07-29 10:14:16,820 INFO exited: 411-hdfs-DATANODE (terminated by SIGKILL; not expected)此时间正好在10:14:12到10:14:36之间。
  2. 之前无聊时看过datanode虚拟机参数，记得有这么个参数。-XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh
    我开始怀疑是不是我这个参数给datanode进程发了kill信号，然后又重新启动。在/var/log/messages中也没发现oom的异常。

步骤6

开始看killparent.sh脚本，发现在调用此脚本时会将一个字符串写入一个文件，但是我在系统中没有发现这个文件，然后我就有点懵逼了。然后我在此脚本中加了一行我自己的代码，等再看看会不会再出现这种情况。

步骤7

跟了一个周末后，发现killparent.sh的脚本没有调用。然后开始在晚上搜索，看了一些hdfs源码，可以确定的是flume的hdfs客户端和datanode之间的连接断了，然后导致datanode报超时错误，最后在flume中报读取流出错。

步骤8

然后开始了两天完全懵逼的时光，在网上看到说可能ulimit对进程的限制，然后就开始在的集群中查看lsof中flume和datanode的链接使用数量。监控了一晚上什么收获都没有，然后就放弃了。

步骤9

然后开始猜测是不是flume进程的某些原因，因为我在成个几次重启的过程中没有重启过datanode，而只重启了flume，但是重启了之后集群就可以开始加载了。然后又开始做尝试，同时看到看tailf过滤datanode日志中的error和warn信息和flume的出错日志。不停等，终于等到了出错，发现只有datanode报连接异常的时候才会导致flume出错，这时候就断定是flume和datanode之间的连接，突然想到可能是gc，想到之前的看过datanode没有full gc，那就可能是flume，看了flumegc日志，尼玛在出错时间点之前还真有一次400多秒的gc。我内心是崩溃的。

步骤10

明天开始尝试将timeout时间再延长，将超时时间设置为3600，跑了周末两天都没什么问题。

暂时告一段落

因为接下来要做的是调整gc参数。