0823-5.15.1-HDFS慢導致Hive查詢慢問題分析

語言: CN / TW / HK

作者:周鵬輝

文件編寫目的



CDH叢集在業務高峰的時候,偶爾會出現Hive 查詢慢的現象,本文通過分析Hive出現查詢慢時候的叢集狀態,查詢導致Hive查詢慢的原因。

  • 文件概述

1.異常現象

2.異常分析

3.總結

  • 生產環境

1.CDH和CM版本:CDH5.15.1和CM5.15.1

2.叢集啟用Kerbeos+OpenLDAP+Sentry


異常現象



1.10月14日14:40左右,業務反應叢集Hive查詢慢,然後檢視各租戶資源池空閒。為了確認導致當時叢集查詢慢的原因,進行了如下測試。使用hive使用者root.default資源池提交如下query,發現確實響應慢,selectcount(*)一個81行資料的表耗時2分鐘。

select count(*)  from cor_credit_id ;
application_1600315084574_2190734



2.檢視此時HiveServer2壓力不大


異常分析



3.1 HiveServer2和YARN層面分析

1. 首先我們先看 query 在 HiveServer2中的執行情況:

1). Query提交時間是 14:45:

2020-10-14 14:45:29,547 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Handler-Pool: Thread-21234249]: Compiling command(queryId=hive_20201014144545_5b55640c-a133-43f3-a34b-1afedde1e271): select count(*) from cor_credit_id


2). Query很快完成編譯,提交到編譯完成耗時毫秒級別完成:

2020-10-14 14:45:29,752 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Handler-Pool: Thread-21234249]: Completed compiling command(queryId=hive_20201014144545_5b55640c-a133-43f3-a34b-1afedde1e271); Time taken: 0.205 seconds


3). Query 很快進入後臺執行:

2020-10-14 14:45:29,764 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Background-Pool: Thread-21432574]: Executing command(queryId=hive_20201014144545_5b55640c-a133-43f3-a34b-1afedde1e271): select count(*) from cor_credit_id


4).接下來 HiveServer2相當於要執行 hadoop jar命令, 因為需要上傳所有與此 Query 有關的依賴檔案(比如至少有 hive-exec.jar、 還有所有的UDF jar 檔案)到HDFS,這一步到最後向 YARN 提交作業花了幾乎 1 分半鐘的時間。

2020-10-14 14:45:30,066 WARN org.apache.hadoop.mapreduce.JobResourceUploader: [HiveServer2-Background-Pool: Thread-21432574]: Hadoop command-line option parsing not performed. Implement the Tool interface and execute your application with ToolRunner to remedy this.
...
2020-10-14 14:46:52,914 WARN org.apache.hadoop.hdfs.DFSClient: [HiveServer2-Background-Pool: Thread-21432574]: Slow waitForAckedSeqno took 39371ms (threshold=30000ms). File being written: /user/hive/.staging/job_1600315084574_2190734/libjars/Test-UDF-1.0-SNAPSHOT.jar, block: BP-333652757-192.168.0.13-1557145721671:blk_2239901365_1168892760, Write pipeline datanodes: [DatanodeInfoWithStorage[192.168.0.61:1004,DS-037a6585-612a-41df-9082-cdeb4896484b,DISK], DatanodeInfoWithStorage[192.168.0.42:1004,DS-a2d024d3-7421-4605-aefc-447ad44ef24b,DISK]]
...
2020-10-14 14:46:55,411 INFO org.apache.hadoop.yarn.client.api.impl.YarnClientImpl: [HiveServer2-Background-Pool: Thread-21432574]: Submitted application application_1600315084574_2190734


5) .其中可以看到有一次長耗時的HDFS檔案寫操作:

Slow waitForAckedSeqno took 39371ms (threshold=30000ms). File being written: /user/hive/.staging/job_1600315084574_2190734/libjars/Test-UDF-1.0-SNAPSHOT.jar


6).檢視query 在 YARN中的執行情況, 作業提交之後, YARN 用時 33秒 (14:46:55-14:47:28)完成:

2020-10-14 14:47:28,963 INFO org.apache.hadoop.hive.ql.Driver: [HiveServer2-Background-Pool: Thread-21432574]: Completed executing command(queryId=hive_20201014144545_5b55640c-a133-43f3-a34b-1afedde1e271); Time taken: 119.199 seconds


