cdh4.6.0更新測試2-distribute cache bug fix

distribute cache purge阻塞task的bug測試。

cdh4.2.0:

測試方法：

local.cache.size=650

因為cachedir size和count是存在記憶體中的HashMap中的，把local.cache.size值設定的足夠小，在每次job運作時都會觸發delete distribute cache的操作。

又因為是private的，是同步删除，會造成task阻塞。

使用dd來構造1M個的小檔案至某一個cache dir目錄。觀察阻塞時間，bug可以重制。

<code>dir</code><code>=`</code><code>for</code> <code>i </code><code>in</code> <code>{1..11}; </code><code>do</code> <code>find</code> <code>/home/xxx/hard_disk/</code><code>${i}</code><code>/mapred/local</code> <code>-name </code><code>"*.jar"</code><code>; </code><code>done</code><code>|</code><code>grep</code> <code>cmdline-jmxclient-0.10.3.jar|</code><code>head</code> <code>-1|</code><code>xargs</code> <code>dirname</code><code>`</code>

<code>mkdir</code> <code>-p ${</code><code>dir</code><code>}</code><code>/dir</code><code>${ii}</code>

<code> </code><code>for</code> <code>i </code><code>in</code> <code>{1..10000};</code><code>do</code> <code>dd</code> <code>if</code><code>=</code><code>/dev/zero</code> <code>of=${</code><code>dir</code><code>}</code><code>/dir</code><code>${ii}/${i}.jar count=1 bs=10000;</code><code>done</code> <code>&</code>

通過inode可以看到檔案數量：

通過hive運作一個簡單sql(需要有mapred),觀察JT和TT日志：

Jt上相關日志：

Job setup阻塞超過10min以上,從job啟動到第一個map運作耗時724s,tt日志上可以觀察到delete distribute cache的操作

Jt log:

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>195</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: job_201404221851_0005: nMaps=</code><code>10</code> <code>nReduces=</code><code>3</code> <code>max=-</code><code>1</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>242</code> <code>INFO org.apache.hadoop.mapred.JobTracker: Job job_201404221851_0005 added successfully </code><code>for</code> <code>user </code><code>'hdfs'</code> <code>to queue </code><code>'default'</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>388</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: jobToken generated and stored with users keys in /tmp/mapred/system/job_201404221851_0005/jobToken</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>396</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: Input size </code><code>for</code> <code>job job_201404221851_0005 = </code><code>2454759843</code><code>. Number of splits = </code><code>10</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>397</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: tip:task_201404221851_0005_m_000000 has split on node:/</code><code>default</code><code>-rack/xxxxxx</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>400</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: job_201404221851_0005 LOCALITY_WAIT_FACTOR=</code><code>1.0</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>400</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: Job job_201404221851_0005 initialized successfully with </code><code>10</code> <code>map tasks and </code><code>3</code> <code>reduce tasks.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>07</code><code>:</code><code>22</code><code>,</code><code>402</code> <code>INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) </code><code>'attempt_201404221851_0005_m_000011_0'</code> <code>to tip task_201404221851_0005_m_000011, </code><code>for</code> <code>tracker </code><code>'tracker_xxxxx:localhost.localdomain/127.0.0.1:14522'</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>08</code><code>:</code><code>55</code><code>,</code><code>931</code> <code>INFO org.apache.hadoop.mapred.JobTracker: attempt_201404221851_0005_m_000011_0 is </code><code>93529</code> <code>ms debug.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>12</code><code>:</code><code>15</code><code>,</code><code>961</code> <code>INFO org.apache.hadoop.mapred.JobTracker: attempt_201404221851_0005_m_000011_0 is </code><code>293559</code> <code>ms debug.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>15</code><code>:</code><code>35</code><code>,</code><code>989</code> <code>INFO org.apache.hadoop.mapred.JobTracker: attempt_201404221851_0005_m_000011_0 is </code><code>493587</code> <code>ms debug.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>18</code><code>:</code><code>56</code><code>,</code><code>019</code> <code>INFO org.apache.hadoop.mapred.JobTracker: attempt_201404221851_0005_m_000011_0 is </code><code>693617</code> <code>ms debug.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>18</code><code>:</code><code>56</code><code>,</code><code>019</code> <code>INFO org.apache.hadoop.mapred.JobTracker: Launching task attempt_201404221851_0005_m_000011_0 timed out.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>11</code><code>:</code><code>32</code><code>:</code><code>03</code><code>,</code><code>508</code> <code>INFO org.apache.hadoop.mapred.JobInProgress$JobSummary: jobId=job_201404221851_0005,</code>

