碼上快樂

相關內容    簡體    繁體

由hbase.client.scanner.caching參數引發的血案（轉）

本文轉載自   查看原文   2017-03-17 09:22   1776    HBase

轉自：http://blog.csdn.net/rzhzhz/article/details/7536285

環境描述

Hadoop 0.20.203.0
Hbase 0.90.3
Hive 0.80.1

 

問題描述

     前幾天，在HIVE執行SQL查詢的時候出現了一個很奇怪的問題：就是每個SQL（涉及到MapReduce的SQL任務）在執行到某個百分比的時候，整個JOB會出現假死的情況。

 

[java]  view plain  copy
 
  1. 2012-04-28 18:22:33,661 Stage-1 map = 0%, reduce = 0%  
  2. 2012-04-28 18:22:59,760 Stage-1 map = 25%, reduce = 0%  
  3. 2012-04-28 18:23:04,782 Stage-1 map = 38%, reduce = 0%  
  4. 2012-04-28 18:23:07,796 Stage-1 map = 50%, reduce = 0%  
  5. 2012-04-28 18:23:08,801 Stage-1 map = 50%, reduce = 8%  
  6. 2012-04-28 18:23:17,839 Stage-1 map = 50%, reduce = 17%  
  7. 2012-04-28 18:23:19,848 Stage-1 map = 63%, reduce = 17%  
  8. 2012-04-28 18:23:32,909 Stage-1 map = 63%, reduce = 21%  
  9. 2012-04-28 18:23:57,017 Stage-1 map = 75%, reduce = 21%  
  10. 2012-04-28 18:24:09,075 Stage-1 map = 75%, reduce = 25%  
  11. 2012-04-28 18:25:09,397 Stage-1 map = 75%, reduce = 25%  
  12. 2012-04-28 18:26:09,688 Stage-1 map = 75%, reduce = 25%  
  13. 2012-04-28 18:27:09,980 Stage-1 map = 75%, reduce = 25%  
  14. 2012-04-28 18:28:10,262 Stage-1 map = 75%, reduce = 25%  
  15. 2012-04-28 18:29:10,522 Stage-1 map = 75%, reduce = 25%  
  16. 2012-04-28 18:30:10,742 Stage-1 map = 75%, reduce = 25%  
  17. 2012-04-28 18:31:10,985 Stage-1 map = 75%, reduce = 25%  
  18. 2012-04-28 18:32:11,238 Stage-1 map = 75%, reduce = 25%  
  19. 2012-04-28 18:33:11,467 Stage-1 map = 75%, reduce = 25%  
  20. 2012-04-28 18:34:11,731 Stage-1 map = 75%, reduce = 25%  
  21. 2012-04-28 18:35:11,968 Stage-1 map = 75%, reduce = 25%  
  22. 2012-04-28 18:36:12,213 Stage-1 map = 75%, reduce = 25%  
  23. 2012-04-28 18:37:12,508 Stage-1 map = 75%, reduce = 25%  
  24. 2012-04-28 18:38:12,747 Stage-1 map = 75%, reduce = 25%  
  25. 2012-04-28 18:39:12,970 Stage-1 map = 75%, reduce = 25%  
  26. 2012-04-28 18:40:13,205 Stage-1 map = 75%, reduce = 25%  

之前幾天還跑得挺好的，沒有出現這種情況，然后是偶爾出現，到最后變成是幾乎每個JOB都這樣。

很頭疼，檢查了所有的日志（包括hadoop，hbase和hive），日志卻沒有任何異常。唯一讓人有點疑慮的日志就是TaskTracker中這樣的提示

[java]  view plain  copy
 
  1. 2012-04-28 18:31:53,879 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  2. 2012-04-28 18:31:56,883 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  3. 2012-04-28 18:31:59,887 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  4. 2012-04-28 18:32:02,892 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  5. 2012-04-28 18:32:05,897 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  6. 2012-04-28 18:32:08,902 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  7. 2012-04-28 18:32:11,906 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  8. 2012-04-28 18:32:14,910 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  9. 2012-04-28 18:32:17,915 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  10. 2012-04-28 18:32:20,920 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  11. 2012-04-28 18:32:23,924 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  12. 2012-04-28 18:32:26,929 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  13. 2012-04-28 18:32:29,934 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  14. 2012-04-28 18:32:32,938 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  15. 2012-04-28 18:32:35,943 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  16. 2012-04-28 18:32:38,948 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  17. 2012-04-28 18:32:41,953 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  18. 2012-04-28 18:32:44,957 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  19. 2012-04-28 18:32:47,961 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  20. 2012-04-28 18:32:50,966 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  21. 2012-04-28 18:32:53,970 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  22. 2012-04-28 18:32:56,974 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  23. 2012-04-28 18:32:59,979 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  24. 2012-04-28 18:33:02,983 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  25. 2012-04-28 18:33:05,987 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  26. 2012-04-28 18:33:08,992 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  27. 2012-04-28 18:33:11,997 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  28. 2012-04-28 18:33:15,001 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  29. 2012-04-28 18:33:18,006 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  30. 2012-04-28 18:33:21,011 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  31. 2012-04-28 18:33:24,015 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  32. 2012-04-28 18:33:27,020 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  33. 2012-04-28 18:33:30,025 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  34. 2012-04-28 18:33:33,029 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  35. 2012-04-28 18:33:36,034 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  36. 2012-04-28 18:33:39,038 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  37. 2012-04-28 18:33:42,043 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  38. 2012-04-28 18:33:45,047 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  39. 2012-04-28 18:33:48,051 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  40. 2012-04-28 18:33:51,057 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  
  41. 2012-04-28 18:33:54,062 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201204281725_0002_m_000002_0 0.0%  

 