2. 基於以上分析, 並且結合 YARN ResourceManager的日誌, 可以確認作業提交到 YARN 之後並沒有延遲, Container 執行的效能也在合理範圍內. 如果把 HiveServer2提交的1 分半延遲去掉的話, 實際query 執行時間應該在 30 秒左右。從目前的 HiveServer2日誌來看, 很多時段都能看到以上Slow waitForAckedSeqno的警告。通常這個警告說明叢集的 DataNode IO 效能下降比較嚴重, 可能是由於 HDFS 負載突然上升, 也可能是磁碟本身原因。具體參考如下連結【1】,於是我們嘗試從 HDFS角度再做調查此問題。

https://my.cloudera.com/knowledge/Diagnosing-Errors--Error-Slow-ReadProcessor--Error-Slow?id=73443


3.2 HDFS層面分析

1.為了調查是否因為HDFS效能下降導致hive查詢慢,通過在HDFS上put一個檔案,然後分析此檔案的執行流程。具體測試如下:

1).開啟一臺DataNode的DEBUG日誌,put hdfs_slow_test.zip  檔案 到HDFS 的/user1/test1 目錄

export HADOOP_ROOT_LOGGER=DEBUG,console
nohup  hadoop fs -put hdfs_slow_test.zip  /user/test1 >  hdfs_slow_test_DEBUG.LOG 2>&1 &


2.) 檢視檔案存在哪些DataNode上,需要分析對應DataNode的日誌

nohup   hadoop fsck /user/test1/hdfs_slow_test.zip -files -blocks -locations >  fsck.log 2>&1 &


blcok所在的DataNode


3.)通過如下方式獲取HDFS的監控資料和磁碟資訊

curl -s http://xxnn001:50070/jmx > ann.jmx
sar -A -f /var/log/sa/sa15 > /tmp/sar15


2.分析Active NameNode日誌、每個block所在的DataNode日誌、HDFS的監控資料ann.jmx和對應DataNode的磁碟資訊檔案sar15: 

1).在我們開啟DEBUG,上傳一個檔案時,一共生成了5個block。我們看其中的1個block: blk_2298768232_1227819374 先看DataNode日誌:

15:05:05,839 - xxxdn001開始接收資料
15:05:12,192 - xxxdn001傳另外一份資料給xxxdn009xxxdn009開始接收資料
15:05:12,650 - xxxdn009寫完資料
15:05:46,941 - xxxdn001才寫完資料


xxxdn009只花了458毫秒就完成了整個過程,可是xxxdn001花了整整41秒才完成:

hadoop-cmf-hdfs-DATANODE-xxxdn001.xxx.log.out.2

------ xxxdn001花了整整41秒[15:05:05,839-15:05:46,941]才完成------
2020-10-21 15:05:05,839 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374 src: /192.168.0.25:35680 dest: /192.168.0.25:1004
2020-10-21 15:05:46,941 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.0.25:35680dest: /192.168.0.25:1004bytes: 134217728op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_1734092044_1, offset: 0srvID: 747bc9a9-c080-4de7-90e1-3619dd4c2944, blockid: BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374duration: 456171685
2020-10-21 15:05:46,941 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder: BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374, type=HAS_DOWNSTREAM_IN_PIPELINE terminating


hadoop-cmf-hdfs-DATANODE-xxxdn009.xxx.log.out

--- xxxdn009只花了458毫秒[15:05:12,19215:05:12,650]就完成了整個過程---
2020-10-21 15:05:12,192 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374 src: /192.168.0.25:46682 dest: /192.168.0.33:1004
2020-10-21 15:05:12,650 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src: /192.168.0.25:46682dest: /192.168.0.33:1004bytes: 134217728op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_1734092044_1, offset: 0srvID: 2c24eeb9-e079-4be2-985c-17c7959b27eb, blockid: BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374duration: 454145857
2020-10-21 15:05:12,650 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder: BP-333652757-192.168.0.13-1557145721671:blk_2298768232_1227819374, type=LAST_IN_PIPELINE, downstreams=0:[] terminating


2).檢視NameNode的日誌檔案,可以看到xxxdn009新生成的block在15:05:12,651加入到NameNode的block map,而xxxdn001一直到15:05:47,647才加入。