<code>submitTime=</code><code>1398222442091</code><code>,launchTime=</code><code>1398222442400</code><code>,firstMapTaskLaunchTime=</code><code>1398223166995</code><code>,</code>

<code>firstReduceTaskLaunchTime=</code><code>1398223895409</code><code>,firstJobSetupTaskLaunchTime=</code><code>1398222442401</code><code>,</code>

<code>firstJobCleanupTaskLaunchTime=</code><code>1398223920769</code><code>,finishTime=</code><code>1398223923508</code><code>,numMaps=</code><code>10</code><code>,numSlotsPerMap=</code><code>1</code><code>,numReduces=</code><code>3</code><code>,numSlotsPerReduce=</code><code>1</code><code>,user=hdfs,queue=</code><code>default</code><code>,status=SUCCEEDED,mapSlotSeconds=</code><code>202</code><code>,reduceSlotsSeconds=</code><code>82</code><code>,clusterMapCapacity=</code><code>27</code><code>,clusterReduceCapacity=</code><code>15</code>

cdh4.6.0：

由于在構造TrackerDistributedCacheManager的執行個體時，會執行個體化一個CleanupThread對象，在task運作中會啟動一個線程異步删除distribute cache，不會出現阻塞狀況。

<code>local</code><code>.cache.size= 20000000</code>

<code>mapreduce.tasktracker.cache.</code><code>local</code><code>.keep.pct=0.5</code>

<code>mapreduce.tasktracker.distributedcache.checkperiod=1</code>

在對應的cache dir中構造1M個小檔案，多次運作同一個job(private的distribute cache不會共享)，distribute cache會一直增大（HashMap中的值）達到指定大小時觀察purge行為（打開tt的debug log/-Dhadoop.root.logger=DEBUG,DRFA）

JT日志：

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>01</code><code>,</code><code>459</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: Job job_201404231547_0036 initialized successfully with </code><code>10</code> <code>map tasks and </code><code>3</code> <code>reduce tasks.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>01</code><code>,</code><code>614</code> <code>INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) </code><code>'attempt_201404231547_0036_m_000011_0'</code> <code>to tip task_201404231547_0036_m_000011, </code><code>for</code> <code>tracker </code><code>'tracker_gd6g12s116-hadooptest-datanode.idc.vipshop.com:localhost.localdomain/127.0.0.1:5580'</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>05</code><code>,</code><code>163</code> <code>INFO org.apache.hadoop.mapred.JobInProgress: Task </code><code>'attempt_201404231547_0036_m_000011_0'</code> <code>has completed task_201404231547_0036_m_000011 successfully.</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>37</code><code>,</code><code>437</code> <code>INFO org.apache.hadoop.mapred.JobInProgress$JobSummary: jobId=job_201404231547_0036,submitTime=</code><code>1398252421298</code><code>,launchTime=</code><code>1398252421458</code><code>,</code>

<code>firstMapTaskLaunchTime=</code><code>1398252425316</code><code>,firstReduceTaskLaunchTime=</code><code>1398252445408</code><code>,</code>

