惊!-hive on spark(hive任务)任务慢---竟然有这些原因！

项目场景：

项目组中有很多hive on spark任务，每个小时调度一次。要求每次调度任务执行不能超过一个小时，只要超过一个小时就会影响下一个任务调度！

问题描述

问题嘛：自然是调度，任务执行超过了一个小时，还很多，中台没有报错，任务能执行完但是很慢，性能很差！

如图所示：

从图中我们可以看出实际正常情况下任务执行是30分钟左右，不正常的很多超过了1个小时，但这个是业务不能容忍的。接下来，跟着我troubleshooting吧！go！

原因分析：

1.找出哪些hive-sql脚本的流程跑的慢。

test1_bms 2023-07-2210:05:292023-07-2210:45:10 成功 40分钟 查看
test2_ods 2023-07-2210:05:292023-07-2210:47:10 成功 42分钟 查看
test3_ads 2023-07-2210:06:192023-07-2210:57:33 成功 51分钟 查看
test4_dwd 2023-07-2210:06:332023-07-2210:54:32 成功 48分钟 查看

请注意，以上流程名我随便取的
2.点击test1_bms流程查看日志，分析一下在哪慢了

2023-07-2210:07:53,619 Stage-14_0:1/1 Finished Stage-15_0:1(+1)/7 
Stage-16_0:0/42 INFO -2023-07-2210:07:54.625 INFO [Thread-0]2023-07-2210:07:54,624 
Stage-14_0:1/1 Finished Stage-15_0:2(+0)/7 Stage-16_0:0/42
INFO -2023-07-2210:09:56.637 INFO [Thread-0]2023-07-2210:09:56,636 Stage-14_0:1/1 Finished Stage-15_0:2(+1)/7 Stage-16_0:0/42
INFO -2023-07-2210:09:57.646 INFO [Thread-0]2023-07-2210:09:57,646 Stage-14_0:1/1 Finished Stage-15_0:2(+5)/7 Stage-16_0:0/42
INFO -2023-07-2210:13:59.658 INFO [Thread-0]2023-07-2210:13:59,657 Stage-14_0:1/1 Finished Stage-15_0:4(+3)/7 Stage-16_0:0/42
INFO -2023-07-2210:14:00.664 INFO [Thread-0]2023-07-2210:14:00,663 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:0/42
INFO -2023-07-2210:18:01.669 INFO [Thread-0]2023-07-2210:18:01,668 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:0(+9)/42
INFO -2023-07-2210:18:02.674 INFO [Thread-0]2023-07-2210:19:02,673 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:9(+9)/42
INFO -2023-07-2210:23:03.679 INFO [Thread-0]2023-07-2210:23:03,679 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:20(+9)/42
INFO -2023-07-2210:24:04.693 INFO [Thread-0]2023-07-2210:24:04,692 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:32(+6)/42
INFO -2023-07-2210:25:05.699 INFO [Thread-0]2023-07-2210:25:05,698 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:37(+5)/42
INFO -2023-07-2210:27:08.711 INFO [Thread-0]2023-07-2210:27:08,711 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:37(+5)/42
INFO -2023-07-2210:29:09.717 INFO [Thread-0]2023-07-2210:29:09,716 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:38(+4)/42
INFO -2023-07-2210:35:11.727 INFO [Thread-0]2023-07-2210:35:11,727 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:40(+2)/42
INFO -2023-07-2210:39:12.733 INFO [Thread-0]2023-07-2210:39:12,732 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:41(+1)/42
INFO -2023-07-2210:46:14.741 INFO [Thread-0]2023-07-2210:46:14,740 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:42/42 Finished

由此发现计算阶段很慢

3.那对比一下多个流程正常的时候和不正常的时候yarn日志吧

这是正常的

上面是不正常的

4.将上面对比的结果反馈给实施开发人员，基本上很多不正常的数据量越多越慢，数据量越少耗时越少。很明显sql多少有点问题

5.在同事优化sql逻辑后，果然有点效果了，超过一个小时的流程变少了，耗时也变少了。那么问题来了是超过一个小时的调度变少了，不是完全没有超时。说明超时原因很可能不止这一个，继续观察

6.继续排查，看一下yarn资源情况和cdh监控情况是否有告警

从图中我们可以发现yarn的资源很平均每天每小时，没有出现出问题的那一个小时资源消耗巨大，并且每小时的数据量并不大

