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