1. 程式人生 > >hadoop1.0 TaskTracker因為分散式快取導致記憶體洩露的一次問題排查

hadoop1.0 TaskTracker因為分散式快取導致記憶體洩露的一次問題排查

       上週五同事到公司說凌晨的時候有值班同事打電話給他,有部分job卡住了,運行了很長時間都沒執行完成,由於是凌晨,他沒來得及詳細的檢視日誌,簡單的把有問題的tasktracker重啟了一下,只有一個節點的TaskTracker程序停掉,讓我查一下具體是什麼問題。以下是排查過程:

1、登陸到停掉TT程序的處理機

(1)、檢視磁碟空間


磁碟沒有出現空間不足的情況。 

(2)、top檢視負載和記憶體使用情況:


根據上圖看出記憶體和負載都不算高,也不存在殭屍程序。

2、檢視程序日誌

1、log4j日誌:

2014-11-28 06:47:43,813 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201406171104_5451817_m_001292_0 which needs 1 slots
2014-11-28 06:47:43,813 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 3 and trying to launch attempt_201406171104_5451817_m_001292_0 which needs 1 slots
2014-11-28 06:47:43,814 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201406171104_5451797_m_-1554592361
2014-11-28 06:47:43,814 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201406171104_5451797_m_-1554592361 spawned.
2014-11-28 06:47:43,821 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /data2/hadoop/local/ttprivate/taskTracker/optimus/jobcache/job_201406171104_5451797/attempt_201406171104_5451797_m_000521_0/taskjvm.sh
2014-11-28 06:47:43,992 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.39.4.178:50060, dest: 10.39.5.241:47487, bytes: 18, op: MAPRED_SHUFFLE, cliID: attempt_201406171104_5450184_m_001640_0, duration: 235398
2014-11-28 06:47:44,317 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.39.4.178:50060, dest: 10.39.0.140:60631, bytes: 18, op: MAPRED_SHUFFLE, cliID: attempt_201406171104_5450184_m_001640_0, duration: 163982
2014-11-28 06:47:44,580 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201406171104_5451797_m_-1554592361 given task: attempt_201406171104_5451797_m_000521_0
2014-11-28 06:47:44,895 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.39.4.178:50060, dest: 10.39.4.164:50407, bytes: 18, op: MAPRED_SHUFFLE, cliID: attempt_201406171104_5450184_m_001640_0, duration: 168406
2014-11-28 06:47:45,057 INFO org.apache.hadoop.mapred.TaskTracker: SHUTDOWN_MSG:


日誌沒有出現異常。

2、由於程序已經停掉了,所以沒法檢視程序堆疊和記憶體對映資訊,不過我們在配置hadoop程序的時候,JVM引數處啟動了gc日誌列印:

vim /etc/bashrc

export JAVA_HOME=/usr/local/jdk1.6.0_21
export JRE_HOME=/usr/local/jdk1.6.0_21/jre
export CLASSPATH=.:$JAVA_HOME/lib:$JAVA_HOME/jre/lib
export HADOOP_HOME=/usr/local/hadoop-0.20.203.0
export HADOOP_LOG_DIR=/data0/hadoop/log
export HADOOP_PID_DIR=/data0/hadoop/pid
export PATH=$JAVA_HOME/bin:$JAVA_HOME/jre/bin:$HADOOP_HOME/bin:$PATH
ulimit -u 65535
export HADOOP_DATANODE_OPTS=" -Xmx4096m -verbose:gc -Xloggc:/data0/hadoop/gclog/datanode.gc.log -XX:ErrorFile=/data0/hadoop/gclog/hs_err_pid.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError "
export HADOOP_TASKTRACKER_OPTS=" -Xmx4096m -verbose:gc -Xloggc:/data0/hadoop/gclog/tasktracker.gc.log -XX:ErrorFile=/data0/hadoop/gclog/hs_err_pid.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError "

以下是gc日誌資訊:

2014-11-28T06:47:08.025+0800: 26433049.397: [Full GC [PSYoungGen: 1340224K->1286605K(1368576K)] [PSOldGen: 2796223K->2796223K(2796224K)] 4136447K->4082829K(4164800K) [PSPermGen: 21554K->21553K(21568K)]      GC time would exceed GCTimeLimit of 98%
, 5.5652750 secs] [Times: user=0.00 sys=5.56, real=5.57 secs]
2014-11-28T06:47:18.126+0800: 26433059.499: [Full GC [PSYoungGen: 1340224K->1340224K(1368576K)] [PSOldGen: 2796223K->2796223K(2796224K)] 4136447K->4136447K(4164800K) [PSPermGen: 21554K->21554K(21568K)], 6.6131270 secs] [Times: user=0.00 sys=6.61, real=6.61 secs]
2014-11-28T06:47:24.740+0800: 26433066.112: [Full GC [PSYoungGen: 1340224K->1286378K(1368576K)] [PSOldGen: 2796223K->2796223K(2796224K)] 4136447K->4082602K(4164800K) [PSPermGen: 21554K->21553K(21568K)], 5.5440730 secs] [Times: user=0.00 sys=5.55, real=5.55 secs]
2014-11-28T06:47:30.994+0800: 26433072.367: [Full GC [PSYoungGen: 1340224K->1340224K(1368576K)] [PSOldGen: 2796223K->2796223K(2796224K)] 4136447K->4136447K(4164800K) [PSPermGen: 21554K->21554K(21568K)], 6.7307300 secs] [Times: user=0.00 sys=6.73, real=6.73 secs]
2014-11-28T06:47:37.725+0800: 26433079.098: [Full GC [PSYoungGen: 1340224K->1287718K(1368576K)] [PSOldGen: 2796223K->2796223K(2796224K)] 4136447K->4083942K(4164800K) [PSPermGen: 21554K->21553K(21568K)], 5.7407480 secs] [Times: user=0.00 sys=5.75, real=5.74 secs]
Heap
 PSYoungGen      total 1368576K, used 1330631K [0x00007f66b3ab0000, 0x00007f6709000000, 0x00007f6709000000)
  eden space 1340224K, 99% used [0x00007f66b3ab0000,0x00007f6704e21d20,0x00007f6705780000)
  from space 28352K, 0% used [0x00007f6705780000,0x00007f6705780000,0x00007f6707330000)
  to   space 29504K, 0% used [0x00007f6707330000,0x00007f6707330000,0x00007f6709000000)
 PSOldGen        total 2796224K, used 2796223K [0x00007f6609000000, 0x00007f66b3ab0000, 0x00007f66b3ab0000)
  object space 2796224K, 99% used [0x00007f6609000000,0x00007f66b3aaffe8,0x00007f66b3ab0000)
 PSPermGen       total 21760K, used 21574K [0x00007f6603c00000, 0x00007f6605140000, 0x00007f6609000000)
  object space 21760K, 99% used [0x00007f6603c00000,0x00007f6605111a98,0x00007f6605140000)

在程序停掉之前老年代記憶體佔用了99%,而且執行了FGC,FGC佔用的時間超過了GC時間限制98%。

從這裡看出,問題是出在TaskTracker程序由於老年代記憶體滿了,一直在進行FGC,而且FGC是stop the world的,即FGC期間程序是無法提供對外服務的,這就是job任務卡住的根本原因。既然找到了是因為TaskTracker程序堆記憶體的原因,那麼是什麼東西導致堆記憶體被佔滿,我們在配置TaskTracker堆記憶體的時候配置了4G記憶體,按理說是完全夠用的,難不成有記憶體洩露,為了確認是不是記憶體洩露,需要dump程序的記憶體資訊,登陸到另外一個TaskTracker程序存活的節點,執行jstat -gcutil ${pid}:

[[email protected] ~]$ jstat -gcutil 27617
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00 100.00 100.00  99.85 621679 20840.395 47500 251938.770 272779.165
  0.00   0.00  78.03 100.00  99.76 621679 20840.395 47500 251945.371 272785.766
  0.00   0.00  78.41 100.00  99.76 621679 20840.395 47500 251945.371 272785.766
  0.00   0.00  78.77 100.00  99.76 621679 20840.395 47500 251945.371 272785.766

