socket连接过多导致dead node

发表于 2015-06-10

近日碰到的一个问题，某些用户的程序耗尽了一些节点的socket资源导致dead node。

症状

我们有用zabbix监控NN metrics。
17点30左右收到报警，集群出现deadnode，但DN进程还在。
查看deadnode的日志：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
2015-06-05 16:47:00,663 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: IOException in offerService
java.net.BindException: Problem binding to [hadoop72.photo.163.org/10.160.173.13:0] java.net.BindException: Address already in use; For more details see: http://wiki.apache.org/hadoop/BindException
at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:719)
at org.apache.hadoop.ipc.Client.call(Client.java:1351)
at org.apache.hadoop.ipc.Client.call(Client.java:1300)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
at com.sun.proxy.$Proxy9.sendHeartbeat(Unknown Source)
at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:186)
at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:102)
at com.sun.proxy.$Proxy9.sendHeartbeat(Unknown Source)
at org.apache.hadoop.hdfs.protocolPB.DatanodeProtocolClientSideTranslatorPB.sendHeartbeat(DatanodeProtocolClientSideTranslatorPB.java:167)
at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.sendHeartBeat(BPServiceActor.java:445)
at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:525)
at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:676)
at java.lang.Thread.run(Thread.java:662)

这个错误的意思是DN无法向NN发送心跳。
NN超过一定时间没有收到心跳，就会将DN标记为dead。这个超时机制见这里第8条。

但为什么无法发送心跳？检查网络、系统、交换机，都没有任何异常。
而且在排查过程中，dead node不断增多，最多时达到6个，已经开始出现missing block。部分用户的任务会失败。

仔细看上面的异常，发现DN进程试图绑定到0号端口。根据给出的wiki链接，0号端口是让系统自动分配一个空闲的端口。
而绑定失败，说明系统已经没有空闲的端口可以分配了。怀疑是网络连接过多。

netstat -anp | grep 1004（1004是DN的RPC端口）看下，发现了8w+的TCP CLOSE_WAIT连接。这8w+里有进来的连接也有出去的连接，没细分。
本来-p参数应该能看到进程id的，就能统计到底哪个进程开了这么多socket。但netstat命令我没有sudo权限，只能看到自己的进程，真是蛋疼。

尝试重启DN进程，没有效果，还是deadnode。
尝试重启NM进程，连接数立刻就正常了。deadnode也消失了。
于是怀疑是某个用户的container进程的问题。

在RM的web界面上查看正在运行的job，根据启动时间排除下，只有一个job符合条件。
查看所有变为dead node的DN，确实都有这个job的reduce在上面跑。
尝试杀掉一个reduce attempt，连接数立刻下降。
可以确定就是这个job的问题。

杀掉这个job，所有DN恢复正常。

另外，在这个过程中，出现了一次NN切换，具体原因不明，不知是否和这次事件有关。好在没有造成什么影响。

分析

事后跟用户沟通，他的代码大概是这么写的：

1
2
3
4
5
6
public void reduce(Text key, Iterable<LongWritable> values,
				Context context) {
	FileSystem fs=FileSystem.get(context.getConfiguration());
	InputStream in=fs.open(new Path("some_file"));
	// 将数据读到一个map中
}

也就是说，每次reduce都会读取hdfs上一个文件。他的本意是做类似于join的事情，这个读取数据的逻辑应该放到setup()方法里的，但却放到了reduce()方法。
而且他最后没有调用in.close()方法，导致打开的socket链接不会释放。

这个问题很容易重现，我先写一段单机的代码试下：

1
2
3
4
5
6
7
8
9
10
public static void main(String[] args) throws IOException,
			InterruptedException {
		Configuration conf = new Configuration();
		FileSystem fs = FileSystem.get(conf);
		// 随便读取hdfs上一个文件
		InputStream in = fs.open(new Path("/user/mine/jxy/yarn.cmd"));
		byte[] buffer = new byte[1024];
		in.read(buffer);
		Thread.sleep(Integer.MAX_VALUE);
	}

运行后，用netstat查看：

1
2
3
4
5
6
7
8
hadoop@inspur116:~$ netstat -anp | grep 1004
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 0.0.0.0:1004            0.0.0.0:*               LISTEN      -               
tcp        1      0 10.160.128.191:21072    10.160.128.193:1004     CLOSE_WAIT  27744/java      
tcp        1      0 10.160.128.191:21075    10.160.128.193:1004     CLOSE_WAIT  27841/java      
tcp        1      0 10.160.128.191:21069    10.160.128.193:1004     CLOSE_WAIT  25892/java      
unix  2      [ ACC ]     STREAM     LISTENING     3620589941 -                   /var/run/hadoop-hdfs/dn.1004

因为我启动了3个进程，所以有3个CLOSE_WAIT的连接。dn.1004那个是用于short-circuit read的unix domain socket，而不是我们通常说的network socket，忽略。
可见如果不调用in.close()确实会造成很多CLOSE_WAIT的连接。

如果在一个进程中循环调用那段代码：

1
2
3
4
5
6
7
8
9
10
11
12
hadoop@inspur116:~$ netstat -anp | grep 1004
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 0.0.0.0:1004            0.0.0.0:*               LISTEN      -               
tcp        1      0 10.160.128.191:21137    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21143    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21182    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21178    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21139    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21141    10.160.128.193:1004     CLOSE_WAIT  31153/java      
tcp        1      0 10.160.128.191:21180    10.160.128.193:1004     CLOSE_WAIT  31153/java      
unix  2      [ ACC ]     STREAM     LISTENING     3620589941 -                   /var/run/hadoop-hdfs/dn.1004