<code>firstJobSetupTaskLaunchTime=</code><code>1398252421609</code><code>,firstJobCleanupTaskLaunchTime=</code><code>1398252454770</code><code>,finishTime=</code><code>1398252457437</code><code>,numMaps=</code><code>10</code><code>,numSlotsPerMap=</code><code>1</code><code>,numReduces=</code><code>3</code><code>,</code>

<code>numSlotsPerReduce=</code><code>1</code><code>,user=hdfs,queue=</code><code>default</code><code>,status=SUCCEEDED,mapSlotSeconds=</code><code>189</code><code>,reduceSlotsSeconds=</code><code>26</code><code>,clusterMapCapacity=</code><code>27</code><code>,clusterReduceCapacity=</code><code>15</code>

<code>#從launch到第一個map運作間隔4s</code>

TT日志：

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>334</code> <code>WARN mapreduce.Counters: Group org.apache.hadoop.mapred.Task$Counter is deprecated. Use org.apache.hadoop.mapreduce.TaskCounter instead</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>335</code> <code>INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201404231547_0036_m_000011_0 task's state:UNASSIGNED</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>335</code> <code>INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201404231547_0036_m_000011_0 which needs </code><code>1</code> <code>slots</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>335</code> <code>INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : </code><code>9</code> <code>and trying to launch attempt_201404231547_0036_m_000011_0 which needs </code><code>1</code> <code>slots</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>396</code> <code>INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Creating 04b0f029-bce2-47ba-ae83-10cc837df172 in /home/vipshop/hard_disk/</code><code>10</code><code>/mapred/local/taskTracker/distcache/-5286275044420583325_-1383138604_240564650/bipcluster/tmp/hive-hdfs/hive_2014-</code><code>04</code><code>-23_19-</code><code>26</code><code>-56_911_7591593033694865463/-mr-</code><code>10003</code><code>-work-</code><code>2737216842579494997</code> <code>with rwxr-xr-x</code>

<code>/home/vipshop/hard_disk/</code><code>11</code><code>/mapred/local/taskTracker/hdfs/distcache/4862822815811779469_-33152971_235118471 as hdfs #1M個小檔案異步删除，沒有阻塞</code>

<code>2014</code><code>-</code><code>04</code><code>-</code><code>23</code> <code>19</code><code>:</code><code>27</code><code>:</code><code>00</code><code>,</code><code>997</code> <code>INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201404231547_0036_m_611176298</code>

從sar的日志可以看到删除distribute cache的時間和io情況：

結論：

cdh4.2.0中在删除private distribute cache時，是使用的同步的方法，會阻塞目前程序，造成job啟動異常（timed out,關于這個放在後面的blog講）。

cdh4.6.0使用了異步的方式，不會阻塞目前程序。

本文轉自菜菜光 51CTO部落格，原文連結：http://blog.51cto.com/caiguangguang/1401413，如需轉載請自行聯系原作者

cdh4.6.0更新測試2-distribute cache bug fix

繼續閱讀

nginx location中斜線的位置的重要性

Apache2.4.x 配置檔案詳解Apache配置需要了解如下：開始講解：

配置apache支援PHP（win7）

27 Best Free Eclipse Plug-ins for Java Developer to be ProductiveCode Quality PluginsText Editor PluginsDependency ManagementVersion Control Integration PluginsFramework Development Continuous Integration Related PluginsOther Utility Plugins

Java String.format方法的簡單使用

neo4j之cypher使用文檔

GitHub連夜封殺！這份阿裡 10W 字内部 Java 字面試手冊到底有多強？

spark/scala關于【資源檔案】加載方法概述外部檔案加載方案測試資源檔案打包入jar包中小結

mybatis_入門程式Mybatis入門

AOP程式設計_Android優雅權限架構(1)概念基礎，2021金三銀四前言正文大綱正文

Effective Java 8:通用程式設計

OOM三種類型

工廠模式-三種類型

【遞歸】高效率求2的n次幂

win10本地scala和spark安裝安裝scala安裝spark

scala (3) Function 和 Method