grep "blockMap updated" *NAME* | grep blk_2298768232_1227819374
2020-10-21 15:05:12,651 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap updated: 192.168.0.33:1004 is added to blk_2298768232_1227819374{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-d4f78b19-5511-40d1-98be-f7379656b752:NORMAL:192.168.0.25:1004|RBW], ReplicaUnderConstruction[[DISK]DS-4ad2aa5d-f780-403a-bb9f-2786948aa154:NORMAL:192.168.0.33:1004|RBW]]} size 0
2020-10-21 15:05:47,647 INFO BlockStateChange: BLOCK* addStoredBlock: blockMap updated: 192.168.0.25:1004 is added to blk_2298768232_1227819374 size 134217728


3)在我們做DEBUG測試的時候,有另外一個Hive作業在執行,生成了大量的臨時檔案,然後又刪除了這些臨時檔案。當增加或刪除一個檔案時,NameNode都要在inode map和block map裡做相應的操作,會涉及到鎖的獲取和釋放。當涉及的檔案數量非常大時,鎖的獲取和釋放會變成瓶頸。在NameNode日誌看到下面幾種資訊:

grep BlockStateChange hadoop-cmf-hdfs-NAMENODE-xxxnn001.xxx.log.out.2


 blk_2298728786_1227779717  在DataNode 192.168.0.40上生成了1個replica,blockMap必須把這個資訊加進去,這樣在找block的時候就知道到哪個DataNode上去找。

INFO BlockStateChangeBLOCKaddStoredBlockblockMap updated: 192.168.0.40:1004 is added to blk_2298728786_1227779717


下面是刪除操作,把block和相應的DataNode加入到Invalidate佇列裡

INFO BlockStateChangeBLOCKaddToInvalidatesblk_2298725136_1227776067 192.168.0.55:1004 192.168.0.206:1004 192.168.0.96:1004 192.168.0.104:1004


在收到DataNode心跳時,把要刪除的block下放給DataNode

INFO BlockStateChangeBLOCKBlockManagerask 192.168.0.207:1004 to delete [ ]


上面的資訊在NameNode的日誌檔案中出現了很多次,例如,14:59這1分鐘blockmap update就發生了4617次。而每一次update都是需要拿到鎖才能更改

grep "blockMap updated" hadoop-cmf-hdfs-NAMENODE-xxxnn001.xxx.log.out.2 | grep "2020-10-21 14:59" | wc -l
4617



執行下面命令,就可以看出大部分生成的檔案都是hive的檔案。每生成1個檔案都需要在inode map裡增加1個inode,這也需要拿到鎖才能增加

grep allocateBlock hadoop-cmf-hdfs-NAMENODE-xxxnn001.xxx.log.out.2



從NameNode的日誌檔案裡,觀察到在15:05:47之前,block map裡增加block的操作次數在200-400之間。在15:05:47之後,降到100以下,此時xxxdn001才有機會在NameNode的block map里加入自己的block。說明當NameNode有壓力的時候,處理block map update就會有延遲。在大量小檔案的場景下,NameNode會面臨非常大的壓立從而成為瓶頸,然後導致各種延遲。


4).通過上面的分析問題的根源在於Hive作業產生大量小檔案,由於前面講到的鎖的競爭,NameNode的響應變慢。HDFS是為處理大檔案而設計的,假如同樣是1G的資料,一種情況是1024個1M的小檔案,另一種情況是8個128M的大檔案。雖然資料量一樣,但是前者管理meta的壓力要比後者大得多。叢集現在的檔案平均尺寸為18MB左右,而檔案平均尺寸在128MB左右是比較合理的值,由此可見叢集現在存在大量小檔案,影響叢集的效能。

(檔案的平均尺寸 = 總共佔用的空間(1628503189 MB) / 總共的檔案數 (44341973 files)/ 複本數( replication factor of 2) = 18.36M)


3.我們通過sar -A -f /var/log/sa/sa15 > /tmp/sar15收集了xxxdn001節點的磁碟資料,從磁碟IO的統計資料(倒數第3列await是磁碟延時)可以看出在有工作壓力的情況下,磁碟延時在700-900ms之間,這是一個非常大的延時。所以,磁碟慢也是造成效能低的原因之一。