令人很驚訝的是看似正常的節點,是乎也存在相同的問題,存在記憶體洩露,老年代記憶體佔用已經100%了,並一直在執行FGC。

執行:

jmap -histo:live 27617  > jmap.log 


從jmap看出,TrackerDistributedCacheManager$CacheStatus和TaskDistributedCacheManager$CacheFile例項有100多萬個,TaskDistributedCacheManager例項有86萬個,這幾個物件都涉及到tasktracker的分散式快取,難不成是分散式快取有問題。

在hadoop的jira上面搜了一下cachestatus,果然搜到了:

根據jira上面的說明job在TT上面初始化的時候會以jobId為key,TaskDistributedCacheManager為value被設定到jobArchives的map物件中, 但是job完成之後,TT沒有立即清除jobArchives物件中相關job的分散式快取資訊,這個問題要解決很簡單,只需要在job完成之後清除分散式快取就可以了,jira中又對應的patch。

相關推薦

hadoop1.0 TaskTracker因為分散式快取導致記憶體洩露問題排查

       上週五同事到公司說凌晨的時候有值班同事打電話給他,有部分job卡住了,運行了很長時間都沒執行完成,由於是凌晨,他沒來得及詳細的檢視日誌,簡單的把有問題的tasktracker重啟了一下,只有一個節點的TaskTracker程序停掉,讓我查一下具體是什麼問題。以

Java Spring Boot 2.0實戰Redis分散式快取與底層API架構

《阿里巴巴Java Spring Boot 2.0開發實戰課程》10課 本期分享專家:徐雷—阿里巴巴雲棲Java講師,MongoDB講師 本期分享主題:Java Spring Boot 2.0實戰Redis分散式快取與底層API架構(面試題) 內容概要:Redis分散式高併發快取,高併發架構的必備技術!

Java記憶體管理之記憶體洩露是什麼?什麼情況下會導致記憶體洩露

文章目錄 1. 靜態類的使用 2. 資源連線的使用 3. 監聽器的使用 雖然Java擁有垃圾回收機制,但同樣會出現記憶體洩露問題,我們說一下比較主要的三種情況。 1. 靜態類的使用 諸如 HashMap、Vector 等集

handler導致記憶體洩露的真正原因

handler是我們在更新UI時經常使用到的類,但是不注意的話,很容易就導致記憶體洩露,最後導致OOM,故現在探究下handler導致記憶體洩露的原因及有哪些常用的解決辦法。 先看下面一段程式碼:  可以看到這段程式碼編輯器為我們標出了黃色,並且提示如下: Th

String 使用不當可能導致記憶體洩露

String是Java中一個比較基礎的類,每一個開發人員都會經常接觸到。而且,String也是面試中經常會考的知識點。String有很多方法,有些方法比較常用,有些方法不太常用。 今天介紹一個String使用不當可能導致記憶體洩露的問題,主要圍繞其subString

安卓Handler當做內部類,導致記憶體洩露的問題

this handler should be static or leaks might occur   How to Leak a Context: Handlers & Inner Classes Context是怎麼洩露的:Handlers & In

ios開發之使用block引發迴圈引用導致記憶體洩露

// // JLPerson.h // BlockTest // // Created by Mac on 15-3-28. // Copyright (c) 2015年 vxinyou. All rights reserved. // #import typedef void (^MyBloc

使用EXIT(0) 直接退出後,出現記憶體洩露情況

使用EXIT(0) 退出程式時,跳出以下記憶體洩露資訊: Detected memory leaks! Dumping objects -> f:\sp\vctools\vc7libs\ship\atlmfc\src\mfc\strcore.cpp(141) :

Direct ByteBuffer可能會導致記憶體洩露的原因

Direct ByteBuffer是在不是在Java Heap分配記憶體,而是在C Heap分配記憶體,但Direct ByteBuffer分配出去的記憶體其實也是由GC負責回收的,Hotspot在GC時會掃描Direct ByteBuffer物件是否有引用,如沒有則回收其

