Hive查询变慢及无响应问题分析

问题描述

某任务使用Hive作数据查询，连续几天任务越来越慢。后面甚至出现了执行失败的错误。

问题分析

经排查发现连接机器A上Hive的任务运行平稳，出现问题的任务都是连接的B机器的，观测到B机器上的Hive进程CPU过高。

我们查询到4154对应的进程是HiveServer2。通过Cloudera Manage查看B机器的负载情况，发现线程数达到了18000多！

观察近三十天的线程数，线程数一直在增加，重启之后线程数也会随着时间上升，怀疑hiveserver2的线程是有问题的。

追踪日志，发现hiveserver2在6月1日有一次GC，而这次GC虚拟机停止了3.7s。

2019-06-01 07:22:36,244 INFO  org.apache.hadoop.hive.ql.session.SessionState: [HiveServer2-Handler-Pool: Thread-268382]: Deleted directory: /tmp/hive/7b4cb2c9-5c18-435f-a7ed-05c2d705c23e on fs with scheme file
2019-06-01 07:22:36,244 INFO  hive.metastore: [HiveServer2-Handler-Pool: Thread-268382]: Closed a connection to metastore, current connections: 1
2019-06-01 11:00:11,604 WARN  org.apache.hadoop.yarn.server.resourcemanager.scheduler.fair.AllocationFileLoaderService: [AllocationFileReloader]: Failed to reload fair scheduler config file because last modified returned 0. File exists: false
2019-06-01 13:00:12,234 INFO  org.apache.hadoop.hive.common.JvmPauseMonitor: [org.apache.hadoop.hive.common.JvmPauseMonitor$Monitor@7dcb42a9]: Detected pause in JVM or host machine (eg GC): pause of approximately 3754ms
No GCs detected
2019-06-02 00:01:02,064 ERROR org.apache.hadoop.conf.Configuration: [HiveServer2-Handler-Pool: Thread-268382]: error parsing conf file:/opt/cm-5.12.0/run/cloudera-scm-agent/process/11384-hive-HIVESERVER2/hive-site.xml
java.io.FileNotFoundException: /opt/cm-5.12.0/run/cloudera-scm-agent/process/11384-hive-HIVESERVER2/hive-site.xml (没有那个文件或目录)
        at java.io.FileInputStream.open0(Native Method)
        at java.io.FileInputStream.open(FileInputStream.java:195)
        at java.io.FileInputStream.<init>(FileInputStream.java:138)
        at java.io.FileInputStream.<init>(FileInputStream.java:93)
        at sun.net.www.protocol.file.FileURLConnection.connect(FileURLConnection.java:90)
        at sun.net.www.protocol.file.FileURLConnection.getInputStream(FileURLConnection.java:188)
        at org.apache.hadoop.conf.Configuration.parse(Configuration.java:2482)
        at org.apache.hadoop.conf.Configuration.loadResource(Configuration.java:2550)
        at org.apache.hadoop.conf.Configuration.loadResources(Configuration.java:2516)
        at org.apache.hadoop.conf.Configuration.getProps(Configuration.java:2412)
        at org.apache.hadoop.conf.Configuration.get(Configuration.java:1234)
        at org.apache.hadoop.hive.conf.HiveConf.getVar(HiveConf.java:2697)
        at org.apache.hadoop.hive.conf.HiveConf.getVar(HiveConf.java:2718)
        at org.apache.hadoop.hive.conf.HiveConf.initialize(HiveConf.java:2790)
        at org.apache.hadoop.hive.conf.HiveConf.<init>(HiveConf.java:2733)
        at org.apache.hive.service.auth.AuthenticationProviderFactory.getAuthenticationProvider(AuthenticationProviderFactory.java:61)
        at org.apache.hive.service.auth.PlainSaslHelper$PlainServerCallbackHandler.handle(PlainSaslHelper.java:104)
        at org.apache.hive.service.auth.PlainSaslServer.evaluateResponse(PlainSaslServer.java:102)
        at org.apache.thrift.transport.TSaslTransport$SaslParticipant.evaluateChallengeOrResponse(TSaslTransport.java:539)
        at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:283)
        at org.apache.thrift.transport.TSaslServerTransport.open(TSaslServerTransport.java:41)
        at org.apache.thrift.transport.TSaslServerTransport$Factory.getTransport(TSaslServerTransport.java:216)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:269)
        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)
2019-06-02 00:01:02,064 ERROR org.apache.thrift.server.TThreadPoolServer: [HiveServer2-Handler-Pool: Thread-268382]: Error occurred during processing of message.
java.lang.RuntimeException: java.io.FileNotFoundException: /opt/cm-5.12.0/run/cloudera-scm-agent/process/11384-hive-HIVESERVER2/hive-site.xml (没有那个文件或目
录)

同时我们发现线程[HiveServer2-Handler-Pool: Thread-268382]的线程id很大，难道是这个线程池里面线程数量太多，还有很多没有销毁？

但是查看更多的log发现这个线程id一直被复用，并不是每次接收到请求就会增长的。

那就从JVM着手吧。
首先登录master01并切换hive用户。

$ sudo su - hive -s /bin/bash

下载并启动Java诊断神器——阿尔萨斯

$ wget https://alibaba.github.io/arthas/arthas-boot.jar
$ java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.1.1
[INFO] Process 15280 already using port 3658
[INFO] Process 15280 already using port 8563
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 15280 org.apache.hadoop.util.RunJar
  [2]: 4171 org.apache.hadoop.util.RunJar
1
[INFO] arthas home: /var/lib/hive/.arthas/lib/3.1.1/arthas
[INFO] The target process already listen port 3658, skip attach.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'
 
 
wiki      https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version   3.1.1
pid       15280
time      2019-06-12 16:57:33

查看线程

$ thread

目之所及，全是Get-Input-Paths线程！
下载Hive源码，发现org.apache.hadoop.hive.ql.exec.Utilities中有与此相关的线程池。

ExecutorService pool = Executors.newFixedThreadPool(numExecutors,
        new ThreadFactoryBuilder().setDaemon(true).setNameFormat("Get-Input-Paths-%d").build());
 
 
executor = Executors.newFixedThreadPool(numExecutors,
        new ThreadFactoryBuilder().setDaemon(true)
                .setNameFormat("Get-Input-Summary-%d").build());

这就相当于每次进入getInputPaths和getInputSummary方法都会创建一个线程池，是不是线程池没正确关闭呢——但是代码中已经有相关逻辑executor.shutdown()。

Google关键字，发现Jira[HIVE-16949]Leak of threads from Get-Input-Paths and Get-Input-Summary thread pool。原来是老版本的Hive没有将线程池关闭，这个Bug在Hive3.0中得以修复。而我们使用的CDH5.12.0中确实没有关闭线程池的代码。

问题解决

1. 可从CDH官网下载对应版本Hive源码下载hive-1.1.0-cdh5.12.0-src.tar.gz
   ，修改并替换集群上所有的hive-exec.jar。修改方法参考上面的Jira。
2. 升级CDH版本至5.12.2，此版本已经修复HIVE-16949的问题，参考Issues Fixed in CDH 5.12.x
   。

以上方法2选1。