看一下cdh告警，发现有告警出现，且是block块的告警，说明可能产生了很多小文件。请注意，一般流式任务会产生很多小文件

7.这个时候我们把问题锁定到了小文件这里，那看看对应异常的流程是哪张表吧，count一下表的文件数是不是很多

[root@hdp01 ~]#hdfs dfs -count /user/hive/warehouse/test.db/test1_bms
5567208342313686008610/user/hive/warehouse/test.db/test1_bms
#由此发现这张表的文件数是2083423，太恐怖了，按道理hdfs不适合做小文件处理，从这里就验证了我们猜想，果然是小文件导致的。那我们后面就从小文件入手吧

8.定位到可能是小文件导致的，我们单独在hue做个验证，查询这张表某个小时的数据看看查询时间是多少，像这样

select * from test1_bms where partition(dt=2023071700);

耗时40分钟，很慢

9.对这个分区的文件做合并处理，再查，看是否时间缩短了，我们用insert overwrite方法合并这一个分区的文件数，像这样

insert overwrite table test1_bms partition(dt=2023071700)
select  
  column1,column2
from
test1_bms 
where dt=2023071700

穿插一句理论知识,insert overwrite和insert into区别：

insert into：将数据追加到表的末尾，不可覆盖。
insert overwrite：将重写表中的内容，删除原表中的数据，再进行插入操作

处理完后，再进行查询：

select * from test1_bms where partition(dt=2023071700);

耗时2分钟，很快，相差了20倍。证明我们的猜想是正确的，就是小文件导致的
10.定位到小文件导致的后，解决方案很多，我们这里使用一般的做法，对产生的小文件进行合并处理。小文件合并处理方案网上很多，我们这里使用insert overwrite方法进行合并，像这样：

insert overwrite table test1_bms partition(dt=2022031100)
select  
  column1,column2
from
tableName 
where dt=2022031100

当然我们还可以使用spark参数解决，类似于这样的具体还得大家自行百度罗（我这里没有用这种方式）：

set spark.merge.files.enabled=true;
set spark.merge.files.number=500;

在你的hive sql脚本加上以上参数具体参数值可能还得调优，请自行探索
11.合并小文件后，果然问题得到了解决，几乎都是20分钟跑完任务。这里穿插一句理论知识：

11.1. HDFS 上每个文件都要在 NameNode 上建立一个索引，这个索引的大小约为 150byte，这样当小文件比较多的时候，会大量占用 NameNode 的内存空间，使得 namenode 压力过大，且 hdfs 能存储的数据量也会变小，影响 hdfs 的横向扩展能力;11.2. 小文件过多会使索引文件大量增加，使得索引速度变慢。如果使用 mapreduce 处理小文件，则会增加 map 任务数量，增加寻址次数。
最终的结果就是导致任务跑的慢！

12.过了2天后发现白天的任务都很快20分钟跑完，每天晚上12点的任务就跑得很慢，请注意只有12点的任务慢，就即使是1点2点3点都会很快

啊哈，和我的直觉一致，这玩意肯定不止前面2个原因导致的--sql逻辑+小文件。继续troubleshooting吧。遇到只有12点出问题，我首先反应的是2个：第一个咨询实施开发12点的数据量是否很大，第二个从定时任务或者调度出发，12点是否有很多调度任务

跟同事确认了数据量甚至比白天的任务还要少，12点调度任务只有2个，yarn资源监控的图也是和上面一样很平均

13.要嘎了，现在第三个性能慢的原因可能是网上从来没遇到过的很难的问题，要炸裂了，兄弟们，冲吧。继续啃，打开cdh继续看监控有哪些异常

终于让我看到了点胜利的曙光，这个hive组件是不健康的，时间点也和我们超时的时间段吻合，很大概率就是这个metastore导致的了，为了验证这个猜想我还得多方面验证，考量，往下看
14.查看任务日志看看，12点的任务到底是哪个阶段慢了

INFO [Thread-0]2023-08-0500:42:54,624 Stage-14_0:1/1 Finished Stage-15_0:2(+0)/7 Stage-16_0:0/42 
INFO [Thread-0]2023-08-0500:42:56,636 Stage-14_0:1/1 Finished Stage-15_0:2(+1)/7 Stage-16_0:0/42
INFO [Thread-0]2023-08-0500:42:57,646 Stage-14_0:1/1 Finished Stage-15_0:2(+5)/7 Stage-16_0:0/42
INFO [Thread-0]2023-08-0500:42:59,657 Stage-14_0:1/1 Finished Stage-15_0:4(+3)/7 Stage-16_0:0/42
INFO [Thread-0]2023-08-0500:43:00,663 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:0/42
INFO [Thread-0]2023-08-0500:43:01,668 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:0(+9)/42
INFO [Thread-0]2023-08-0500:43:02,673 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:9(+9)/42
INFO [Thread-0]2023-08-0500:43:03,679 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:20(+9)/42
INFO [Thread-0]2023-08-0500:43:04,692 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:32(+6)/42
INFO [Thread-0]2023-08-0500:43:05,698 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:37(+5)/42
INFO [Thread-0]2023-08-0500:43:08,711 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:37(+5)/42
INFO [Thread-0]2023-08-0500:43:09,716 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:38(+4)/42
INFO [Thread-0]2023-08-0500:43:11,727 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:40(+2)/42
INFO [Thread-0]2023-08-0500:43:12,732 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:41(+1)/42
INFO [Thread-0]2023-08-0500:43:14,740 Stage-14_0:1/1 Finished Stage-15_0:7/7 Finished Stage-16_0:42/42 Finished

从这里我们能看出计算阶段很快仅仅只耗时1分钟，这与我们看的yarn监控，资源情况一致，并不是资源不足导致的慢，继续分析日志

05-08-202300:21:42 CST INFO -2023-08-0500:21:42.967 INFO [Thread-0] Logging initialized using configuration in jar:file:/opt/cloudera/parcels/CDH-6.3.2-1.cdh6.3.2.p0.1605554/jars/hive-common-2.1.1-cdh6.3.2.jar!/hive-log4j2.properties Async: false
05-08-202300:36:12 CST INFO -2023-08-0500:36:12.164 INFO [Thread-0] Query ID = user_20230804002144_1a6f198b-78b9-40a3-8b81-60b2497a3717
05-08-202300:36:12 CST INFO -2023-08-0500:36:12.166 INFO [Thread-0] Total jobs =505-08-202300:36:12 CST INFO -2023-08-0500:36:12.185 INFO [Thread-0] Launching Job 1 out of 5

发现什么了，是不是登录很慢00:21:42开始loggin，00:36:12才开始登录上 提交spark job任务，有的兄弟会讲这是资源不足导致的等待，错了，兄弟们这还没到spark，yarn那里去，任务还没提交呢这15分钟。我们继续看

Spark job[3] finished successfully in 2.01second(s)
Spark Job[3] Metrics: TaskDurationTime:787, ExecutorCpuTime:87, JvmGCTime:0, BytesRead / RecordsRead:14752/3, BytesReadEC:0, ShuffleTotalBytesRead / ShuffleRecordsRead:0/0, ShuffleBytesWritten / ShuffleRecordsWritten:0/005-08-202300:39:10 CST -2023-08-0500:39:10.409 INFO [Thread-0] Loading data to table test.test1_bms
05-08-202300:53:02 CST -2023-08-0500:53:02.437 INFO [Thread-0] OK
05-08-202300:53:02 CST -2023-08-0500:53:02.680 INFO [Thread-0] Time taken:1878.287 seconds
05-08-202300:53:03 CST INFO - Process with id 22305 completed successfully in 1894 seconds.

从这里看到计算耗时很快而且算完了，貌似卡在了临时表加载数据到hive表的这个过程中，一样的loading很慢花费了15分钟。再看看正常时候loggin和loading的耗时：

SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]05-08-202301:06:13 CST INFO -2023-08-0501:06:13.837 INFO [Thread-0]05-08-202301:06:13 CST INFO -2023-08-0501:06:13.837 INFO [Thread-0] Logging initialized using configuration in jar:file:/opt/cloudera/parcels/CDH-6.3.2-1.cdh6.3.2.p0.1605554/jars/hive-common-2.1.1-cdh6.3.2.jar!/hive-log4j2.properties Async: false
05-08-202301:06:17 CST INFO -2023-08-0501:06:17.077 INFO [Thread-0] OK
05-08-202301:06:17 CST INFO -2023-08-0501:06:17.078 INFO [Thread-0] Time taken:2.197 seconds
05-08-202301:06:19 CST INFO -2023-08-0501:06:19.684 INFO [Thread-0] Query ID = user_20230806010617_a292532d-da64-49d1-b0fd-59ad4328d1cb