如果登陆到10.160.128.193这台DN上去看：

1
2
3
4
5
6
hadoop@inspur122:~$ netstat -anp | grep 1004
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp        0      0 0.0.0.0:1004            0.0.0.0:*               LISTEN      -               
tcp        0      0 10.160.128.193:1004     10.160.128.191:21184    FIN_WAIT2   -               
unix  2      [ ACC ]     STREAM     LISTENING     69412045 -                   /var/run/hadoop-hdfs/dn.1004

客户端出现CLOSE_WAIT我可以理解，因为没有主动关闭。就算接到了服务端的FIN包，虽然会ACK，但不会返还一个FIN包。
服务端出现FIN_WAIT2不是很明白，而且和客户端的CLOSE_WAIT不是一一对应的。大概是因为服务端主动关闭socket，等待客户端返还一个FIN包，一直没有回应，就超时了，直接关闭了吧。我计算机网络学的比较烂。。。
google找到了一个参数tcp_fin_timeout：

1
2
3
# 这个目录下还有很多关于网络的参数
hadoop@inspur122:~$ cat /proc/sys/net/ipv4/tcp_fin_timeout
60

就是说一个FIN_WAIT2的连接超过60秒会直接关掉。大概吧。

接下来把这段代码写到wordcount里，每次map都读这个文件，而且不关闭。
提交job到测试集群，可以观察到连接数暴涨：

1
2
3
4
5
6
7
8
hadoop@inspur131:~$ netstat -anp | grep 1004 | wc -l
53539
hadoop@inspur131:~$ netstat -anp | grep 1004 | wc -l
89481
hadoop@inspur131:~$ netstat -anp | grep 1004 | wc -l
119334
hadoop@inspur131:~$ netstat -anp | grep 1004 | wc -l
173461

过一段时间后出现dead node。跟线上集群之前的症状一样。
查看map的日志可以看到很多dead node异常。

但观察到一个有意思的事。/user/mine/jxy/yarn.cmd这个文件只有一个block，位于3台机器上。这3台机器会比其他节点先挂（挂指的是不能向NN发心跳）。
其他机器上挂掉时都是大量CLOSE_WAIT的连接。但这3台机器挂掉时还有大量的FIN_WAIT2连接。
可以认为，普通节点，socket资源都耗费在出去的连接上了。而这3台机器还有一些资源耗费在进来的连接上。

而且这3台机器也不是一起挂掉的，而是按一个固定的顺序。
因为client读取hdfs数据时，是从NN处获取一个DN列表（在我们的集群上就是3个），然后依次尝试。如果一个DN不通就尝试下一个。
猜测NN返回的列表顺序是固定的（不考虑本地性的情况下）。但没看代码验证过。

结论：InputStream必须close啊。。。

关于socket

wiki讲的很清楚：一个socket=IP+端口+协议。
所以TCP的127.0.0.1:80和UDP的127.0.0.1:80是两个不同的socket，不会互相影响。
但我们所说的socket一般默认都是指TCP。

关于TCP连接状态

关于TCP socket的状态，最权威的当然是RFC。但一般人看不了这个。还是翻翻计算机网络的教材吧。。。好在我还留着。
关于CLOSE_WAIT，这篇文章讲的还算清楚。

之前说过FIN_WAIT2会在一分钟内超时，其实CLOSE_WAIT放着不管也会超时并释放的，见这个文章。但默认超时是2个小时，足够把集群搞挂了。。。
另外这个超时机制不是针对CLOSE_WAIT的，对所有TCP连接都生效。

hbase regionserver

其实处理上次hbase的事故时，我就观察到了一些regionserver有大量的CLOSE_WAIT连接。
当时虽然觉得有点奇怪，但没有深究。
借这次的机会看了下。本来以为是bug，相关JIRA：HDFS-5671、HBASE-9393、HBASE-11833

但后来发现CLOSE_WAIT的连接都是ipv6的：

1
2
3
4
5
tcp6       1      0 10.160.128.139:21508    10.160.128.139:1004     CLOSE_WAIT  16987/java      
tcp6       1      0 10.160.128.139:64814    10.160.128.139:1004     CLOSE_WAIT  16987/java      
tcp6       1      0 10.160.128.139:16763    10.160.128.139:1004     CLOSE_WAIT  16987/java      
tcp6       1      0 10.160.128.139:34750    10.160.128.139:1004     CLOSE_WAIT  16987/java      
tcp6       1      0 10.160.128.139:30541    10.160.128.139:1004     CLOSE_WAIT  16987/java

看来启动JVM时没加上-Djava.net.preferIPv4Stack=true参数，找时间重启下regionserver再观察下。

遗留的问题

NN为何切换？

原因不明。。不知道当时NN的连接数状况。
如果确实是这个job导致的，为何切换后的NN一直很稳定。
先认为是个偶然事件吧。

调查NN切换的过程中倒是发现了checkpoint的另一个bug：HDFS-6184。相关分析见这篇文章最后。

为何只有少量dead node？

按理说，这个job能把整个集群搞挂的。为何最多时只挂了6个节点？
是因为发现比较及时么？
还是说用户数据倾斜比较严重，某些reduce数据量小，所以触发reduce()方法的次数也少？

netstat -anp为何有重复记录？

我之前说netstat -anp | grep 1004 | wc -l有8w+记录。但端口号最大就是65535啊，为啥会有这么多连接。
其实netstat -anp输出的记录里，有些是重复的，不知为何。如果去重后，就5w左右。

#hadoop #hdfs #socket #运维
hadoop与windows
Linux豆知识