CDH5.12.0-HiveServer2-java.net.SocketTimeoutException: Read timed out

数据探险家

已于 2022-12-06 20:44:50 修改

阅读量1.6w

点赞数 30

CC 4.0 BY-SA版权

分类专栏： hadoop 文章标签： hive hadoop cdh 大数据

于 2018-12-14 21:03:45 首次发布

本文链接：https://blog.youkuaiyun.com/xin_jmail/article/details/85004967

hadoop 专栏收录该内容

4 篇文章

订阅专栏

解决HiveServer2 SocketTimeoutException问题，通过调整参数和升级CDH版本，优化HiveServer2与MetaStore通信，减少作业失败率。

一. 问题背景

基于CDH构建离线数仓，在通过JDBC向HiveServer2提交作业时出现java.net.SocketTimeoutException: Read timed out 错误，导致大批量的作业失败，不能按时产生数据，已严重影响到业务运行。

二. 集群环境

CDH-5.12.0
Hive-1.1.0

三. 错误日志

提交作业客户端报的错误日志如下:

java.sql.SQLException: org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out
	at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:263)
	at org.apache.hive.jdbc.HiveStatement.executeUpdate(HiveStatement.java:407)
	at com.dtwave.dipper.dubhe.node.executor.runner.impl.Hive2TaskRunner.doRun(Hive2TaskRunner.java:229)
	at com.dtwave.dipper.dubhe.node.executor.runner.BasicTaskRunner.execute(BasicTaskRunner.java:88)
	at com.dtwave.dipper.dubhe.node.executor.TaskExecutor.run(TaskExecutor.java:32)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out
	at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:129)
	at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
	at org.apache.thrift.transport.TSaslTransport.readLength(TSaslTransport.java:376)
	at org.apache.thrift.transport.TSaslTransport.readFrame(TSaslTransport.java:453)
	at org.apache.thrift.transport.TSaslTransport.read(TSaslTransport.java:435)
	at org.apache.thrift.transport.TSaslClientTransport.read(TSaslClientTransport.java:37)
	at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
	at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429)
	at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318)
	at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219)
	at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77)
	at org.apache.hive.service.cli.thrift.TCLIService$Client.recv_ExecuteStatement(TCLIService.java:225)
	at org.apache.hive.service.cli.thrift.TCLIService$Client.ExecuteStatement(TCLIService.java:212)
	at sun.reflect.GeneratedMethodAccessor104.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.hive.jdbc.HiveConnection$SynchronizedHandler.invoke(HiveConnection.java:1309)
	at com.sun.proxy.$Proxy86.ExecuteStatement(Unknown Source)
	at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:254)
	... 9 more
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
	at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)
	... 27 more

但是HiveServer2及MetaStore服务端的日志里并没有任何错误提示，导致定位不到出错原因。然后就开始了漫长的解决问题之路，这一走就是近20天。

四. 错误周期

出错后，重跑作业时95%概率不会再出现，但有时还是报相同错误，多尝试几次后，错误又没有了。
重启HiveServer2后，大概7-9天内不再出现，但超过7-9天以后，又开始出错。

结论: 此错误具有偶发性并带有一定周期的，我们技术同学观察此错误前后长达2个多月。

五. 第一次尝试解决

时间范围: 2018年11月26日-2018年11月30日

由于是socket timeout问题，因此把目光放在服务端上，开始排查HiveServer2的问题。由于HiveServer2日志里没有任何错误，因此开始摸索。

在客户端telnet HiveServer2进程，正常。
用jmap 查看堆内存信息，正常。
用jstat 查看进程GC信息，正常。
用netstat 查看连接情况，正常。

上述方法尝试完成后，一切正常，开始查看Hive源代码，几个小时过去了，还是没有发现任何异常，开始陷入思考中…

时间来到第二天，早上11点13分运行作业又出现socket timeout 问题，碰巧在CDH管理界面上看到Hive MetaStore的异常情况, 如下图:
在这里插入图片描述

因为HiveServer2执行任务的时候会调用MetaStore获取元数据信息，执行作业的时候刚好MetaStore挂了，感觉找到问题原因了，内心里有点小欢喜。于是乎开始把阵地转移到MetaStore中…

经过排查，发现MetaStore内存只有2G，最近还发生2次Full GC。而且这个时候在网上找到相关博客报表使用hive数据源报java.net.SocketTimeoutException: Read timed out、
java.net.SocketTimeoutException: Read timed out，前者内容如下:
在这里插入图片描述
认定原因是: HiveServer2和MetaStore通讯时，因为MetaStore发生Full GC或者hive.metastor.client.socket.timeout设置时间过短(配置的是300)，于是开始修复MetaStore。
由于客户的MetaStore是单点，每天HiveServer2、Impala、Spark作业都会去连接，而且部署MetaStore的机器上还有很多其他Hadoop相关服务。于是给客户三条修复建议:

增加hive.metastore.client.socket.timeout的值，目前是300。建议改为1000
增加hive metastore的最大内存。
把hive metastore 部署成多个，避免现在的单点故障。