是不是很快loggin只耗时1,2秒，我看了很多实例流程正常的都只要几秒钟最多1分钟，继续看正常的loading阶段

Moving data to directory hdfs://nameservice1/tmp/hive/.hive-staging_hive_2023-08-05_01-06-17_104_6389065562264413444-1/-ext-1000005-08-202301:07:27 CST -2023-08-0501:07:27.812 INFO [Thread-0] Loading data to table test.test1_bms
05-08-202301:07:29 CST -2023-08-0501:07:29.124 INFO [Thread-0] OK
05-08-202301:07:29 CST -2023-08-0501:07:29.278 INFO [Thread-0] Time taken:72.092 seconds

也是很快的，由此我们判断，hive metastore组件一定有问题
我们看看metastore 监控：

metesore每到12点就开始不健康了，时间完全吻合

canary耗时最高会达到3分钟，说明这个时间段，建库性能很差，耗时比较长。这个是cdh用来检测元数据库健康状态的。每次会用canary去建测试库表，检测建库时间耗时。建完会删除测试库表。我们继续，看metastore有什么关键的报错没：

点击Stderr进入错误日志页面

大部分日志都是这样，没有什么关键的日志。但是这个日志很明显只是ssl参数的问题，根本不是问题所在

Thu Aug 0300:06:15 CST 2023 WARN: Establishing SSL connection without server's identity verification is not recommended. According to My

15.上面已经定位到是metastore的问题，导致loggin和loading data to table 慢。登陆过程中hive-cli会连接hive-server2,metastore,hdfs,metastore异常了所以导致了慢，那根本原因究竟是什么呢，因为metastore会去连接mysql元数据库，那会不会是元数据有问题呢，我们往后看

# 登录到元数据库机器，查看日志文件在哪个位置
[root@hdp01 ~]# grep -i log /etc/my.cnf
log-error  =/data/mysql/log/mysqld.err
[root@hdp01 ~]# tail -200f/data/mysql/log/mysqld.err |more
#一步一步回车看报错
#很惊讶，报错时间和我们12点超时任务开始和结束时间几乎一致，由此我非常肯定就是mysql导致的
2023-04-08T16:25:13.113649Z 447642[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
d to fulfill the request.2023-04-08T16:25:13.143734Z 447643[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
d to fulfill the request.2023-04-08T16:25:13.144834Z 447644[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
d to fulfill the request.2023-04-08T16:25:13.183042Z 447641[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
d to fulfill the request.2023-04-08T16:30:19.878378Z 447957[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
d to fulfill the request.2023-04-08T16:30:19.901852Z 447955[Warning][MY-013712][Server] No suitable 'keyring_component_metadata_query' service implementation foun
这里的时间是UTC美国时间，加8个小时，刚好和我们异常任务时间完全一致。说明就是这个报错导致的，我们继续排查
插一句，可能有兄弟问，为什么反应出是mysql问题，看mysql日志，其实还有一个蛛丝马迹：前几天zabbix告警发了mysql发生重启的告警，说明我们的mysql不健康

16.定位到根本问题后，我们开始百度搜索这个报错具体解决办法，找到如下2篇关键性文章

说是mysql8.0的bug
上面文章报错跟我们一致，大致是说bug，看官方文档也有说是bug，但是升级mysql动作太大了，不可取，继续搜索
这篇文章刚好吻合，是由什么程序导致的bug复现
这篇文章道出了根因是备份程序导致得bug复现，于是我开始定位从库mysql有没有问题，结果没发现问题
继续看mysqldump备份程序，果然有问题

[root@hdp01 ~]# crontab -l
*0*** sh /opt/mysql_backup.sh  

我的妈呀，问题大着呢，这个定时任务表达式是12点的时候每分钟做一次备份呢，我去，赶紧进行优化：

[root@hdp01 ~]# crontab -e
10*** sh /opt/mysql_backup.sh   

只让他执行一次备份脚本
17.观察，果然第二天跑得很快，只用了19分钟，开心奥利给解决了大问题，哈哈哈！

解决方案及总结：

总结：
1.解决方案如上，第二部分，从sql逻辑，小文件合并，hive元数据库，yarn资源不足，spark参数等诸多方面入手解决
2.我这里性能问题主要原因有3个：从sql逻辑，小文件合并，hive元数据库
3.以后定时任务要小心了，尽量避免跑了多次
原文链接
转载请注明出处！！！