问题描述
在Hive on Spark上运行一个hive查询脚本，spark将其划分为3个stage。发现脚本在执行到stage2时有大量task失败，失败任务被重新调起后依然失败，最终导致整个job失败。
分析问题
查看任务日志，发现报出的错误是
ERROR spark.SparkReduceRecordHandler: Fatal error: org.apache.hadoop.hive.ql.metadata.HiveException: Error while processing row (tag=0) {"key":{"_col0":"48945840 5791400728103103000049993","_col1":"01"},"value":{"_col0":0,"_col1":90,"_col2":0,"_col3":0,"_col4":0}}org.apache.hadoop.hive.ql.metadata.HiveException: Error while processing row (tag=0) {"key":{"_col0":"48945840 5791400728103103000049993","_col1":"01"},"value":{"_col0":0,"_col1":90,"_col2":0,"_col3":0,"_col4":0}}
继续往下翻看日志，看到
Caused by: org.apache.hadoop.hive.ql.exec.mapjoin.MapJoinMemoryExhaustionException: 2019-08-20 04:24:26 Processing rows: 3600000 Hashtable size: 3599999 Memory usage: 9491710256 percentage: 0.921 at org.apache.hadoop.hive.ql.exec.mapjoin.MapJoinMemoryExhaustionHandler.checkMemoryStatus(MapJoinMemoryExhaustionHandler.java:99)
根据字面意思，是因为由于执行了mapjoin而导致内存耗尽，内存占用率达到了0.921，因此任务无法继续执行，导致失败。
为什么会触发map join呢？根据mapjoin原理介绍可知：
MapJoin通常用于一个很小的表和一个大表进行join的场景，具体小表有多小，由参数 hive.mapjoin.smalltable.filesize来决定，该参数表示小表的总大小，默认值为25000000字节，即25M。
mapjoin的优化在于，在mapreduce task开始之前，创建一个local task， 小表以hashtable的形式加载到内存，然后序列化到磁盘，把内存的hashtable压缩为tar文件。然后把文件分发到 Hadoop Distributed Cache，然后传输给每一个mapper，mapper在本地反序列化文件并加载进内存在做join。
在我的HQL语句中，确实有多个left outer join语句。据此，可以猜测是在小表加载时，内存溢出导致的问题。
确认原因
再次查阅日志，发现在报错之前有这么一段：
19/08/20 16:24:05 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:05 Processing rows: 2600000 Hashtable size: 2599999 Memory usage: 7472152840 percentage: 0.725
2019-08-20 04:24:05 Processing rows: 2800000 Hashtable size: 2799999 Memory usage: 7564427528 percentage: 0.734
19/08/20 16:24:05 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:05 Processing rows: 2800000 Hashtable size: 2799999 Memory usage: 7564427528 percentage: 0.734
2019-08-20 04:24:07 Processing rows: 2700000 Hashtable size: 2699999 Memory usage: 8992588048 percentage: 0.872
19/08/20 16:24:07 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:07 Processing rows: 2700000 Hashtable size: 2699999 Memory usage: 8992588048 percentage: 0.872
2019-08-20 04:24:07 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 7488930560 percentage: 0.726
19/08/20 16:24:07 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:07 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 7488930560 percentage: 0.726
2019-08-20 04:24:07 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 7572816640 percentage: 0.735
19/08/20 16:24:07 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:07 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 7572816640 percentage: 0.735
2019-08-20 04:24:10 Processing rows: 2800000 Hashtable size: 2799999 Memory usage: 7694450952 percentage: 0.746
19/08/20 16:24:10 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:10 Processing rows: 2800000 Hashtable size: 2799999 Memory usage: 7694450952 percentage: 0.746
2019-08-20 04:24:10 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8029995272 percentage: 0.779
19/08/20 16:24:10 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:10 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8029995272 percentage: 0.779
2019-08-20 04:24:10 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8143241480 percentage: 0.79
19/08/20 16:24:10 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:10 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8143241480 percentage: 0.79
19/08/20 16:24:11 INFO spark.SparkRecordHandler: processing 6000000 rows: used memory = 8357150984
19/08/20 16:24:11 INFO spark.SparkRecordHandler: processing 6000000 rows: used memory = 8503951624
2019-08-20 04:24:12 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 8294236424 percentage: 0.805
19/08/20 16:24:12 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:12 Processing rows: 2900000 Hashtable size: 2899999 Memory usage: 8294236424 percentage: 0.805
2019-08-20 04:24:12 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 8671723784 percentage: 0.841
19/08/20 16:24:12 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:12 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 8671723784 percentage: 0.841
2019-08-20 04:24:13 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 7904166168 percentage: 0.767
19/08/20 16:24:13 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:13 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 7904166168 percentage: 0.767
2019-08-20 04:24:14 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8243904824 percentage: 0.80
19/08/20 16:24:14 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:14 Processing rows: 3000000 Hashtable size: 2999999 Memory usage: 8243904824 percentage: 0.80
19/08/20 16:24:15 INFO spark.SparkRecordHandler: processing 6000000 rows: used memory = 8269070632
2019-08-20 04:24:16 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 8147435816 percentage: 0.79
19/08/20 16:24:16 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:16 Processing rows: 3100000 Hashtable size: 3099999 Memory usage: 8147435816 percentage: 0.79
2019-08-20 04:24:16 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8256487720 percentage: 0.801
19/08/20 16:24:16 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:16 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8256487720 percentage: 0.801
2019-08-20 04:24:16 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8508145960 percentage: 0.825
19/08/20 16:24:16 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:16 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8508145960 percentage: 0.825
2019-08-20 04:24:18 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 8524084384 percentage: 0.827
19/08/20 16:24:18 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:18 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 8524084384 percentage: 0.827
2019-08-20 04:24:18 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 8779936928 percentage: 0.852
19/08/20 16:24:18 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:18 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 8779936928 percentage: 0.852
2019-08-20 04:24:19 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8642363704 percentage: 0.838
19/08/20 16:24:19 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:19 Processing rows: 3200000 Hashtable size: 3199999 Memory usage: 8642363704 percentage: 0.838
2019-08-20 04:24:21 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 8919187768 percentage: 0.865
19/08/20 16:24:21 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:21 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 8919187768 percentage: 0.865
2019-08-20 04:24:22 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 9120514360 percentage: 0.885
19/08/20 16:24:22 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:22 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 9120514360 percentage: 0.885
2019-08-20 04:24:23 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 9053405496 percentage: 0.878
19/08/20 16:24:23 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:23 Processing rows: 3300000 Hashtable size: 3299999 Memory usage: 9053405496 percentage: 0.878
2019-08-20 04:24:24 Processing rows: 3500000 Hashtable size: 3499999 Memory usage: 9223274816 percentage: 0.895
19/08/20 16:24:24 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:24 Processing rows: 3500000 Hashtable size: 3499999 Memory usage: 9223274816 percentage: 0.895
2019-08-20 04:24:25 Processing rows: 3500000 Hashtable size: 3499999 Memory usage: 9179234616 percentage: 0.89
19/08/20 16:24:25 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:25 Processing rows: 3500000 Hashtable size: 3499999 Memory usage: 9179234616 percentage: 0.89
19/08/20 16:24:25 INFO spark.SparkRecordHandler: processing 7000000 rows: used memory = 9405727032
2019-08-20 04:24:25 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 9189720384 percentage: 0.891
19/08/20 16:24:25 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:25 Processing rows: 3400000 Hashtable size: 3399999 Memory usage: 9189720384 percentage: 0.891
19/08/20 16:24:26 INFO spark.SparkRecordHandler: processing 7000000 rows: used memory = 9202303280
2019-08-20 04:24:26 Processing rows: 3600000 Hashtable size: 3599999 Memory usage: 9491710256 percentage: 0.921
19/08/20 16:24:26 INFO exec.HashTableSinkOperator: 2019-08-20 04:24:26 Processing rows: 3600000 Hashtable size: 3599999 Memory usage: 9491710256 percentage: 0.921
在内存用到0.921之后，就开始出现错误信息了，因此可以确定是mapjoin优化而导致的内存溢出。
解决方案
可以hive.mapjoin.localtask.max.memory.usage将内存使用极限调大到0.999，这个配置默认是0.9。但是很明显这个举措既不治标也不治本，内存里面根本就放不下。
因此可以
set hive.auto.convert.join = false #关闭mapjion，自从hive0.11.0之后这个参数默认为true
调小hive.smalltable.filesize，默认是25000000（在2.0.0版本中）
set hive.ignore.mapjoin.hint=false; 关闭忽略mapjoin的hints
其中最关键的是直接关闭mapjoin自动优化，就不会有上面的问题了。如果是在脚本中关闭，可以写为
beeline --hiveconf hive.auto.convert.join=false
在关闭mapjoin之后，该任务顺利执行，不过原来的3个stage变成了5个。
一点小思考
仔细想想这个问题，hive会首先将join关联的中一个表判定为小表，然后才会将其加载到内存中。我所用集群的hive.smalltable.filesize为100MB，按理说被判定为小表的表完全可以放到内存中，毕竟内存相对而言是很大的。但为什么会内存溢出呢？是hive对表大小的判断失误吗？据一些专家所言，hive可能会把大表而不是小表装进内存，这是hive的一个bug吗？希望有大佬指点迷津。
hear me roar!
网友评论