庖丁解牛，复盘 HiveServer2 连接频繁卡顿问题
本文作者为中国移动云能力中心大数据团队软件开发工程师张步涛，文章针对 HiveServer2 连接频繁卡顿问题，使用基本的运维手段找出问题根因，并给出解决方案，供大家参考。
背景
首先交代一下集群环境，集群运行的主要是 Hive on Tez 作业，主要套件版本为：Apache Haoop 3.1.0，Apache Hive 3.1.0，Apache Tez 0.9.2。
运维同学反映 HS2（HiveServer2）连接频繁卡顿，偶发个别 HS2 节点连接数较高，初步定位是当前 HS2 负载均衡机制不够完善，部分 HS2 节点由于连接过多，导致新的客户端连接卡顿。运维同学的这种定位也算合理，因为线上 HS2 是通过 zookeeper 动态随机选择，虽然能够做到一定程度负载均衡，但是随机选择的算法有时会导致部分 HS2 节点连接数较多。
由于当前 HS2 的默认最大连接数由 hive.server2.thrift.max.worker.threads 控制，默认设置了 500，为了减少 HS2 节点连接过多导致负载较高问题，运维同学修改最大值为 120。但是参数改完问题依然没有解决，业务侧反馈有 HS2 节点连不上，但是通过 netstat 查看 HS2 端口连接数发现只有 16 个，HS2 进程也没有出现 full gc 的情况，从表象看 HS2 没有问题，根据过往经验，底层 HDFS 如果负载较高（比如 RPC 响应延迟）也会导致 HS2 连接异常，但是测试发现 HDFS 的指标都在正常范围。所以还是需要从 HS2 进程着手，寻找可疑点。
问题定位
确定 jstack 异常线程
遇到这种 java 进程卡顿问题，最直接的定位手段就是打印 jstack 堆栈信息，一般情况下关注 jstack 中的 BLOCKED 与 WAITING 线程信息，再结合服务端日志分析就能找出一些蛛丝马迹。果不其然，通过多次对 HS2 进程 jstack，发现 HS2 堆栈信息中有 119 个具有相同堆栈的 BLOCKED 状态的线程，如下：
仔细观察这些 BLOCKED 的线程，发现都在等待同一个锁资源 <0x00000003c09c2fb8> ，说明这把锁被某一个线程长时间持有，那么如何找到持有锁的这个线程？这里有个快捷的方法，直接在 jstack 文件中搜索 locked <0x00000003c09c2fb8>，找到持有锁的这个线程 Thread-629610：
这里找到了 119 个 BLOCKED 线程加上一个持锁的线程，这 120 个线程其实就是运维同学设置的 HS2 最大连接数 120 个，堆栈信息显示这 120 个线程在 HS2 服务端一直没有关闭成功，119 个线程一直在等待 Thread-629610 线程持有的锁，有了锁才能在服务端释放连接，显然 Thread-629610 线程在关闭连接的时候出现了异常，无法释放锁。
注意：这里 jstack 表明 HS2 的 120 个连接其实已经用完，而 netstat 查看的 HS2 连接只有 16 个并不能反映服务端真实连接情况。
既然找出了这些异常的连接线程，如何分析？一般情况下需要对 jstack 从下至上逐次分析，结合源代码以及日志信息找出问题根因。
分析线程同步锁
119 个 HS2 线程一直在 WAITING 等待锁，需要重点分析持有该锁的线程 Thread-629610，看这把锁用在哪里。我们线上版本是 Apache Hive 3.1.0，打开 Hive 3.1.0 代码，直接定位线程持锁的方法：
首先定位 org.apache.hive.service.cli.CLIService.closeSession 方法，第 241 行：
图 1 HS2 连接线程关闭调用处
继续点击进入 241 行的方法，进入 org.apache.hive.service.cli.session.SessionManager.closeSession 方法，注意观察 545 行的 synchronized 同步锁：
图 2 HS2 线程关闭方法体以及同步锁
这里可以看到 SessionManager 类中的 closeSession 方法增加了同步锁，任何 HS2 连接线程关闭的时候都需要在这里获取锁，然后才能释放连接。
这里为什么会在整个方法 closeSession 上加锁？正常来说 HS2 连接线程之间资源应该都是隔离的，这里做一个线程同步似乎有点多余。我们查看了这个方法的 git 更改记录，找到了这个方法加锁的变动社区 issue：https://issues.apache.org/jira/browse/HIVE-14296 。这个 jira 解决了一个当客户端没有正常关闭时，HS2 服务端日志不能正确统计 session 数量，通过方法加锁，保证 session 数量全局准确。但是这个加锁的方式太过粗粒度，因为方法中涉及 session 数量变动的只有 546 一行，即 HiveSession session = handleToSession.remove(sessionHandle);，方法中其他逻辑不需要同步。
既然这个加锁方法太过粗粒度，需要优化，我们首先来看 master 分支代码有没有优化这个代码，直接查阅 master 分支代码，发现这个代码已经被优化如图 3，见 jira：https://issues.apache.org/jira/browse/HIVE-22165：
图 3 Hive 最新代码优化后的线程同步锁
HIVE-22165 的优化思路和我们预想的一致，只把锁加到的 handleToSession.remove(sessionHandle)的代码处，这一行代码只是一个 Map 容器 remove 操作，不会有异常耗时，这样可以优化在 HS2 高并发连接、关闭 session 的时候，由一个 HS2 连接线程长时间持锁导致其他 HS2 线程无法释放的问题。
分析到这里，看起来只要根据 HIVE-22165 优化 Hive3.1.0 代码就能解决问题。实际情况如此吗？优化代码之后，HS2 连接之间不会在这里抢锁，一个 HS2 线程释放失败并不会 block 其他线程正常释放，如总 HS2 连接线程 120，有 119 个可以正常释放并被客户端重新连接，一般情况这种优化可以解决问题。但是极端情况下，可能 120 个线程都不能正常释放，那么用户还是会无法连接 HS2。所以我们需要继续分析堆栈信息，查看究竟是什么原因导致这个线程 Thread-629610 无法正常释放，状态一直处于 WAITING。
分析 HS2 connection 与 session 关系
从 Thread-629610 的初始有效堆栈信息开发分析：如下 ThriftBinaryCLIService.java 是我们需要重点研究的 HS connection 连接代码，这个 class 用来初始化 HS2 连接池以及接受、关闭连接。
jstack 堆栈显示 Thread-629610 在执行 ThriftBinaryCLIService.deleteContex 方法的时候一直 WAITING，我们查看 jstack 指示的 ThriftBinaryCLIService.java 代码块，重点关注 141 行的上下几行代码块，如图 4：
图 4 HS2 connection 关闭时会同步关闭 session
如图，很惊喜的看到一直 WAITING 的 141 行代码处于一个参数控制区，也就是说如果该参数设置为 false，那么就可以跳过整个 WAITING 的 141 方法体，那么 HS2 的连接不释放问题自然就可以解决，该参数如下图 5 默认为 true，即默认会执行卡住的 141 行方法：
图 5 HS2 connection 与 session 解耦参数
根据字面描述解释这个参数的含义：设置为 true 的时候，当 HS2 某个 connection 连接关闭的时候，connection 上绑定的 session 会话也会默认关闭。这里补充一下：一个 session 对应着 Hive 的多个同步以及异步 operation（job）。
这个参数控制着 connection 与 session 是否同步关闭，为了进一步了解设置这个参数的意义，我们找到了相关变动的 jira：https://issues.apache.org/jira/browse/HIVE-13415(Hive 2.1.0)与https://issues.apache.org/jira/browse/HIVE-9601(Hive 1.2.0)。HIVE-9601 中为了解决 Hive on Spark 的 beeline 二次启动卡住问题，在 HS2 关闭 connection 的时候进行了 session 绑定并同步关闭 session；HIVE-13415 中讨论认为 HIVE-9601 的改变有悖于 HS2 的 connection 与 session 解耦架构，但为了避免出现新的问题最终在这里妥协加了参数，由上层应用参数控制 connection 与 session 是否同步关闭。
这里我们不去深入讨论 Hive 设计之初对 connection 与 session 的关系定位。根据这两个 jira 能够得出两个结论：
（1）在 HIVE-9601 之前，即 Hive 1.2.0 之前的版本中 connection 与 session 完全解耦，关闭 session 不会去调用关闭 connection 的代码块，也不会不存在本文描述的问题；
（2）在 HIVE-13415 之后，即 Hive 2.1.0 以及之后的版本中，由参数控制 connection 与 session 是否同步关闭，默认是耦合同步关闭，但上层应用可以修改参数，解耦 connection 与 session。
我们线上使用的是 Hive3.1.0 版本，显然只要修改这个参数就可以根本上解决本文 HS2 连接不释放问题。但是会引发另外一个问题，因为 session 对应着多个同步以及异步作业，有的作业是运行在 yarn 上的 Tez 作业，如果关闭 connection 但不同步关闭 session，会导致该 session 上的 Tez 作业一直运行，但用户可能误以为 Tez 作业已经被 kill，不会主动管理这些 Tez 作业，这样带来一个危害就是会浪费过多的 yarn 资源。显然这个解决方案不够优雅，需要进一步分析，寻求合理的解决方案。
分析异常 Tez 作业
前几步我们都把目光聚焦在 Hive 代码上，一直在尝试从 Hive 侧去解决问题，其实 Hive 侧基本上可以解决问题，但是极端情况下还是会出现其他问题。我们需要把目光转移到应用侧，分析出现异常的 Tez 作业，研究导致 Thread-629610 一直 WAITIGN 的最终异常调用栈。
如何找到 Thread-629610 对应的 Tez 作业呢？我们需要找到 Tez 作业对应的 Hive SQL 以及 ApplicationId，进行针对性分析。jstack 堆栈中是看不出 SQL 信息以及 ApplicationID 的，需要在 HS2 日志中进行搜索 Thread-629610 关键词，找到日志信息，注意 Thread-629610 是 HS2 的连接线程，同一时间段内 Thread-629610 会接受客户端的多个 SQL 任务，每个 SQL 任务又会分配给一个异步线程执行，这个异步线程才是每个 SQL 任务独有的执行线程，一般情况下可以根据异常时间结合 HS2 中的异常信息（ERROR、WARN）以及其他作业监控页面(如 Tez UI)去定位 HS2 中线程日志，如下图 6Tez UI 监控，我们看到几个执行时间超长的作业，其中第一个作业已经运行了 17 个小时，结合 HS2 中的异常信息，我们定位这个作业就是 Thread-629610 线程接收的作业，并分配给 Thread-629711 异步线程执行：
图 6 Thread-629711 异步线程任务
进一步点击 Tez UI，还可以其他一些有效信息，比如用户的 SQL 以及执行 DAG 流向图，如下图 7 DAG 显示第一个 stage（Map1）一直在 running，后面的几个 stage 自然也无法完成：
图 7 SQL 任务 DAG 流向图
结合 Thread-629610 堆栈中涉及到 Tez 的关键堆栈信息以及 HS2、Tez 代码分析，如下：
可以看到调用栈中显示关闭 session 的同时会调用 Tez dag 接口 kill 任务，然后 dag 客户端会 check 任务的状态是否改变，比如这里 check 是否变为 KILLED 状态：
图 8 HS2 TezTask.java 中 kill dag 操作
Thread-629610 线程最终在 RPC 请求 DAG Master 的时候出现了 WAITING，说明 Tez 任务没有被正常 kill，有可能是 DAG Master 没有收到 dag 客户端 Kill 请求，有可能 Dag Master 出现问题，根据获取的 ApplicationId，找到运行 Dag Mater 的 Container，然后去运行 Container 所在的节点，jstat 查看 Contaier 进程的 gc 情况：
图 9 Dag Master 进程 full gc 信息
可以看到 Dag Master 出现严重 full gc 的情况，集群默认的 Tez container 较小，而用户的部分作业数据量较大，Dag Master 需要频繁请求以及调度 task container，而且 Tez 是一个 pipeline 执行框架，task 并行度比较高，相比 MR 任务的 App Master， Tez 的 Dag Master 需要配置稍大一些内存；同时由于该 SQL 任务主要是在做一些 group by 去重操作，建议用户添加 group by 数据倾斜优化参数，避免出现长尾 task 导致某个 stage 无法完成。
分析到这里，才清楚 Thread-629610 是因为 Tez DAG Master 出现 full gc，没有接收到 dag client 的 kill 信号，导致线程锁一直无法释放。理论上对这种类型的 Tez 作业进行调优，避免 Tez full gc 情况，一定程度上能够解决问题。
但是这里考虑一个问题，为什么在 Tez 作业还在运行的时候，这个集群为什么会频繁出现 HS2 connection 连接关闭的情况呢？ 正常情况下用户侧需要管理作业的生命流程，作业取消或者完成后再去关闭 HS2 连接。这个问题需要了解用户侧的作业管理方式。
分析用户侧的 Tez 作业管理方式
用户侧业务场景：单次提交并发作业很多，HS2 瞬时连接较多，如果 SQL 扫描数据量比较多或者逻辑比较复杂，可能会导致 Tez 作业无法完成，比如出现 DAG Master full gc 问题。用户侧会通过 kill 客户端 SQL 作业的 jar 进程来取消作业，这种取消作业的方式如 Thread-629610 的堆栈信息描述：“HS2 关闭连接的时候连带关闭 session ，RPC 调用 DAG 的 kill 接口删掉任务”。但是如果 DAG Master 出现异常无法接收 kill 信号，异常作业还是会一直处于 RUNNING 状态，导致该 HS2 连接 Thread-629610 关闭失败，一直占有同步锁，进一步引发其他 HS2 连接无法进入关闭 session 逻辑，最终导致 HS2 的所有连接都无法关闭，客户端出现连接 HS2 卡顿的表象。
综合上文分析以及用户侧的 Tez 作业管理方式，我们画出 Thread-629610 的执行流程如下图 10：
图 10 Thread-629610 连接关闭执行流程
解决方案
综上分析，由图 10 可以直观看到，在标红处的多个地方我们都可以通过优化参数、优化代码的方式去解决本文描述的问题。如果不考虑极端情况，我们只需要优化其中任何一个部分，不需要从用户侧结合代码分析整个流程。但是线程生产环境一旦出现问题，都是一些极端业务场景下测试出来的，需要彻底找出问题根因，避免新的问题出现。本文描述的问题简要总结可以做以下优化：
（1）优化 org.apache.hive.service.cli.session.SessionManager.closeSession 同步锁，参考https://issues.apache.org/jira/browse/HIVE-22165；
（2）针对该用户作业设置参数 hive.server2.close.session.on.disconnect 为 false，同时用户侧取消作业的时候要使用 yarn kill 命令删除作业，避免异常作业浪费 yarn 资源；
（3）优化 Tez DAG Master 的 JVM 内存，避免 full gc 导致 dag client 的 rpc 请求失败；同时增加 group by 数据倾斜优化参数，避免 SQL 作业数据倾斜导致 task 执行时间超长。
小结
本文针对 HS2 连接频繁卡顿问题，使用基本的运维手段找出问题根因，给出解决方案。解决问题的思路供大家参考，大数据场景的运维套路多数是一致的，如果遇到其他组件的卡顿问题，也可以用类似的手段去定位。
大数据运维是一个枯燥且有趣的工作，针对每一个线上问题，需要结合用户使用方式以及组件代码进行逐步分析，抽丝剥茧，找出问题根因。在最后问题解决的时刻才会体会到拨开云雾见天日，守得云开见月明的乐趣。
移动云，5G时代你身边的智慧云 2019.02.13 加入
移动云大数据产品团队，在移动云上提供云原生大数据分析LakeHouse，消息队列Kafka/Pulsar，云数据库HBase，弹性MapReduce，数据集成与治理等PaaS服务。 微信公众号：人人都学大数据
评论