查看日志無果，然后我很自然的想到了是不是網絡或者內存、cpu的問題，查看系統參數，也沒有出現異常的情況。

也懷疑過是否某個TT所在機器的性能問題，所以嘗試停止了一些TT，但問題依舊存在。

繼續糾結，完全不知道從何下手……

實在是沒辦法，只有在job監控頁面查找鎖定出現問題的task，記住其taskId，並追蹤到相應的child進程（運行task的jvm）並kill掉，查看方法如下

jps -mvll |grep taskId

（此時JT檢測到該task死亡並會重新分配該任務到其他TT）。最后奇跡發生了，該JOB順利的執行完畢。

[java]  view plain  copy
 
  1. 2012-04-28 18:40:51,324 Stage-1 map = 88%, reduce = 25%  
  2. 2012-04-28 18:41:04,364 Stage-1 map = 88%, reduce = 29%  
  3. 2012-04-28 18:41:31,448 Stage-1 map = 100%, reduce = 29%  
  4. 2012-04-28 18:41:43,485 Stage-1 map = 100%, reduce = 100%  

很意外，而且每個JOB假死時這個方法都湊效。從job監控界面看到假死的task都有一個備用的task也在運行。當時想到是hadoop本身的Speculative Task調度策略，然后就以為是hadoop本身的bug，還傻乎乎的去提bug……

等待無果，就只能自己動手了，從最簡單的hive-hbase-handler-0.8.1.jar（因為不需要分開部署，哈哈，我其實還是蠻懶的）開始，查源碼，加log。然后發現其實假死的task並沒有被掛起，其實它還一直在運作，只是運作速度很慢。而且瓶頸就在hbase scan數據的時候，每取一條數據需要70+ms，神啊幾十萬的數據，這么個速度不慢才怪。

此時問題又出現了，為什么其他task的讀取速度這么快呢？難道是本地數據的原因？

然后寫log才發現，出現假死情況的task所處理的數據所在的regionServer不是本地的regionServer，其實Speculative Task調度策略也起作用了，只是該task比較點背，第二個分配的task也不在數據所在的regionServer上。所以才出現了hbase讀取速度慢的原因。

但令人奇怪的是我明明在hbase-site.xml文件中設置了hbase.client.scanner.caching參數，scan數據的時候不應該是會在client端會有cache嗎？為什么log中提現的是每取一條數據都會消耗70+ms的時間？難道是參數沒有生效？

查看了scan的整個流程，hbase.client.scanner.caching的設置沒有任何問題。只能又拿hive-hbase-handler-0.8.1.jar開刀了，修改HiveHBaseTableInputFormat這個類，在實例化Scan的手動設置一個cache值，最后發布，運行！問題解決，cache生效了。

奇怪的說，callable在設置cache的時候明明是先看Scan是否設置了cache，如果沒設置就取配置文件中設置的值。為什么明明配置文件中設置了卻不生效呢？

郁悶的時候出去溜達了一圈，才恍然大悟，我光在server端設置了cache，client端並沒有設置，這個參數的名字這么明顯是client端的。腦殘了……

最后修改hadoop  conf目錄下的hbase-site.xml，問題解決。

 

結論

既然task所處理的數據所在的regionServer不是本地的regionServer時，取數據會比較慢，那就減少與非本地regionServer的交互次數。在保證內存足夠的情況下適當的設置cache值對mapreduce的處理速度會提高不少。但這個參數是在client端參數，設置時請務必在client端設置。


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 一個配置引發的血案 前++和后++引發的血案~~！！ 研發效能度量引發的血案 MySql的時區（serverTimezone）引發的血案 PYTHONIOENCODING = UTF-8 引發的血案 mybatis—— 一個空格引發的血案 MySQL5.6分區數量太多引發的血案【轉】 【轉】HBase中Zookeeper，RegionServer，Master，Client之間關系 一個EL IF表達式引發的血案 流的操作（一）視頻轉音頻引發的血案
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM