hadoop通过log分析mapreduce的过程及定位错误、分析问题

网上有很多mapreduce的源码解析以及执行过程，这里从相关的日志角度看mapreduce的执行过程，以便于在通过日志分析定位分析问题
先简单说一下mapreduce的执行过程，如下图：

1、应用程序客户端client准备作业(数据split划分，作业配置等)，并上传值HDFS中；并提交作业至JobTracker。

2、JobTracker根据job的配置信息(jobconf，split等)，创建Tasks，并放到任务队列中，等待调度，JobTracker会启动JobInProcess跟踪job的执行过程。

3、TaskTracker通过心跳到JobTracker获取相关的task，TaskTracker首先进行JOB_SETUP会从HDFS中获取执行的jar，
   然后对于获取的每一个task开启一个taskinprocess跟踪task的执行过程，TaskTracker会启动一个JVM执行map、reduce的相关逻辑。

下面结合JobTracker和TaskTracker的日志进行分析关键执行路径

hadoop-root-jobtracker-xxxxxx.log
#表示这个job包含三个map和1个reduce任务，jobid为 job_201212191009_0012
2012-12-19 13:46:40,478 INFO org.apache.hadoop.mapred.JobInProgress:   job_201212191009_0012: nMaps=3 nReduces=1 max=-1
2012-12-19 13:46:40,479 INFO org.apache.hadoop.mapred.JobTracker: Job job_201212191009_0012 added successfully for user 'root' to queue 'default'

2012-12-19 13:46:40,479 INFO org.apache.hadoop.mapred.AuditLogger: USER=root IP=10.1.1.28 OPERATION=SUBMIT_JOB

TARGET=job_201212191009_0012 RESULT=SUCCESS

#job的初始化，根据job的相关的配置信息（根据件job.jar，job.split，和job.xml，生成三个map task,一个reduce task，放到调度队列中）

2012-12-19 13:46:40,479 INFO org.apache.hadoop.mapred.JobTracker: Initializing job_201212191009_0012
2012-12-19 13:46:40,479 INFO org.apache.hadoop.mapred.JobInProgress: Initializing job_201212191009_0012
2012-12-19 13:46:40,525 INFO org.apache.hadoop.mapred.JobInProgress: jobToken generated and stored with users keys

in /var/hadoop2/hadoop-tmp/mapred/system/job_201212191009_0012/jobToken
2012-12-19 13:46:40,529 INFO org.apache.hadoop.mapred.JobInProgress: Input size for job job_201212191009_0012 = 525769586. Number of splits = 3
2012-12-19 13:46:40,529 INFO org.apache.hadoop.mapred.JobInProgress: tip: task_201212191009_0012_m_000000 has split on node:/default-rack/wxlab29
2012-12-19 13:46:40,529 INFO org.apache.hadoop.mapred.JobInProgress: tip: task_201212191009_0012_m_000001 has split on node:/default-rack/wxlab29
2012-12-19 13:46:40,530 INFO org.apache.hadoop.mapred.JobInProgress: tip: task_201212191009_0012_m_000002 has split on node:/default-rack/wxlab29
2012-12-19 13:46:40,530 INFO org.apache.hadoop.mapred.JobInProgress: job_201212191009_0012 LOCALITY_WAIT_FACTOR=1.0
2012-12-19 13:46:40,530 INFO org.apache.hadoop.mapred.JobInProgress: Job job_201212191009_0012 initialized successfully with 3 map tasks and 1 reduce tasks.




#增加一个JOB_SETUP的task给tasktracker节点做job的设置，比如从HDFS中获取执行的jar文件等，每个tasktracker在执行一个job开始时都必须进行JOB_SETUP

2012-12-19 13:46:40,831 INFO org.apache.hadoop.mapred.JobTracker: Adding task (JOB_SETUP) 'attempt_201212191009_0012_m_000004_0'

to tip task_201212191009_0012_m_000004,

for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:46:49,838 INFO org.apache.hadoop.mapred.JobInProgress:

Task 'attempt_201212191009_0012_m_000004_0' has completed task_201212191009_0012_m_000004 successfully.

#tasktraker心跳到jobtracker后，获取分配的task；hadoop默认情况下，每个tasktracker只有2个slots，所以只能同时分配2个map task给该taskNode执行

2012-12-19 13:46:49,840 INFO org.apache.hadoop.mapred.JobTracker: Adding task (MAP)

'attempt_201212191009_0012_m_000000_0' to tip  task_201212191009_0012_m_000000 , for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:46:49,840 INFO org.apache.hadoop.mapred.JobInProgress: Choosing data-local task task_201212191009_0012_m_000000
2012-12-19 13:46:49,841 INFO org.apache.hadoop.mapred.JobTracker: Adding task (MAP)
'attempt_201212191009_0012_m_000001_0' to tip task_201212191009_0012_m_000001 , for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:46:49,841 INFO org.apache.hadoop.mapred.JobInProgress: Choosing data-local task task_201212191009_0012_m_000001



#执行完成一个task后，空余一个slot，分配下一map task给该节点执行
2012-12-19 13:47:04,850 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201212191009_0012_m_000001_0'
has completed task_201212191009_0012_m_000001  successfully.
2012-12-19 13:47:04,852 INFO org.apache.hadoop.mapred.JobTracker: Adding task (MAP) 'attempt_201212191009_0012_m_000002_0'
to tip task_201212191009_0012_m_000002 , for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:47:04,852 INFO org.apache.hadoop.mapred.JobInProgress: Choosing data-local task task_201212191009_0012_m_000002



#taskNode map任务执行完成后，执行reduce task
2012-12-19 13:47:04,852 INFO org.apache.hadoop.mapred.JobTracker: Adding task ( REDUCE ) 'attempt_201212191009_0012_r_000000_0'
to tip task_201212191009_0012_r_000000 , for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:47:07,856 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201212191009_0012_m_000000_0'
has completed task_201212191009_0012_m_000000   successfully.
2012-12-19 13:47:10,860 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201212191009_0012_m_000002_0'
has completed task_201212191009_0012_m_000002  successfully.
2012-12-19 13:47:22,867 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201212191009_0012_r_000000_0'
has completed task_201212191009_0012_r_000000  successfully.


#执行完reduce任务后，进行相关的清理工作JOB_CLEANUP（把一些临时文件,如job history等，move到logs的done目录下，
表示job已经完成，后续可以通过./hadoop job -history output-dir查看job的执行历史情况，便于跟踪
2012-12-19 13:47:22,871 INFO org.apache.hadoop.mapred.JobTracker: Adding task ( JOB_CLEANUP ) 'attempt_201212191009_0012_m_000003_0'

to tip task_201212191009_0012_m_000003, for tracker 'tracker_wxlab29:localhost.localdomain/127.0.0.1:28696'
2012-12-19 13:47:28,876 INFO org.apache.hadoop.mapred.JobInProgress: Task 'attempt_201212191009_0012_m_000003_0' has completed

task_201212191009_0012_m_000003 successfully.
2012-12-19 13:47:28,877 INFO org.apache.hadoop.mapred.JobInProgress: Job job_201212191009_0012 has completed successfully.
2012-12-19 13:47:28,877 INFO org.apache.hadoop.mapred.JobInProgress$JobSummary: jobId=job_201212191009_0012,

submitTime=1355896000452,launchTime=1355896000530,firstMapTaskLaunchTime=1355896009840,

firstReduceTaskLaunchTime=1355896024852,firstJobSetupTaskLaunchTime=1355896000830,firstJobCleanupTaskLaunchTime=1355896042871,

finishTime=1355896048877,numMaps=3,numSlotsPerMap=1,numReduces=1,numSlotsPerReduce=1,user=root,queue=default,status=SUCCEEDED,

mapSlotSeconds=44,reduceSlotsSeconds=16,clusterMapCapacity=2,clusterReduceCapacity=2
2012-12-19 13:47:28,881 INFO org.apache.hadoop.mapred.JobHistory:

Moving file:/test/hadoop-0.20.204.0/logs/history/job_201212191009_0012_1355896000452_root_select+tbl1.key1%2Ctbl2.v09+..

.tbl2.v06%3D%272800%27%28Stage to file:/test/hadoop-0.20.204.0/logs/history/done/version-1/wxlab28_1355882990229_/2012/12/19/000000
2012-12-19 13:47:28,882 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_m_000000_0'
2012-12-19 13:47:28,882 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_m_000001_0'
2012-12-19 13:47:28,882 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_m_000002_0'
2012-12-19 13:47:28,883 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_m_000003_0'
2012-12-19 13:47:28,883 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_m_000004_0'
2012-12-19 13:47:28,883 INFO org.apache.hadoop.mapred.JobTracker: Removing task 'attempt_201212191009_0012_r_000000_0'
2012-12-19 13:47:28,887 INFO org.apache.hadoop.mapred.JobHistory: Moving file:/test/hadoop-0.20.204.0/logs/history/job_201212191009_0012_conf.xml

to file:/test/hadoop-0.20.204.0/logs/history/done/version-1/wxlab28_1355882990229_/2012/12/19/000000

hadoop-root-tasktracker-xxxxxx.log
#launch Job，初始化，从HDFS中下载job相关的jar，启动一个子的虚拟机运行
2012-12-19 14:01:15,296 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_ 201212191009_0012_m_000004_0   task's state:UNASSIGNED
2012-12-19 14:01:15,296 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_m_000004_0 which needs 1 slots
2012-12-19 14:01:15,296 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201212191009_0012_m_000004_0 which needs 1 slots
2012-12-19 14:01:15,343 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Creating 07a1028e-d708-4099-af92-ecf4b2564e98 in /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/distcache/1191307413421368883_526354753_833818610/wxlab28/tmp/hive-root/hive_2012-12-19_13-46-39_735_6112058870903323944/-mr-10003-work--3119353475737334056 with rwxr-xr-x
2012-12-19 14:01:15,352 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/tmp/hive-root/hive_2012-12-19_13-46-39_735_6112058870903323944/-mr-10003/07a1028e-d708-4099-af92-ecf4b2564e98#HIVE_PLAN07a1028e-d708-4099-af92-ecf4b2564e98 as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/distcache/1191307413421368883_526354753_833818610/wxlab28/tmp/hive-root/hive_2012-12-19_13-46-39_735_6112058870903323944/-mr-10003/07a1028e-d708-4099-af92-ecf4b2564e98
2012-12-19 14:01:15,353 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/tmp/hive-root/hive_2012-12-19_13-46-39_735_6112058870903323944/-mr-10003/07a1028e-d708-4099-af92-ecf4b2564e98#HIVE_PLAN07a1028e-d708-4099-af92-ecf4b2564e98 as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/distcache/1191307413421368883_526354753_833818610/wxlab28/tmp/hive-root/hive_2012-12-19_13-46-39_735_6112058870903323944/-mr-10003/07a1028e-d708-4099-af92-ecf4b2564e98
2012-12-19 14:01:15,375 INFO org.apache.hadoop.mapred.JobLocalizer: Initializing user root on this TT.
2012-12-19 14:01:16,037 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Creating hive-builtins-0.9.0.jar in /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/4116514918261870944_1448929340_833818786/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-builtins-0.9.0.jar-work-6629786413938296570 with rwxr-xr-x
2012-12-19 14:01:16,048 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Extracting /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/4116514918261870944_1448929340_833818786/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-builtins-0.9.0.jar-work-6629786413938296570/hive-builtins-0.9.0.jar to /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/4116514918261870944_1448929340_833818786/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-builtins-0.9.0.jar-work-6629786413938296570
2012-12-19 14:01:16,058 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-builtins-0.9.0.jar as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/4116514918261870944_1448929340_833818786/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-builtins-0.9.0.jar
2012-12-19 14:01:16,061 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Creating hbase-0.94.0.jar in /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-5402046291038797272_879232748_833818802/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hbase-0.94.0.jar-work--8944004131205652253 with rwxr-xr-x
2012-12-19 14:01:16,168 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Extracting /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-5402046291038797272_879232748_833818802/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hbase-0.94.0.jar-work--8944004131205652253/hbase-0.94.0.jar to /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-5402046291038797272_879232748_833818802/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hbase-0.94.0.jar-work--8944004131205652253
2012-12-19 14:01:16,856 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hbase-0.94.0.jar as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-5402046291038797272_879232748_833818802/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hbase-0.94.0.jar
2012-12-19 14:01:17,004 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Creating hive-hbase-handler-0.9.0.jar in /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-7444155095864525423_-1661283310_833818926/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-hbase-handler-0.9.0.jar-work-977178928309628470 with rwxr-xr-x
2012-12-19 14:01:17,016 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Extracting /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-7444155095864525423_-1661283310_833818926/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-hbase-handler-0.9.0.jar-work-977178928309628470/hive-hbase-handler-0.9.0.jar to /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-7444155095864525423_-1661283310_833818926/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-hbase-handler-0.9.0.jar-work-977178928309628470
2012-12-19 14:01:17,033 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-hbase-handler-0.9.0.jar as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/-7444155095864525423_-1661283310_833818926/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/hive-hbase-handler-0.9.0.jar
tmp/mapred/local/taskTracker/root/distcache/6190772022211013073_849301084_833818971/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/zookeeper-3.4.3.jar-work-2040726136439130217
2012-12-19 14:01:17,292 INFO org.apache.hadoop.filecache.TrackerDistributedCacheManager: Cached hdfs://wxlab28:9100/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/zookeeper-3.4.3.jar as /var/hadoop2/hadoop-tmp/mapred/local/taskTracker/root/distcache/6190772022211013073_849301084_833818971/wxlab28/var/hadoop2/hadoop-tmp/mapred/staging/root/.staging/job_201212191009_0012/libjars/zookeeper-3.4.3.jar
2012-12-19 14:01:17,353 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_m_109531397
2012-12-19 14:01:17,354 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_m_109531397 spawned.

#启动一个虚拟机运行该Node的JOB初始化任务
2012-12-19 14:01:17,357 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_m_000004_0/taskjvm.sh
2012-12-19 14:01:18,289 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_m_109531397 given task: attempt_201212191009_0012_m_000004_0
2012-12-19 14:01:22,218 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000004_0 0.0% setup
2012-12-19 14:01:22,220 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_m_000004_0 is done.
2012-12-19 14:01:22,220 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_m_000004_0  was -1
2012-12-19 14:01:22,221 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-12-19 14:01:22,405 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_m_109531397 exited with exit code 0. Number of tasks it ran: 1

#Launch map  task，只能同时运行两个map任务
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201212191009_0012_m_000000_0 task's state:UNASSIGNED
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201212191009_0012_m_000001_0 task's state:UNASSIGNED
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_m_000000_0 which needs 1 slots
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: Received KillTaskAction for task: attempt_201212191009_0012_m_000004_0
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201212191009_0012_m_000000_0 which needs 1 slots
2012-12-19 14:01:24,306 INFO org.apache.hadoop.mapred.TaskTracker: About to purge task: attempt_201212191009_0012_m_000004_0
2012-12-19 14:01:24,307 INFO org.apache.hadoop.mapred.IndexCache: Map ID attempt_201212191009_0012_m_000004_0 not found in cache
2012-12-19 14:01:24,307 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_m_000001_0 which needs 1 slots
2012-12-19 14:01:24,307 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 1 and trying to launch attempt_201212191009_0012_m_000001_0 which needs 1 slots
2012-12-19 14:01:24,312 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_m_-1172612431
2012-12-19 14:01:24,313 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_m_-1172612431 spawned.
2012-12-19 14:01:24,313 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_m_224943722
2012-12-19 14:01:24,314 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_m_224943722 spawned.

##启动两个JVM运行两个map操作
2012-12-19 14:01:24,316 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_m_000000_0/taskjvm.sh
2012-12-19 14:01:24,317 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_m_000001_0/taskjvm.sh
2012-12-19 14:01:25,238 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_m_-1172612431 given task: attempt_201212191009_0012_m_000000_0
2012-12-19 14:01:25,240 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_m_224943722 given task: attempt_201212191009_0012_m_000001_0
2012-12-19 14:01:32,144 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000000_0 0.0% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:0+67108864
2012-12-19 14:01:32,165 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000001_0 0.26760873% hdfs://wxlab28:9100/user/hive/warehouse/hive_hly_temp8/0011_3_2012022_1340208778506_1.order:67108864+67108864
2012-12-19 14:01:35,148 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000000_0 0.5% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:134217728+67108864
2012-12-19 14:01:35,170 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000001_0 0.8028262% hdfs://wxlab28:9100/user/hive/warehouse/hive_hly_temp8/0011_3_2012022_1340208778506_1.order:201326592+49445731
2012-12-19 14:01:38,151 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000000_0 0.75% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:201326592+67108864
2012-12-19 14:01:38,174 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000001_0 0.8028262% hdfs://wxlab28:9100/user/hive/warehouse/hive_hly_temp8/0011_3_2012022_1340208778506_1.order:201326592+49445731
2012-12-19 14:01:38,177 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000001_0 0.8028262% hdfs://wxlab28:9100/user/hive/warehouse/hive_hly_temp8/0011_3_2012022_1340208778506_1.order:201326592+49445731
2012-12-19 14:01:38,178 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_m_000001_0 is done.
2012-12-19 14:01:38,178 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_m_000001_0  was 54154041
2012-12-19 14:01:38,178 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 1
2012-12-19 14:01:38,308 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_m_224943722 exited with exit code 0. Number of tasks it ran: 1

#launch 最后一个map task
2012-12-19 14:01:39,318 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201212191009_0012_m_000002_0 task's state:UNASSIGNED
2012-12-19 14:01:39,318 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_m_000002_0 which needs 1 slots
#launch reduce task
2012-12-19 14:01:39,318 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201212191009_0012_r_000000_0 task's state:UNASSIGNED
2012-12-19 14:01:39,318 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 1 and trying to launch attempt_201212191009_0012_m_000002_0 which needs 1 slots
2012-12-19 14:01:39,319 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_r_000000_0 which needs 1 slots
2012-12-19 14:01:39,319 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201212191009_0012_r_000000_0 which needs 1 slots
2012-12-19 14:01:39,324 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_m_-1876092175
2012-12-19 14:01:39,325 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_m_-1876092175 spawned.
2012-12-19 14:01:39,326 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_r_1270955257
2012-12-19 14:01:39,326 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_r_1270955257 spawned.

启动两个JVM运行分别map操作和reduce操作
2012-12-19 14:01:39,327 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_m_000002_0/taskjvm.sh
2012-12-19 14:01:39,329 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_r_000000_0/taskjvm.sh
2012-12-19 14:01:39,770 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_m_-1876092175 given task: attempt_201212191009_0012_m_000002_0
2012-12-19 14:01:40,246 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_r_1270955257 given task: attempt_201212191009_0012_r_000000_0
2012-12-19 14:01:41,155 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000000_0 0.75% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:201326592+67108864
2012-12-19 14:01:41,159 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000000_0 0.75% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:201326592+67108864
2012-12-19 14:01:41,160 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_m_000000_0 is done.
2012-12-19 14:01:41,160 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_m_000000_0  was 66686793
2012-12-19 14:01:41,160 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 1
2012-12-19 14:01:41,295 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_m_-1172612431 exited with exit code 0. Number of tasks it ran: 1
2012-12-19 14:01:43,307 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000002_0 0.0% hdfs://wxlab28:9100/user/hive/warehouse/table3/000000_0:268435456+6561807
2012-12-19 14:01:43,310 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_m_000002_0 is done.
2012-12-19 14:01:43,310 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_m_000002_0  was 1629920
2012-12-19 14:01:43,310 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-12-19 14:01:43,481 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_m_-1876092175 exited with exit code 0. Number of tasks it ran: 1
2012-12-19 14:01:46,938 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.1.1.29:50060, dest: 10.1.1.29:43245, bytes: 54154041, op: MAPRED_SHUFFLE, cliID: attempt_201212191009_0012_m_000001_0, duration: 344311888
2012-12-19 14:01:47,208 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 0.11111112% reduce > copy (1 of 3 at 8.61 MB/s) >
2012-12-19 14:01:48,876 INFO org.mortbay.log:  org.mortbay.io.nio.SelectorManager$SelectSet@399b08cc JVM BUG(s) - injecting delay3 times
2012-12-19 14:01:48,876 INFO org.mortbay.log:  org.mortbay.io.nio.SelectorManager$SelectSet@399b08cc JVM BUG(s) - recreating selector 3 times, canceled keys 48 times
2012-12-19 14:01:48,996 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.1.1.29:50060, dest: 10.1.1.29:43245, bytes: 66686793, op: MAPRED_SHUFFLE, cliID: attempt_201212191009_0012_m_000000_0, duration: 2048778539
2012-12-19 14:01:49,021 INFO org.apache.hadoop.mapred.TaskTracker.clienttrace: src: 10.1.1.29:50060, dest: 10.1.1.29:43245, bytes: 1629920, op: MAPRED_SHUFFLE, cliID: attempt_201212191009_0012_m_000002_0, duration: 14093527
2012-12-19 14:01:49,240 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 0.11111112% reduce > copy (1 of 3 at 8.61 MB/s) >
2012-12-19 14:01:49,453 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 0.11111112% reduce > copy (1 of 3 at 8.61 MB/s) >
2012-12-19 14:01:50,213 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 0.66729903% reduce > reduce
2012-12-19 14:01:53,220 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 0.8342909% reduce > reduce
2012-12-19 14:01:56,225 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 1.0% reduce > reduce
2012-12-19 14:01:56,228 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_r_000000_0 1.0% reduce > reduce
2012-12-19 14:01:56,229 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_r_000000_0 is done.
2012-12-19 14:01:56,229 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_r_000000_0  was -1
2012-12-19 14:01:56,230 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-12-19 14:01:56,368 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_r_1270955257 exited with exit code 0. Number of tasks it ran: 1

#launch 一个task做清理工作
2012-12-19 14:01:57,338 INFO org.apache.hadoop.mapred.TaskTracker: LaunchTaskAction (registerTask): attempt_201212191009_0012_m_000003_0 task's state:UNASSIGNED
2012-12-19 14:01:57,339 INFO org.apache.hadoop.mapred.TaskTracker: Trying to launch : attempt_201212191009_0012_m_000003_0 which needs 1 slots
2012-12-19 14:01:57,339 INFO org.apache.hadoop.mapred.TaskTracker: Received KillTaskAction for task: attempt_201212191009_0012_r_000000_0
2012-12-19 14:01:57,339 INFO org.apache.hadoop.mapred.TaskTracker: In TaskLauncher, current free slots : 2 and trying to launch attempt_201212191009_0012_m_000003_0 which needs 1 slots
2012-12-19 14:01:57,339 INFO org.apache.hadoop.mapred.TaskTracker: About to purge task: attempt_201212191009_0012_r_000000_0
2012-12-19 14:01:57,344 INFO org.apache.hadoop.mapred.JvmManager: In JvmRunner constructed JVM ID: jvm_201212191009_0012_m_-146665480
2012-12-19 14:01:57,345 INFO org.apache.hadoop.mapred.JvmManager: JVM Runner jvm_201212191009_0012_m_-146665480 spawned.
2012-12-19 14:01:57,348 INFO org.apache.hadoop.mapred.TaskController: Writing commands to /var/hadoop2/hadoop-tmp/mapred/local/ttprivate/taskTracker/root/jobcache/job_201212191009_0012/attempt_201212191009_0012_m_000003_0/taskjvm.sh
2012-12-19 14:01:58,364 INFO org.apache.hadoop.mapred.TaskTracker: JVM with ID: jvm_201212191009_0012_m_-146665480 given task: attempt_201212191009_0012_m_000003_0
2012-12-19 14:01:59,270 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000003_0 0.0%
2012-12-19 14:02:02,266 INFO org.apache.hadoop.mapred.TaskTracker: attempt_201212191009_0012_m_000003_0 0.0% cleanup
2012-12-19 14:02:02,269 INFO org.apache.hadoop.mapred.TaskTracker: Task attempt_201212191009_0012_m_000003_0 is done.
2012-12-19 14:02:02,269 INFO org.apache.hadoop.mapred.TaskTracker: reported output size for attempt_201212191009_0012_m_000003_0  was -1
2012-12-19 14:02:02,269 INFO org.apache.hadoop.mapred.TaskTracker: addFreeSlot : current free slots : 2
2012-12-19 14:02:02,454 INFO org.apache.hadoop.mapred.JvmManager: JVM : jvm_201212191009_0012_m_-146665480 exited with exit code 0. Number of tasks it ran: 1
2012-12-19 14:02:03,349 INFO org.apache.hadoop.mapred.TaskTracker: Received 'KillJobAction' for job: job_201212191009_0012
2012-12-19 14:02:03,350 INFO org.apache.hadoop.mapred.IndexCache: Map ID attempt_201212191009_0012_m_000003_0 not found in cache
2012-12-19 14:02:03,351 INFO org.apache.hadoop.mapred.UserLogCleaner: Adding job_201212191009_0012 for user-log deletion with retainTimeStamp:1355983323351