android中不小心使用靜態變數會導致記憶體洩露

     在android 專案開發過程中,不小心可能就會導致activity的記憶體洩露,即使使用者在使用APP的時候並沒有感受到記憶體洩露給APP帶來毀滅性的奔潰,但我們開發者可以通過除錯能夠很明顯的看到有些佔用的記憶體死也GC不掉。      OK ,隔壁家老伍來講解

iOS開發運用block時何時會導致記憶體洩露問題???

為什麼block容易出現記憶體洩露,根本原因是存在物件間的迴圈引用問題(物件a強引用物件b,物件b強引用物件a)。接下來看看以下幾種情況。 1. 結論:會出現記憶體洩露。這也最常見的block迴

inet_ntoa導致記憶體洩露

環境:     cpu: ARM7      OS:vxworks      語言:C語言    vxworks中inet_ntoa的實現程式碼如下 char *inet_ntoa ( struct in_addr inetAddress /* inet add

分散式事務不理解?給你講清楚!

分散式事務不理解?一次給你講清楚! victor zheng 搜雲庫技術團隊 昨天 搜雲庫技術團隊 關注送4000G架構師視訊 關注 來源:juejin.im/post/5baa54e1f265da0ac2566fb2  整編:搜雲庫技術團

jquery校驗 remote快取 remote只驗證 解決辦法

    jquery校驗,為了實現非同步使用者名稱是否存在功能,往往要用 jquery remote方法,然而,用remote方法,往往會有快取,只請求一次,即使內容改變,錯誤結果還是一樣。 折騰了兩天,什麼修改jquery原始檔,或者加程式碼清空第一次產生的快取,各種辦法

關於Netty+Gson造成記憶體洩露的分析排查

最近做了一個內部系統之間的資料同步伺服器,client端通過socket傳送經過壓縮的json資料到server端,server完成資料解碼和儲存。server架構:netty+Gson解碼 在做壓力測試的時候,竟然發現server記憶體洩露。分析記憶體洩露的時候,其實我

基於openapi3.0的yaml檔案生成java程式碼的實踐

在github上看了swagger-api專案(https://github.com/swagger-api/swagger-codegen)中的一些文件以及swagger-codegen的使用說明,還是覺得有些麻煩,該專案中有提到使用swagger-codeg

排查Java專案記憶體洩漏的過程

發現問題 公司自己維護的服務三四個,有的服務還分多個節點,自己也有幾個私人伺服器,所以為了能實時知道各個伺服器的情況,就使用ServerStatus做了個雲探針,功能很簡單,能實時的監控每個伺服器的記憶體、cpu、硬碟、流量的使用情況,如下 雖然只有幾個

排查線上程式記憶體的忽高忽低,又是大集合惹禍了

## 一:背景 ### 1. 講故事 昨天繼續還技術債,優化一輪後的程式拉到線上後記憶體繼續忽高忽低,低的時候20G,高的時候30G,過了一會又下降了幾個G,毫無疑問,程式中有什麼集合或者什麼操作佔用了大量記憶體,所以準備在28,29G的時候抓dump分析分析。 ## 二:解決思路 從快照中找

【直播預告】:Java Spring Boot實戰系列課程(第十講):Spring Boot 2.0實戰高併發分散式快取

內容概要:Redis作為開源分散式高併發快取,在網際網路公司高併發系統中廣泛使 用,本次課程講解如何使用最新的Java Spring Data實戰Redis,以及底層API的實現原始碼。主講人:徐雷(阿里雲棲特邀Java專家)直播時間:2019年1月1日 週二 今晚20:00直播地點:【阿里Java技術進階】

Mybatis一級快取導致分散式環境下的查詢髒資料

    Mybatis一級快取,也稱本地快取,預設是SqlSession級別的快取。在一次程式與資料庫的會話(Sqlsession)中,mybatis會維護一個以hashmap為儲存結構的一級快取,在這個會話中,只要在兩次相同條件的查詢中間,這個會話裡沒有出現增刪改的操作,那