前言

大家好，我是明哥！

大数据作业异常的排查，往往是个比较棘手的问题。这一方便是因为分布式作业的执行往往需要跨多个网络节点进行通信比较复杂，另一方面也是因为涉及底层框架多（spark, hive, flink, hdfs, hbase, kafka, yarn，zookeeper 等等），排查人员对这些组件各自的运行机制以及组件之间如何交互配合完成最终作业的机制不甚明了，再加上整个作业的执行涉及到各种日志且这些日志散落于集群多个节点多个目录，如何根据时间线跟踪排查各处日志，还原作业执行发生异常时底层究竟发生了什么原因是什么，相比传统的作业异常的排查确实更加困难些。

但正所谓会者不难难者不会，只要大家日积月累勤修内功掌握各个组件的底层原理和运行机制，再加上勤学苦练多多实操查看异常时的各处日志并定期归纳整理，相信大家排查相关问题会越来越得心顺手，成为一名合格的“排坑”专家！在此分享一次真实项目中hive sql作业的异常排查经验，供大家学习参考。

问题现象

某大数据业务系统在每日日终清算环节，会采集上游业务系统rdbms中的业务数据到Hive中，进行hive sql离线计算，然后推送结果数据到下游系统的rdbms中。这些数据采集和推送作业，偶尔会执行失败，此时业务端会收到如下SocketTimeoutException异常：

java.sql.SQLException:org.apache.thrift.transport.TTransportException:java.net.SocketTimeoutException: Read timed out  atorg.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:262)

有的作业还会有个被抑制的异常：Suppressed:java.sql.SQLException: Error while cleaning up the server resources atorg.apache.hive.jdbc.HiveConnection.close(HiveConnection.java:595) Caused by:org.apache.thrift.TApplicationException: CloseSession failed: out of sequenceresponse

 问题背景

该大数据业务系统中的数据采集和数据推送，都是通过我司研发中心的datago组件来进行的（datago底层是开源的datax，datago在易用性上做了封装，会根据datago配置文件生成datax作业的配置文件）。针对数据采集作业， datago首先会通过jdbc连接到hiveserver执行sql拿到目标hive表的元数据信息（hdfs文件路径，表字段，表格式等信息），然后执文件清理和分区创建等工作，然后会通过rdbmsreader插件读取上游oracle数据，并通过Hdfswriter插件直接写数据到目标表目标分区在hdfs上对应的目录下；针对数据推送作业中使用rdbmsreader插件的推送作业，其机制是datax先建立到hive server的jdbc连接，然后提交sql给hiveserver，hive serverza在执行完毕sql后会返回结果数据给客户端datax，datax再通过rdbmswriter推送结果数据到下游Oracle。观察发现以上SocketTimeoutExceptions是偶发现象，在并发提交的作业较多时（四五十个左右）出现的可能性更大，且跟表的数据量关系不大，部分小表甚至空表也会出现以上异常。

 问题分析

首先查看各处的日志，包括业务系统日志，数据同步中间件datago的日志，datago底层实际的执行引擎datax的日志，以及大数据hive server的日志，hive metastore的日志，hdfs namenode的日志，按照时间线梳理各处日志还原底层究竟发生了什么，结合查阅datago，datax和Hive的源码，分析得到如下结论：

1. 首次以上异常都是提交sql成功后，等待sql执行结果的过程中发生的SocketTimeoutException，而不是建立JDBC连接时的连接超时，所以跟hive server允许的最大连接数应该没有关系。

2. 针对数据采集作业进行分析：这部分作业底层执行的sql只有desc extended tablexx 和alter table xxx addpartition xxx两种，都是很轻量级的ddl sql，在hive server中即可执行，不会生成和分发spark/mr任务；观察datago日志发现sql都已经提交，观察hive server日志发现sql已经收到了，观察hive metastore日志发现对应的sql也收到并执行了，观察hdfs namenode日志没有相关信息，但通过hdfs dfs –ls 查看发现对应的目录已经创建成功了。对应到异常日志信息，结合查看datago源码和hive源码，发现hive的jdbc客户端（HiveStatement）提交sql给hiveserver执行后，会轮询等待sql执行完成，然后jdbc客户端（HiveStatement）中的 thrift client会通过thrift协议读取hive server/thrift server的sql执行结果，在读取时因为超过了TSocket 使用的 socket timeout值而抛出了异常。事实上由于datago代码中建立 jdbc connection时使用了java的try-with-resource语法，所以timeout异常时自动执行了connection.close，此时又由于thfirt的单个client不能处理并发请求，所以排除了被抑制的异常org.apache.thrift.TApplicationException:CloseSession failed: out of sequence。

3. 针对使用rdbms插件的数据推送作业进行分析：其执行机制是，datax首先建立到hive server 的jdbc连接，然后提交sql 给hiveserver，而hive server在后台会解析这些sql生成并提交分布式的mr/spark作业，此时hive的jdbc客户端（HiveStatement）在提交sql给hive server后，会轮询等待sql执行完毕 – 即等待这些mr/spark作业执行完毕，然后jdbc客户端（HiveStatement）中的 thrift client会通过thrift协议从hive server/thrift server单点读取sql执行结果，在读取时因为超过了TSocket 使用的socket timeout值而抛出了异常。

4. 所以以上两类作业的SocketTimeoutExceptions，其底层原因都是jdbc客户端的HiveStatement在轮询等待sql执行完毕后（其实轮询查询sql是否已经执行完毕，在底层使用的也是thrift协议）， 在通过thrift client读取hive server（即thrift server）中的sql结果数据时，因为超过了TSocket 使用的socket timeout的值而抛出了异常。

  问题解决方案

知道了问题原因，问题的解决方法就相对清晰了。可以从以下四个方面进行调整以彻底解决上述问题：

1. 一是业务代码从使用方式上进行调整，减小对hive server单点的压力：针对我们的场景，可以把datago数据推送作业切换使用hdfsreader插件而不再是rdbmsreader插件，此时需要推送的数据就是通过直接读取hdfs上的文件获取， 而不再是发送sql给hive server，由hive server解析sql生成并提交mr/spark作业，待mr/spark作业执行完毕后，客户端再从hive server单点获取结果数据。通过该项调整，该系统作业发生socketTimeout异常的概率已经大大减小。

2. 二是优化Hive server的性能：这点包括提升集群硬件配置和hive server参数优化两个方面。由于该环境中物理节点内存为256G，而hive server进程的堆空间 目前原来配置的是最小2G最大8G，所以初步调整最大堆空间大小到16G，后续调整后观察下效果，必要时再做进一步调整，甚至调整gc算法参数。（我们的connetion并发数不大，在60左右）

3. 三是配置调整HiveStatement底层thrift客户端的TSocket 实际使用的socket timeout的值：这点是目前hive做的不够完善的地方，因为thrift socket read 的read timeout 的值，目前使用的就是hive jdbc的connect timeout的值，而hive目前并不像mysql那样在支持在url中配jdbc的connect timeout，所以目前只能通过DriverManager.setloginTimeout(int seconds)方法进行全局配置（对所有jdbc连接生效）。

4. 四是在业务代码中加上同步任务的重试机制：出于业务代码稳定性和减小人工介入运维成本的考虑，业务代码可以加上对同步任务的失败重试机制，并在失败重试时合理配置重试间隔和重试次数。

    相关技术背景知识

1.     需要了解jdbc中各种timeout配置项的工作机制，大家可以搜索“Understanding JDBC Internals & Timeout Configuration” 自行了解。概括来讲需要区分各种timeout，包括：os level socket timeout, jdbcdriver socket timeout (又分为connect/login是的socket timeout, query 是的socket timeout), 以及statement/query timeout 和 transactiontimeout。

2. 需要结合源码了解hive jdbc的实现：如org.apache.hive.jdbc.HiveConnection 中不支持配置networkTimeout, 该参数值固定为0，可参见方法setNetworkTimeout()；如org.apache.hive.jdbc.HiveStatement中不支持配置 queryTimeout, 该参数值固定为0，参见方法 setQueryTimeout()；如org.apache.hive.jdbc.HiveStatement中使用的thrift socket read 的readtimeout 的值，是在org.apache.hive.jdbc.HiveConnection 的 setupLoginTimeout() 方法中配置的，参见源码可见其获取的就是DriverManager.getLoginTimeout()；

附录：

hive timeout相关jira 可以参考:

https://issues.apache.org/jira/browse/HIVE-22196

https://issues.apache.org/jira/browse/HIVE-6679

https://issues.apache.org/jira/browse/HIVE-12371

hive各种参数说明可以参考：

https://cwiki.apache.org/confluence/display/Hive/Configuration+Properties

hive优化可以参考：

https://docs.cloudera.com/documentation/enterprise/latest/topics/admin_hive_tuning.html

欢迎大家关注同名微信公众号，后台留言加群交流！