经过上述三个操作后，HiveServer2和MetaStore都被重启了。

上述修复完成后，就开始了数绵羊的日子:
1天、2天、3天…都没有问题。

就这样到了12月10号，终于熬过了10天(以前是7-9天)，以为问题彻底解决了，心里暗暗舒了一口气…

但是12月11号早上，收到客户运维同学发来的消息:
在这里插入图片描述

问题复现，第一次解决尝试失败，又开始第二次尝试解决…

六. 第二次尝试解决

时间范围: 2018年12月12日-2018年12月14日

由于错误周期性复现，这个时候寻求运维同学的帮助，两个人在CDH管理界面上苦苦查看HiveServer2的每个指标，终于功夫不负有心人，找到了一个异常的、周期性的指标！
在这里插入图片描述

每间隔7天多，发现JVM daemon线程都出现一次波峰，然后值降到0。和客户的运维同学确认后，这是由于在这几天进行了重启操作。最终得到分析结果:每次重启后，HiveServer2的deamon thread 就一直逐天增加, 2k、4k…一直到10k多，最终运行作业就会出现socket timeout问题。

于是第一时间用jstack开始查看HiveServer2内的线程信息:
在这里插入图片描述
统计后居然发现有6481个线程处于BLOCKED状态，大惊!!!
分析:
HiveServer的内存配置的是4G，假设每个线程的栈的大小是1MB，理论上最多能创建4096个线程。因此怀疑是进程里线程数过多，导致服务越来越慢，对一些作业响应出现问题，导致客户端出现socket timeout问题。

同时开启Google模式，找到CDH官网一篇文章HiveServer2-has-more-than-10K-waiting-daemon-threads-named。文章内容的核心点如下面两张图:
在这里插入图片描述

线程增长曲线、堆栈调用关系跟我们遇到的错误一模一样，此时理论上定位到了错误原因。

PS: 我在客户CDH及公司内部CDH的服务器上jstack的结果都是没有线程名(自己本地的Apache社区是有线程名的)，只有线程ID，例如: Thread 3667。博客中的截图是有线程名的，例如: “Get-Input-Paths-1” 。因此这一点不是100%和博客吻合，看此博客的哪位高手如有其它方法，请留言告知下，多谢!

在博客下面，有人提到这是HiveServer2的一个BUG: HIVE-16949
在这里插入图片描述

打开 https://issues.apache.org/jira/browse/HIVE-16949，内容如下：
在这里插入图片描述

这个BUG是因为作业完成后没有关闭线程池，调用pool.shutdown()操作。此BUG是在HIVE3.0.0才修复的，然后我开始下载hive-1.1.0-cdh5.12.0源代码，计划把HIVE-16949.1.patch补到hive源代码中，然后重新编译打包。
但是…
在这里插入图片描述
没成功，我们的版本是1.1.0和3.0修复的这个补丁差异太大，尝试多次后，熬到凌晨2点多发现代码还是没法合并进来(哪位高手如有方法，请留言告知下，多谢!)。于是开始尝试其他方法…

隔天，幸好，在CDH官网上找到此BUG的描述，如下:
在这里插入图片描述

这个BUG影响的CDH版本是5.11.0, 5.11.1, 5.11.2, 5.12.0, 5.12.1，很不幸我们刚好是5.12.0。文中给出两种办法:

升级CDH，5.12.2、5.13.0 and higher
修改参数 hive.exec.input.listing.max.threads=1

方法二经过测试后，线程数确实不增加，但是任务的速度减慢很多，原来2分钟的作业改后需要5分钟，因此很可能导致晚上的数仓作业跑不完。因此后续计划采用方法一。

七. 验证

目前暂时采用的是上述方法2，今晚会跑大量作业，然后等明天早上观察HiveServer2的Thread数目。

期待明天结果…
同时还要验证7-9天后不再会周期性出现socked timeout问题。

八. 总结

对于这种周期的偶发性错误排查一定要彻底、要全面。
例如在第一次尝试解决中，用netstat、jmap、jstat分别查看了连接数、堆内存、GC等信息，唯独忘记了用jstack查看，结果问题就出现在了大量线程处于BLOCKED中。
商业公司不建议用Apache 社区原生的，因为监控、运维基本没有，对于这种没有报错日志的BUG基本无处下手。

九. 致谢

感谢客户积极配合我们解决错误，以及对数澜的耐心；
感谢运维同学安邦的帮忙；
感谢开发同学项栋、帅豪 2个多月熬夜人工修复客户的作业。
感谢PM、商务积极的跟客户沟通、协调，给技术缓冲解决问题的时间。

感想:
数栖平台目前已支持HDP、CDH、TDH、FusionInsight、腾讯EMR，但未来肯定还会遇到底层平台各种问题，导致客户业务出错。过程中无论客户对数澜-数栖平台的稳定性产生怀疑、甚至是不信任，我们都不会做任何争辩，只会踏踏实实的用行动去协助、帮助客户解决问题，一起打造起企业的数据中台！