12:00:01 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
12:10:01 AM dev8-16 64.29 9070.54 14640.82 368.83 47.13 733.18 8.89 57.15
12:10:01 AM dev8-0 6.33 6.29 284.64 45.98 1.05 165.60 60.39 38.21
12:10:01 AM dev8-32 83.00 11847.24 20153.23 385.54 81.15 977.75 8.35 69.32
12:10:01 AM dev8-64 57.18 7903.46 16568.74 428.00 42.00 734.51 9.54 54.53
12:10:01 AM dev8-80 65.70 8187.79 20158.37 431.44 54.67 831.99 9.12 59.94
12:10:01 AM dev8-112 85.27 12042.37 20937.19 386.75 19.09 223.91 4.03 34.37
12:10:01 AM dev8-128 84.35 10577.63 15231.61 305.99 26.50 314.21 4.55 38.36
12:10:01 AM dev8-48 95.39 12221.05 21419.03 352.64 51.98 541.85 6.99 66.72
12:10:01 AM dev8-144 73.22 7399.48 22124.58 403.22 47.79 652.69 7.90 57.86
12:10:01 AM dev8-96 79.80 11828.18 17827.16 371.61 60.77 761.56 7.38 58.93


4.從收集的jmx監控資料看,大部分DataNode last contact都是1-2秒,只有下面2個DataNode last contact是10秒和14秒,但是它們都小於30秒,在正常範圍之內。

192.168.0.112:1004\",\"lastContact\":10
192.168.0.31:1004\",\"lastContact\":14


再檢視下面3個跟效能有關的指標,這說明我們有足夠的handler處理RPC Request,但是NameNode有壓力沒辦法及時處理,進一步驗證了在小檔案的場景下,NameNode已經成為瓶頸。

"RpcQueueTimeAvgTime" : 0.10964765661563147,
"RpcProcessingTimeAvgTime" : 2.0928996456508657,
"CallQueueLength" : 0,
RpcProcessingTimeAvgTime > RpcQueueTimeAvgTime


5.為了進一步驗證問題,我們建立瞭如下圖表,這些圖表都是從不同的角度展示了small files問題帶來的症狀。當有大量的small files需要處理(增加或刪除),NameNode就會非常忙,表現出來的症狀就是無法及時處理DataNode過來的心跳,RPC響應時間變長,RPC佇列變長。

 DataNode的平均心跳圖表:

SELECT heartbeats_avg_time



NameNode  rpc響應相關圖表

select service_block_received_and_deleted_avg_time,service_send_heartbeat_avg_time,service_block_report_avg_time,service_register_datanode_rate WHERE roleType=NameNode AND hostname=xxxnn001.xxx


select service_rpc_processing_time_avg_time,service_rpc_queue_time_avg_time WHERE roleType=NameNode AND hostname=xxxnn001.xxx


select rpc_processing_time_avg_time,rpc_queue_time_avg_time WHERE roleType=NameNode AND hostname=xxxnn001.xxx



select rpc_call_queue_length,service_rpc_call_queue_length WHERE roleType=NameNode AND hostname=xxxnn001.xxx


總結



通過以上的分析,我們可以得出叢集不時出現查詢慢的原因,並不是因為Hive 和YARN響應慢導致,主要是以下兩大原因造成叢集響應慢:

1.叢集業務高峰(主要是每天下午2點-6點)時間段,叢集處於高負載狀態,HDFS需要對磁碟進行大量的讀寫操作,而當前叢集所在的私有云的磁碟讀寫慢,從而導致HDFS響應慢是造成效能慢的原因之一;

2.叢集現在存在大量的小檔案,叢集現在平均檔案尺寸為18MB,大量小檔案的生成和刪除是效能慢的另外一個原因。需要合併Hive上產生的大量小檔案。合併小檔案的方法可以參考如下連結:

https://my.cloudera.com/knowledge/Handling-Small-Files-on-Hadoop-with-Hive-and-Impala?id=74071
https://blog.cloudera.com/small-files-big-foils-addressing-the-associated-metadata-and-application-challenges/

本文分享自微信公眾號 - Hadoop實操(gh_c4c535955d0f)。
如有侵權,請聯絡 [email protected] 刪除。
本文參與“OSC源創計劃”,歡迎正在閱讀的你也加入,一起分享。