一個存疑的Hive Case——MapRedTask Slow

線上Hadoop做壓縮格式更新，預設的從GZip轉到Snappy，并重新開機了HDFS/MAPREDUCE叢集，突然發現一個Hive Script Job從原來的12分鐘縮短到4分鐘并穩定跑了2天，并且該Job agent Server上的所有Hive Script Job的運作時間都縮短了；首先分析變更前後兩天Job的MAPREDUCE日志，發現MAPREDUCE隻變快了4分鐘（因為Snappy的低壓縮比導緻了增加了一個REDUCER而把一個最慢的step加快，該哭還是笑呢：P），另外那詭異的4分鐘在哪裡消失了呢？

對比了兩天的Job運作日志發現變化之前每個Job Stage之間的時間間隔在30s+，而維護後這個時間在3s以内，第一反應就是懷疑是不是JobTracker的問題，在确認了從生成Job，送出Job到Job完成的時間都是正常的，并且Job在準備檔案的過程中對HDFS的操作也是确認正常，GC正常，排除掉JT的問題同時也排除了Namenode的問題；再進一步發現Hive的MoveTask/Stats Task也是1s完成，掐頭去尾後定位到是在MAPREDUCE已經被JobTracker确認完成後，但是Hive被block了接近30s（=10×（pullinterval+checkpollinterval））才确認完成！（counterplan在隔了30s才列印，也就是說runningJob isNotCompleted）.

然後檢視了其他的Hive agent Server的日志發現都一直正常，那麼範圍進一步縮小就是這台有問題，結合上面的分析有幾點可能：

1.JT到agent網絡不穩定——是否調整過有待确認，不過檢視sar無錯誤包等，流量正常，看MR源碼waitingforComplete的interval預設是在5s，如果是網絡問題應該retry了5，6次；

2.Hive所在伺服器問題

3.Hive本身問題

對于2伺服器本身的流量/IO/LOAD都不高，餘量很充分，并且2無錯誤日志，找一台對比OS參數發現太多不一樣的了(坑)直接忽略掉，假設沒問題，存疑；

對于3直接看Hive代碼了，假設沒1的問題，Hive在polltask的過程中有一個Bug（HIVE-4000），就是runningQueue不是線程安全的，可能導緻racecondition進而會block住Hive；并且從

context switch/sec：

<a href="http://blog.51cto.com/attachment/201310/000430922.png" target="_blank"></a>

和Interupted/sec：

<a href="http://blog.51cto.com/attachment/201310/000458508.png" target="_blank"></a>

上看确實維護後降低了，也就是Sleep時間（此處Hive代碼注釋錯誤，每2秒而不是10秒進行一次poll）降低了，但是如果是Bug那應該是随機的，為什麼單單這一台在維護之前有問題，是以這個解釋不通，那這個cs降低應該是“果”而不是“因”，是以最可能的還是1，2網絡層面的問題

問題分析到這裡雖然還沒有一個完美的答案，但是還是暴露一些問題：比如參數不統一，比如一些不合理的設定和監控的缺失，不過對HIVE/MAPREDUCE/HDFS梳理更清晰了.經驗值确實值1000了：）

本文轉自MIKE老畢 51CTO部落格，原文連結：http://blog.51cto.com/boylook/1303926，如需轉載請自行聯系原作者