手上有一个消费Kafka的服务，这个服务每隔一段时间使用SimpleConsumer从kafka集群获取数据。Kafka的版本是0.8.21。今天这个服务一直在报错：SocketTimeoutException。异常信息如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
2018-12-22 15:18:32 INFO SimpleConsumer:68 - Reconnect due to socket error: java.net.SocketTimeoutException 2018-12-22 15:19:32 INFO SimpleConsumer:68 - Reconnect due to socket error: java.net.SocketTimeoutException java.net.SocketTimeoutException at sun.nio.ch.SocketAdaptor$SocketInputStream.read(SocketAdaptor.java:211) at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) at java.nio.channels.Channels$ReadableByteChannelImpl.read(Channels.java:385) at kafka.utils.Utils$.read(Utils.scala:380) at kafka.network.BoundedByteBufferReceive.readFrom(BoundedByteBufferReceive.scala:54) at kafka.network.Receive$class.readCompletely(Transmission.scala:56) at kafka.network.BoundedByteBufferReceive.readCompletely(BoundedByteBufferReceive.scala:29) at kafka.network.BlockingChannel.receive(BlockingChannel.scala:111) at kafka.consumer.SimpleConsumer.liftedTree1$1(SimpleConsumer.scala:79) at kafka.consumer.SimpleConsumer.kafka$consumer$SimpleConsumer$$sendRequest(SimpleConsumer.scala:68) at kafka.consumer.SimpleConsumer.getOffsetsBefore(SimpleConsumer.scala:127) |
从异常信息上来看是网络连接超时。翻看了一下任务的运行日志发现是在连接Kafka集群的k3节点时出的错。
尝试telnet连接k3节点的broker是可以的。这样子还报错就比较奇怪了。
使用glances查看了一下消费节点的本地运行环境，发现各项指标也都挺正常的。
登录到k3节点，查看kafka的运行日志也能够看到消费节点的连接记录：
|
1 2 3 4 5 |
[2018-12-21 21:00:47,531] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor) [2018-12-21 21:00:50,189] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor) [2018-12-21 21:00:58,296] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor) [2018-12-21 21:00:59,007] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor) [2018-12-21 21:01:00,782] INFO Closing socket connection to /xxx.xx.xx.xx. (kafka.network.Processor) |
查看了一下使用high-level consumer的其他服务也是正常的。
百思不得其解。但是问题还得解决，随手查看了一下k3节点的句柄数，发现一个进程的句柄数高得有点儿离谱哎：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
[zhyea@k3]$ lsof|awk '{print $2}'|sort|uniq -c|sort -nr|more 2776803 53466 280 15671 256 35292 224 13903 176 14305 172 21177 64 15692 44 12061 32 21191 24 2648 24 21135 20 12073 18 190059 16 14453 16 13872 14 188621 |
k3节点每个进程可以打开的最大句柄数：
|
1 2 3 4 |
[zhyea@k3]$ cat /proc/sys/fs/file-max 3265156 [zhyea@k3]$ ulimit -n 3265156 |
53466就是k3节点上的kafka broker进程：
|
1 2 3 |
[zhyea@k3]$ jps -l 53466 kafka.Kafka 190100 sun.tools.jps.Jps |
此时有必要看下这个进程的网络连接了：
|
1 |
netstat -apn | grep 53466 |
发现有大量的CLOSE_WAIT和TIME_WAIT连接：
|
1 2 3 4 5 |
tcp 1 0 k3:9092 j0:51436 CLOSE_WAIT 53466/java tcp 1 0 k3:9092 j0:51436 CLOSE_WAIT 53466/java tcp 1 0 k3:9092 j0:51436 CLOSE_WAIT 53466/java tcp 1 0 k3:9092 j0:51436 CLOSE_WAIT 53466/java tcp 1 0 k3:9092 j0:51436 CLOSE_WAIT 53466/java |
统计了下CLOSE_WAIT和TIME_WAIT连接的数量，好像有点儿多：
|
1 2 3 4 5 6 7 8 |
[zhyea@k3]$ netstat -apn | wc -l 12399 [zhyea@k3]$ netstat -apn | grep CLOSE_WAIT | wc -l 8562 [zhyea@k3]$ netstat -apn | grep CLOSE_WAIT | grep j0 | wc -l 8554 [zhyea@k3]$ netstat -apn | grep TIME_WAIT | wc -l 1022 |
可以看出来所有连接中CLOSE_WAIT的记录占了绝大部分，和CLOSE_WAIT相关的连接又多是在j0节点上。
到j0节点查找和端口51436相关的进程，发现是一个kafka-manager服务。不是生产服务，直接关掉了事。
回到k3节点，重启该节点的broker。再进行测试，异常消失。持续观察几天，kafka的连接数是正常的，说明问题已经得到修复。
##########
发表评论