Hadoop源码分析(3): Hadoop的运行痕迹
在使用hadoop的时候，可能遇到各种各样的问题，然而由于hadoop的运行机制比较复杂，因而出现了问题的时候比较难于发现问题。
本文欲通过某种方式跟踪Hadoop的运行痕迹，方便出现问题的时候可以通过这些痕迹来解决问题。
一、环境的搭建
为了能够跟踪这些运行的痕迹，我们需要搭建一个特殊的环境，从而可以一步步的查看上一节提到的一些关键步骤所引起的变化。
我们首先搭建一个拥有一个NameNode(namenode:192.168.1.104)，三个DataNode(datanode01:192.168.1.105, datanode02:192.168.1.106, datanode03:192.168.1.107)的Hadoop环境，其中SecondaryNameNode和NameNode运行在同一台机器上。
对于这四台机器上的Hadoop，我们需要进行如下相同的配置：
- NameNode，SeondaryNameNode，JobTracker都应该运行在namenode:192.168.1.104机器上
- DataNode，TaskTracker，以及生成的Map和Reduce的Task JVM应该运行在datanode01, datanode02, datanode03上
- 数据共有三份备份
- HDFS以及Map-Reduce运行的数据放在/data/hadoop/dir/tmp文件夹下
|
<property> <name>fs.default.name</name> <value>hdfs://192.168.1.104:9000</value> </property> <property> <name>mapred.job.tracker</name> <value>192.168.1.104:9001</value> </property> <property> <name>dfs.replication</name> <value>3</value> </property> <property> <name>hadoop.tmp.dir</name> <value>/data/hadoopdir/tmp</value> <description>A base for other temporary directories.</description> </property> |
然而由于Map-Reduce过程相对复杂，为了能够对Map和Reduce的Task JVM进行远程的调试，从而能一步一步观察，因而对NameNode和三个DataNode有一些不同的配置：
对于NameNode:
- 设置mapred.job.reuse.jvm.num.tasks为-1，使得多个运行于同一个DataNode上的Map和Reduce的Task共用同一个JVM，从而方便对此JVM进行远程调试，并且不会因为多个Task JVM监听同一个远程调试端口而发生冲突
- 对于mapred.tasktracker.map.tasks.maximum和mapred.tasktracker.reduce.tasks.maximum的配置以DataNode上的为准
- 设置io.sort.mb为1M(原来为100M)，是为了在Map阶段让内存中的map output尽快的spill到文件中来，从而我们可以观察map的输出
- 设置mapred.child.java.opts的时候，即设置Task JVM的运行参数，添加远程调试监听端口8333
|
<property> <property> <property> <property> |
对于DataNode:
- 对于datanode01:192.168.1.105，设置同时运行的map task的个数(mapred.tasktracker.map.tasks.maximum)为1，同时运行的reduce task的个数(mapred.tasktracker.reduce.tasks.maximum)为0
- 对于datanode02:192.168.1.106，设置同时运行的map task的个数(mapred.tasktracker.map.tasks.maximum)为0，同时运行的reduce task的个数(mapred.tasktracker.reduce.tasks.maximum)为0
- 对于datanode02:192.168.1.107，设置同时运行的map task的个数(mapred.tasktracker.map.tasks.maximum)为0，同时运行的reduce task的个数(mapred.tasktracker.reduce.tasks.maximum)为1
- 之所以这样设置，是因为我们虽然可以控制多个Map task共用同一个JVM，然而我们不能控制Map task和Reduce Task也共用一个JVM。从而当Map task的JVM和Reduce Task的JVM同时在同一台机器上启动的时候，仍然会出现监听远程调用端口冲突的问题。
- 经过上面的设置，从而datanode01专门负责运行Map Task，datanode03专门负责运行Reduce Task，而datanode02不运行任何的Task，甚至连TaskTracker也不用启动了
- 对于Reduce Task设置mapred.job.shuffle.input.buffer.percent和mapred.job.shuffle.merge.percent为0.001，从而使得拷贝，合并阶段的中间结果都因为内存设置过小而写入硬盘，我们能够看到痕迹
- 设置io.sort.factor为2，使得在map task输出不多的情况下，也能触发合并。
除了对Map task和Reduce Task进行远程调试之外，我们还想对NameNode，SecondaryName，DataNode，JobTracker，TaskTracker进行远程调试，则需要修改一下bin/hadoop文件：
|
if [ "$COMMAND" = "namenode" ] ; then CLASS='org.apache.hadoop.hdfs.server.namenode.NameNode' HADOOP_OPTS="$HADOOP_OPTS $HADOOP_NAMENODE_OPTS -agentlib:jdwp=transport=dt_socket,address=8888,server=y,suspend=n" elif [ "$COMMAND" = "secondarynamenode" ] ; then CLASS='org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode' HADOOP_OPTS="$HADOOP_OPTS $HADOOP_SECONDARYNAMENODE_OPTS -agentlib:jdwp=transport=dt_socket,address=8887,server=y,suspend=n" elif [ "$COMMAND" = "datanode" ] ; then CLASS='org.apache.hadoop.hdfs.server.datanode.DataNode' HADOOP_OPTS="$HADOOP_OPTS $HADOOP_DATANODE_OPTS -agentlib:jdwp=transport=dt_socket,address=8886,server=y,suspend=n" …… elif [ "$COMMAND" = "jobtracker" ] ; then class="org".apache.hadoop.mapred.JobTracker HADOOP_OPTS="$HADOOP_OPTS $HADOOP_JOBTRACKER_OPTS -agentlib:jdwp=transport=dt_socket,address=8885,server=y,suspend=n" elif [ "$COMMAND" = "tasktracker" ] ; then class="org".apache.hadoop.mapred.TaskTracker HADOOP_OPTS="$HADOOP_OPTS $HADOOP_TASKTRACKER_OPTS -agentlib:jdwp=transport=dt_socket,address=8884,server=y,suspend=n" |
在进行一切实验之前，我们首先清空/data/hadoopdir/tmp以及logs文件夹。
二、格式化HDFS
格式化HDFS需要运行命令：bin/hadoop namenode –format
于是打印出如下的日志：
|
10/11/20 19:52:21 INFO namenode.NameNode: STARTUP_MSG: |
这个时候在NameNode的/data/hadoopdir/tmp下面出现如下的文件树形结构：
| +- dfs +- name +--- current +---- edits +---- fsimage +---- fstime +---- VERSION +---image +---- fsimage |
这个时候，DataNode的/data/hadoopdir/tmp中还是空的。
二、启动Hadoop
启动Hadoop需要调用命令bin/start-all.sh，输出的日志如下：
|
starting namenode, logging to logs/hadoop-namenode-namenode.out 192.168.1.106: starting datanode, logging to logs/hadoop-datanode-datanode02.out 192.168.1.105: starting datanode, logging to logs/hadoop-datanode-datanode01.out 192.168.1.107: starting datanode, logging to logs/hadoop-datanode-datanode03.out 192.168.1.104: starting secondarynamenode, logging to logs/hadoop-secondarynamenode-namenode.out starting jobtracker, logging to logs/hadoop-jobtracker-namenode.out 192.168.1.106: starting tasktracker, logging to logs/hadoop-tasktracker-datanode02.out 192.168.1.105: starting tasktracker, logging to logs/hadoop-tasktracker-datanode01.out 192.168.1.107: starting tasktracker, logging to logs/hadoop-tasktracker-datanode03.out |
从日志中我们可以看出，此脚本启动了NameNode, 三个DataNode，SecondaryName，JobTracker以及三个TaskTracker.
下面我们分别从NameNode和三个DataNode中运行jps -l，看看到底运行了那些java程序：
在NameNode中：
|
22214 org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode 22107 org.apache.hadoop.hdfs.server.namenode.NameNode 22271 org.apache.hadoop.mapred.JobTracker |
在datanode01中：
|
12580 org.apache.hadoop.mapred.TaskTracker 12531 org.apache.hadoop.hdfs.server.datanode.DataNode |
在datanode02中：
|
10548 org.apache.hadoop.hdfs.server.datanode.DataNode |
在datanode03中：
|
12593 org.apache.hadoop.hdfs.server.datanode.DataNode 12644 org.apache.hadoop.mapred.TaskTracker |
同我们上面的配置完全符合。
当启动了Hadoop以后，/data/hadoopdir/tmp目录也发生了改变，通过ls -R我们可以看到。
对于NameNode：
- 在name文件夹中，多了in_use.lock文件，说明NameNode已经启动了
- 多了nameseondary文件夹，用于存放SecondaryNameNode的数据
|
.: dfs ./dfs: name namesecondary ./dfs/name: current image in_use.lock ./dfs/name/current: edits fsimage fstime VERSION ./dfs/name/image: fsimage ./dfs/namesecondary: current image in_use.lock ./dfs/namesecondary/current: edits fsimage fstime VERSION ./dfs/namesecondary/image: fsimage |
对于DataNode:
- 多了dfs和mapred两个文件夹
- dfs文件夹用于存放HDFS的block数据的
- mapred用于存放Map-Reduce Task任务执行所需要的数据的。
|
.: dfs mapred ./dfs: data ./dfs/data: current detach in_use.lock storage tmp ./dfs/data/current: dncp_block_verification.log.curr VERSION ./dfs/data/detach: ./dfs/data/tmp: ./mapred: local ./mapred/local: |
当然随着Hadoop的启动，logs文件夹下也多个很多的日志：
在NameNode上，日志有：
- NameNode的日志：
- hadoop-namenode-namenode.log此为log4j的输出日志
- hadoop-namenode-namenode.out此为stdout和stderr的输出日志
- SecondaryNameNode的日志：
- hadoop-secondarynamenode-namenode.log此为log4j的输出日志
- hadoop-secondarynamenode-namenode.out此为stdout和stderr的输出日志
- JobTracker的日志：
- hadoop-jobtracker-namenode.log此为log4j的输出日志
- hadoop-jobtracker-namenode.out此为stdout和stderr的输出日志
在DataNode上的日志有(以datanode01为例子)：
- DataNode的日志
- hadoop-datanode-datanode01.log此为log4j的输出日志
- hadoop-datanode-datanode01.out此为stdout和stderr的输出日志
- TaskTracker的日志
- hadoop-tasktracker-datanode01.log此为log4j的输出日志
- hadoop-tasktracker-datanode01.out此为stdout和stderr的输出日志
下面我们详细查看这些日志中的有重要意义的信息：
在hadoop-namenode-namenode.log文件中，我们可以看到NameNode启动的过程：
|
Namenode up at: namenode/192.168.1.104:9000 //文件的数量 Number of files = 0 Number of files under construction = 0 //加载fsimage和edits文件形成FSNamesystem Image file of size 97 loaded in 0 seconds. Edits file /data/hadoopdir/tmp/dfs/name/current/edits of size 4 edits # 0 loaded in 0 seconds. Image file of size 97 saved in 0 seconds. Finished loading FSImage in 12812 msecs //统计block的数量和状态 Total number of blocks = 0 Number of invalid blocks = 0 Number of under-replicated blocks = 0 Number of over-replicated blocks = 0 //离开safe mode Leaving safe mode after 12 secs. //注册DataNode Adding a new node: /default-rack/192.168.1.106:50010 Adding a new node: /default-rack/192.168.1.105:50010 Adding a new node: /default-rack/192.168.1.107:50010 |
在hadoop-secondarynamenode-namenode.log文件中，我们可以看到SecondaryNameNode的启动过程：
|
Secondary Web-server up at: 0.0.0.0:50090 //进行Checkpoint的周期 Checkpoint Period :3600 secs (60 min) Log Size Trigger :67108864 bytes (65536 KB) //进行一次checkpoint，从NameNode下载fsimage和edits Downloaded file fsimage size 97 bytes. Downloaded file edits size 370 bytes. //加载edit文件，进行合并，将合并后的fsimage保存，我们可以看到fsimage变大了 Edits file /data/hadoopdir/tmp/dfs/namesecondary/current/edits of size 370 edits # 6 loaded in 0 seconds. Image file of size 540 saved in 0 seconds. //此次checkpoint结束 Checkpoint done. New Image Size: 540 |
在hadoop-jobtracker-namenode.log文件中，我们可以看到JobTracker的启动过程：
|
JobTracker up at: 9001 JobTracker webserver: 50030 //清除HDFS中的/data/hadoopdir/tmp/mapred/system文件夹，是用于Map-Reduce运行过程中保存数据的 Cleaning up the system directory //不断的从TaskTracker收到heartbeat，第一次是注册TaskTracker Got heartbeat from: tracker_datanode01:localhost/127.0.0.1:58297 Adding a new node: /default-rack/datanode01 Got heartbeat from: tracker_datanode03:localhost/127.0.0.1:37546 Adding a new node: /default-rack/datanode03 |
在hadoop-datanode-datanode01.log中，可以看到DataNode的启动过程：
|
//格式化DataNode存放block的文件夹 Storage directory /data/hadoopdir/tmp/dfs/data is not formatted. Formatting ... //启动DataNode Opened info server at 50010 Balancing bandwith is 1048576 bytes/s Initializing JVM Metrics with processName=DataNode, sessionId=null //向NameNode注册此DataNode dnRegistration = DatanodeRegistration(datanode01:50010, storageID=, infoPort=50075, ipcPort=50020) New storage id DS-1042573498-192.168.1.105-50010-1290313555129 is assigned to data-node 192.168.1.105:5001 DatanodeRegistration(192.168.1.105:50010, storageID=DS-1042573498-192.168.1.105-50010-1290313555129, infoPort=50075, ipcPort=50020)In DataNode.run, data = FSDataset{dirpath='/data/hadoopdir/tmp/dfs/data/current'} //启动block scanner Starting Periodic block scanner. |
在hadoop-tasktracker-datanode01.log中，可以看到TaskTracker的启动过程：
|
//启动TaskTracker Initializing JVM Metrics with processName=TaskTracker, sessionId= TaskTracker up at: localhost/127.0.0.1:58297 Starting tracker tracker_datanode01:localhost/127.0.0.1:58297 //向JobTracker发送heartbeat Got heartbeatResponse from JobTracker with responseId: 0 and 0 actions |
一个特殊的log文件是hadoop-tasktracker-datanode02.log中，因为我们设置的最大Map Task数目和最大Reduce Task数据为0，而报了一个Exception，Can not start task tracker because java.lang.IllegalArgumentException，从而使得datanode02上的TaskTracker没有启动起来。
当Hadoop启动起来以后，在HDFS中也创建了一些文件夹/data/hadoopdir/tmp/mapred/system，用来保存Map-Reduce运行时候的共享资源。
三、向HDFS中放入文件
向HDFS中放入文件，需要使用命令：bin/hadoop fs -put inputdata /data/input
放入文件完毕后，我们查看HDFS：bin/hadoop fs -ls /data/input，结果为：
-rw-r--r-- 3 hadoop supergroup 6119928 2010-11-21 00:47 /data/input/inputdata
这个时候，我们查看DataNode下的/data/hadoopdir/tmp文件夹发生了变化：
- 在datanode01, datanode02, datanode03上的/data/hadoopdir/tmp/dfs/data/current下面都多了如下的block文件
- 可见block文件被复制了三份
|
.: dfs mapred ./dfs: data ./dfs/data: current detach in_use.lock storage tmp ./dfs/data/current: blk_2672607439166801630 blk_2672607439166801630_1002.meta dncp_block_verification.log.curr VERSION ./dfs/data/detach: ./dfs/data/tmp: ./mapred: local ./mapred/local: |
在放入文件的过程中，我们可以看log如下：
namenode的hadoop-namenode-namenode.log如下:
|
//创建/data/input/inputdata ugi=admin,sambashareip=/192.168.1.104 cmd=create src=/data/input/inputdata dst=null perm=hadoop:supergroup:rw-r--r-- //分配block NameSystem.allocateBlock: /data/input/inputdata. blk_2672607439166801630_1002 NameSystem.addStoredBlock: blockMap updated: 192.168.1.107:50010 is added toblk_2672607439166801630_1002 size 6119928 NameSystem.addStoredBlock: blockMap updated: 192.168.1.105:50010 is added toblk_2672607439166801630_1002 size 6119928 NameSystem.addStoredBlock: blockMap updated: 192.168.1.106:50010 is added toblk_2672607439166801630_1002 size 6119928 |
datanode01的hadoop-datanode-datanode01.log如下:
|
//datanode01从客户端接收一个block Receiving block blk_2672607439166801630_1002 src: /192.168.1.104:41748 dest: /192.168.1.105:50010 src: /192.168.1.104:41748, dest: /192.168.1.105:50010, bytes: 6119928, op: HDFS_WRITE, cliID: DFSClient_-1541812792, srvID: DS-1042573498-192.168.1.105-50010-1290313555129, blockid: blk_2672607439166801630_1002 PacketResponder 2 for block blk_2672607439166801630_1002 terminating |
datanode02的hadoop-datanode-datanode02.log如下：
|
//datanode02从datanode01接收一个block Receiving block blk_2672607439166801630_1002 src: /192.168.1.105:60266 dest: /192.168.1.106:50010 src: /192.168.1.105:60266, dest: /192.168.1.106:50010, bytes: 6119928, op: HDFS_WRITE, cliID: DFSClient_-1541812792, srvID: DS-1366730865-192.168.1.106-50010-1290313543717, blockid: blk_2672607439166801630_1002 PacketResponder 1 for block blk_2672607439166801630_1002 terminating |
datanode03的hadoop-datanode-datanode03.log如下：
|
//datanode03从datanode02接收一个block Receiving block blk_2672607439166801630_1002 src: /192.168.1.106:58899 dest: /192.168.1.107:50010 src: /192.168.1.106:58899, dest: /192.168.1.107:50010, bytes: 6119928, op: HDFS_WRITE, cliID: DFSClient_-1541812792, srvID: DS-765014609-192.168.1.107-50010-1290313555841, blockid: blk_2672607439166801630_1002 PacketResponder 0 for block blk_2672607439166801630_1002 terminating Verification succeeded for blk_2672607439166801630_1002 |
四、运行一个Map-Reduce程序
运行Map-Reduce函数，需要运行命令：bin/hadoop jar hadoop-0.19.2-examples.jar wordcount /data/input /data/output
为了能够观察Map-Reduce一步步运行的情况，我们首先远程调试JobTracker，将断点设置在JobTracker.submitJob函数中。
按照我们上一篇文章讨论的那样，DFSClient向JobTracker提交任务之前，会将任务运行所需要的三类文件放入HDFS，从而可被JobTracker和TaskTracker得到：
- 运行的jar文件：job.jar
- 运行所需要的input split的信息：job.split
- 运行所需的配置：job.xml
当Map-Reduce程序停在JobTracker.submitJob函数中的时候，让我们查看HDFS中有如下的变化：
bin/hadoop fs -ls /data/hadoopdir/tmp/mapred/system
其中多了一个文件夹job_201011202025_0001，这是当前运行的Job的ID，在这个文件夹中有三个文件：
|
bin/hadoop fs -ls /data/hadoopdir/tmp/mapred/system/job_201011202025_0001 Found 3 items -rw-r--r-- /data/hadoopdir/tmp/mapred/system/job_201011202025_0001/job.jar -rw-r--r-- /data/hadoopdir/tmp/mapred/system/job_201011202025_0001/job.split -rw-r--r-- /data/hadoopdir/tmp/mapred/system/job_201011202025_0001/job.xml |
现在我们可以断开对JobTracker的远程调试。
在JobTracker.submitJob的函数中，会读取这些上传到HDFS的文件，从而将Job拆分成Map Task和Reduce Task。
当TaskTracker通过heartbeat向JobTracker请求一个Map Task或者Reduce Task来运行，按照我们上面的配置，显然datanode01会请求Map Task来执行，而datanode03会申请Reduce Task来执行。
下面我们首先来看datanode01上Map Task的执行过程：
当TaskTracker得到一个Task的时候，它会调用TaskTracker.localizeJob将job运行的三个文件从HDFS中拷贝到本地文件夹，然后调用TaskInProgress.localizeTask创建Task运行的本地工作目录。
我们来远程调试datanode01上的TaskTracker，分别将断点设在localizeJob和localizeTask函数中，当程序停在做完localizeTask后，我们来看datanode01上的/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache下多了一个文件夹
job_201011202025_0001，在此文件夹下面有如下的结构：
|
datanode01:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001$ ls -R .: attempt_201011202025_0001_m_000000_0 attempt_201011202025_0001_m_000003_0 jars job.xml work ./attempt_201011202025_0001_m_000000_0: job.xml split.dta work ./attempt_201011202025_0001_m_000000_0/work: ./attempt_201011202025_0001_m_000003_0: pid work ./attempt_201011202025_0001_m_000003_0/work: tmp ./attempt_201011202025_0001_m_000003_0/work/tmp: ./jars: job.jar META-INF org ./work: |
其中，job.xml, job.jar，split.dta为配置文件和运行jar以及input split，jars文件夹下面为job.jar的解压缩。
接下来datanode01要创建Child JVM来执行Task，这时我们在datanode01上运行ps aux | grep java，可以发现各有一个新的JVM被创建：
|
/bin/java …… -Xmx200m -agentlib:jdwp=transport=dt_socket,address=8883,server=y,suspend=y …… org.apache.hadoop.mapred.Child 127.0.0.1 58297 attempt_201011202025_0001_m_000003_0 2093922206 |
从JVM的参数我们可以看出，这是一个map任务。从上面的文件我们可以看出，其实此TaskTracker已经在同一个Child JVM里面运行了两个map task，其中一个是attempt_201011202025_0001_m_000003_0，这个没有input split，后来发现他是一个job setup task，而另一个是attempt_201011202025_0001_m_000000_0，是一个真正处理数据的map task，当然如果需要处理的数据量足够大，会有多个处理数据的map task被运行。
我们可以对Child JVM进行远程调试，把断点设在MapTask.run函数中，从上一篇文章中我们知道，map的结果一开始都是保存在buffer中的，当数据量足够大，则spill到硬盘中，形成spill文件，在map task结束之前，我们查看attempt_201011202025_0001_m_000000_0文件夹，我们可以看到，大量的spill文件已经生成：
|
datanode01:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001/attempt_201011202025_0001_m_000000_0$ ls -R .: job.xml output split.dta work ./output: spill0.out spill16.out spill22.out spill29.out spill35.out spill41.out spill48.out spill54.out spill60.out spill67.out spill73.out spill7.out spill10.out spill17.out spill23.out spill2.out spill36.out spill42.out spill49.out spill55.out spill61.out spill68.out spill74.out spill80.out spill11.out spill18.out spill24.out spill30.out spill37.out spill43.out spill4.out spill56.out spill62.out spill69.out spill75.out spill81.out spill12.out spill19.out spill25.out spill31.out spill38.out spill44.out spill50.out spill57.out spill63.out spill6.out spill76.out spill82.out spill13.out spill1.out spill26.out spill32.out spill39.out spill45.out spill51.out spill58.out spill64.out spill70.out spill77.out spill83.out spill14.out spill20.out spill27.out spill33.out spill3.out spill46.out spill52.out spill59.out spill65.out spill71.out spill78.out spill8.out spill15.out spill21.out spill28.out spill34.out spill40.out spill47.out spill53.out spill5.out spill66.out spill72.out spill79.out spill9.out ./work: tmp ./work/tmp: |
当整个map task结束后，所有的spill文件会合并成一个文件，这时候我们再查看attempt_201011202025_0001_m_000000_0文件夹：
|
datanode01:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001/attempt_201011202025_0001_m_000000_0$ ls -R ./output: ./work: ./work/tmp: |
当然如果有多个map task处理数据，就会生成多个file.out，在本例子中，一共只有两个map task处理数据，所以最后的结果为：
|
datanode01:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001$ ls -R attempt_201011202025_0001_m_00000* attempt_201011202025_0001_m_000000_0: job.xml output split.dta work attempt_201011202025_0001_m_000000_0/output: file.out file.out.index attempt_201011202025_0001_m_000000_0/work: tmp attempt_201011202025_0001_m_000000_0/work/tmp: attempt_201011202025_0001_m_000001_0: job.xml output split.dta work attempt_201011202025_0001_m_000001_0/output: file.out file.out.index attempt_201011202025_0001_m_000001_0/work: tmp attempt_201011202025_0001_m_000001_0/work/tmp: attempt_201011202025_0001_m_000003_0: pid work attempt_201011202025_0001_m_000003_0/work: tmp attempt_201011202025_0001_m_000003_0/work/tmp: |
然后我们再来看datanode03上reduce task的运行情况：
我们同样远程调试datanode03上的TaskTracker，将断点设在localizeJob和localizeTask函数中，当程序停在做完localizeTask后，我们来看datanode03上的/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache下也多了一个文件夹job_201011202025_0001，在此文件夹下面有如下的结构：
|
datanode03:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001$ ls -R attempt_201011202025_0001_r_00000* attempt_201011202025_0001_r_000000_0/work: attempt_201011202025_0001_r_000000_0/work/tmp: attempt_201011202025_0001_r_000002_0: attempt_201011202025_0001_r_000002_0/work: attempt_201011202025_0001_r_000002_0/work/tmp: |
上面的两个Reduce Task中，attempt_201011202025_0001_r_000002_0是一个job setup task，真正处理数据的是attempt_201011202025_0001_r_000000_0。
接下来datanode03要创建Child JVM来执行Task，这时我们在datanode03上运行ps aux | grep java，可以发现各有一个新的JVM被创建：
|
/bin/java …… -Xmx200m -agentlib:jdwp=transport=dt_socket,address=8883,server=y,suspend=y - …… org.apache.hadoop.mapred.Child 127.0.0.1 37546 attempt_201011202025_0001_r_000002_0 516504201 |
从JVM的参数我们可以看出，这是一个map任务。
从上一篇文章中我们知道，Reduce Task包括三个过程：copy，sort，reduce
拷贝过程即将所有的map结果复制到reduce task的本地
|
datanode03:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001/attempt_201011202025_0001_r_000000_0$ ls -R .: job.xml output pid work ./output: map_0.out map_1.out map_2.out map_3.out ./work: tmp ./work/tmp: |
如图所示，如果共有4个map task，则共拷贝到本地4个map.out。
在拷贝的过程中，有一个背后的线程会对已经拷贝到本地的map.out进行预先的合并，形成map.merged文件，合并的规则是按照io.sort.factor来进行合并，对于我们的配置就是两两合并，下面我们看到的就是map_2.out和map_3.out合并成map_3.out.merged，在另外两个还没有合并的时候，拷贝过程结束了，则背后的合并进程也就结束了。
|
datanode03:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001/attempt_201011202025_0001_r_000000_0$ ls -R ./output: ./work: ./work/tmp: |
sort过程就是将拷贝过来的map输出合并并排序，也是按照io.sort.factor来进行合并，也即两两合并。下面我们看到的就是map_0.out和map_1.out合并为一个intermediate.1，加上另外的map_3.out.merged，数目已经小于io.sort.factor了，于是不再合并。
|
datanode03:/data/hadoopdir/tmp/mapred/local/attempt_201011202025_0001_r_000000_0$ ls -r intermediate.1 |
|
datanode03:/data/hadoopdir/tmp/mapred/local/taskTracker/jobcache/job_201011202025_0001/attempt_201011202025_0001_r_000000_0$ ls -R ./output: ./work: ./work/tmp: |
reduce的过程就是循环调用reducer的reduce函数，将结果输出到HDFS中。
|
namenode:/data/hadoop-0.19.2$ bin/hadoop fs -ls /data/output Found 2 items /data/output/_logs /data/output/part-00000 |
当然我们通过log，也可以看到Map-Reduce的运行过程：
命令行输出的日志如下：
|
namenode:/data/hadoop-0.19.2$ bin/hadoop jar hadoop-0.19.2-examples.jar wordcount /data/input /data/output 10/11/22 07:38:44 INFO mapred.FileInputFormat: Total input paths to process : 4 10/11/22 07:38:45 INFO mapred.JobClient: Running job: job_201011202025_0001 10/11/22 07:38:46 INFO mapred.JobClient: map 0% reduce 0% 10/11/22 07:39:14 INFO mapred.JobClient: map 25% reduce 0% 10/11/22 07:39:23 INFO mapred.JobClient: map 50% reduce 0% 10/11/22 07:39:27 INFO mapred.JobClient: map 75% reduce 0% 10/11/22 07:39:30 INFO mapred.JobClient: map 100% reduce 0% 10/11/22 07:39:31 INFO mapred.JobClient: map 100% reduce 8% 10/11/22 07:39:36 INFO mapred.JobClient: map 100% reduce 25% 10/11/22 07:39:40 INFO mapred.JobClient: map 100% reduce 100% 10/11/22 07:39:41 INFO mapred.JobClient: Job complete: job_201011202025_0001 10/11/22 07:39:41 INFO mapred.JobClient: Counters: 16 10/11/22 07:39:41 INFO mapred.JobClient: File Systems 10/11/22 07:39:41 INFO mapred.JobClient: HDFS bytes read=61199280 10/11/22 07:39:41 INFO mapred.JobClient: HDFS bytes written=534335 10/11/22 07:39:41 INFO mapred.JobClient: Local bytes read=74505214 10/11/22 07:39:41 INFO mapred.JobClient: Local bytes written=81308914 10/11/22 07:39:41 INFO mapred.JobClient: Job Counters //四个map，一个reduce 10/11/22 07:39:41 INFO mapred.JobClient: Launched reduce tasks=1 10/11/22 07:39:41 INFO mapred.JobClient: Launched map tasks=4 10/11/22 07:39:41 INFO mapred.JobClient: Data-local map tasks=4 10/11/22 07:39:41 INFO mapred.JobClient: Map-Reduce Framework 10/11/22 07:39:41 INFO mapred.JobClient: Reduce input groups=37475 10/11/22 07:39:41 INFO mapred.JobClient: Combine output records=351108 10/11/22 07:39:41 INFO mapred.JobClient: Map input records=133440 10/11/22 07:39:41 INFO mapred.JobClient: Reduce output records=37475 10/11/22 07:39:41 INFO mapred.JobClient: Map output bytes=31671148 10/11/22 07:39:41 INFO mapred.JobClient: Map input bytes=24479712 10/11/22 07:39:41 INFO mapred.JobClient: Combine input records=2001312 10/11/22 07:39:41 INFO mapred.JobClient: Map output records=1800104 10/11/22 07:39:41 INFO mapred.JobClient: Reduce input records=149900 |
在namenode的hadoop-jobtracker-namenode.log中，我们可以看到JobTracker的运行情况：
|
//创建一个Job，分成四个map task JobInProgress: Input size for job job_201011220735_0001 = 24479712 JobInProgress: Split info for job:job_201011220735_0001 JobInProgress: tip:task_201011220735_0001_m_000000 has split on node:/default-rack/datanode02 JobInProgress: tip:task_201011220735_0001_m_000000 has split on node:/default-rack/datanode01 JobInProgress: tip:task_201011220735_0001_m_000000 has split on node:/default-rack/datanode03 JobInProgress: tip:task_201011220735_0001_m_000001 has split on node:/default-rack/datanode03 JobInProgress: tip:task_201011220735_0001_m_000001 has split on node:/default-rack/datanode01 JobInProgress: tip:task_201011220735_0001_m_000001 has split on node:/default-rack/datanode02 JobInProgress: tip:task_201011220735_0001_m_000002 has split on node:/default-rack/datanode02 JobInProgress: tip:task_201011220735_0001_m_000002 has split on node:/default-rack/datanode01 JobInProgress: tip:task_201011220735_0001_m_000002 has split on node:/default-rack/datanode03 JobInProgress: tip:task_201011220735_0001_m_000003 has split on node:/default-rack/datanode01 JobInProgress: tip:task_201011220735_0001_m_000003 has split on node:/default-rack/datanode02 JobInProgress: tip:task_201011220735_0001_m_000003 has split on node:/default-rack/datanode03
//datanode01通过heartbeat向JobTracker申请运行一个job setup task JobTracker: Adding task 'attempt_201011220735_0001_m_000005_0' to tip task_201011220735_0001_m_000005, for tracker 'tracker_datanode01:localhost/127.0.0.1:48339' JobTracker: tracker_datanode01:localhost/127.0.0.1:48339 -> LaunchTask: attempt_201011220735_0001_m_000005_0 JobInProgress: Task 'attempt_201011220735_0001_m_000005_0' has completed task_201011220735_0001_m_000005 successfully.
//datanode01向JobTracker请求运行第一个map task JobTracker: Adding task 'attempt_201011220735_0001_m_000000_0' to tip task_201011220735_0001_m_000000, for tracker 'tracker_datanode01:localhost/127.0.0.1:48339' JobInProgress: Choosing data-local task task_201011220735_0001_m_000000 JobTracker: tracker_datanode01:localhost/127.0.0.1:48339 -> LaunchTask: attempt_201011220735_0001_m_000000_0 JobInProgress: Task 'attempt_201011220735_0001_m_000000_0' has completed task_201011220735_0001_m_000000 successfully.
//datanode01向JobTracker请求运行第二个map task JobTracker: Adding task 'attempt_201011220735_0001_m_000001_0' to tip task_201011220735_0001_m_000001, for tracker 'tracker_datanode01:localhost/127.0.0.1:48339' JobInProgress: Choosing data-local task task_201011220735_0001_m_000001 JobTracker: tracker_datanode01:localhost/127.0.0.1:48339 -> LaunchTask: attempt_201011220735_0001_m_000001_0 JobInProgress: Task 'attempt_201011220735_0001_m_000001_0' has completed task_201011220735_0001_m_000001 successfully.
//datanode01向JobTracker请求运行第三个map task JobTracker: Adding task 'attempt_201011220735_0001_m_000002_0' to tip task_201011220735_0001_m_000002, for tracker 'tracker_datanode01:localhost/127.0.0.1:48339' JobInProgress: Choosing data-local task task_201011220735_0001_m_000002 JobTracker: tracker_datanode01:localhost/127.0.0.1:48339 -> LaunchTask: attempt_201011220735_0001_m_000002_0 JobInProgress: Task 'attempt_201011220735_0001_m_000002_0' has completed task_201011220735_0001_m_000002 successfully.
//datanode01向JobTracker请求运行第四个map task JobTracker: Adding task 'attempt_201011220735_0001_m_000003_0' to tip task_201011220735_0001_m_000003, for tracker 'tracker_datanode01:localhost/127.0.0.1:48339' JobInProgress: Choosing data-local task task_201011220735_0001_m_000003 JobTracker: tracker_datanode01:localhost/127.0.0.1:48339 -> LaunchTask: attempt_201011220735_0001_m_000003_0 JobTracker: Got heartbeat from: tracker_datanode01:localhost/127.0.0.1:48339 (initialContact: false acceptNewTasks: true) with responseId: 39 JobInProgress: Task 'attempt_201011220735_0001_m_000003_0' has completed task_201011220735_0001_m_000003 successfully. //datanode03向JobTracker申请运行一个commit task JobTracker: Adding task 'attempt_201011220735_0001_r_000000_0' to tip task_201011220735_0001_r_000000, for tracker 'tracker_datanode03:localhost/127.0.0.1:44118' JobTracker: tracker_datanode03:localhost/127.0.0.1:44118 -> LaunchTask: attempt_201011220735_0001_r_000000_0 JobTracker: tracker_datanode03:localhost/127.0.0.1:44118 -> CommitTaskAction: attempt_201011220735_0001_r_000000_0 JobInProgress: Task 'attempt_201011220735_0001_r_000000_0' has completed task_201011220735_0001_r_000000 successfully.
//datanode03向JobTracker申请运行一个reduce task JobTracker: Adding task 'attempt_201011220735_0001_r_000001_0' to tip task_201011220735_0001_r_000001, for tracker 'tracker_datanode03:localhost/127.0.0.1:44118' JobTracker: tracker_datanode03:localhost/127.0.0.1:44118 -> LaunchTask: attempt_201011220735_0001_r_000001_0 JobInProgress: Task 'attempt_201011220735_0001_r_000001_0' has completed task_201011220735_0001_r_000001 successfully.
JobInProgress: Job job_201011220735_0001 has completed successfully. |
同样，在datanode01的hadoop-tasktracker-datanode01.log可以看到TaskTracker的运行过程。
在datanode01的logs/userlogs下面，我们可以看到为了运行map task所生成的Child JVM打印出的log，每个map task一个文件夹，在本例中，由于多个map task共用一个JVM，所以只输出了一组log文件
|
datanode01:/data/hadoop-0.19.2/logs/userlogs$ ls -R .: attempt_201011220735_0001_m_000000_0 attempt_201011220735_0001_m_000002_0 attempt_201011220735_0001_m_000005_0 attempt_201011220735_0001_m_000001_0 attempt_201011220735_0001_m_000003_0 ./attempt_201011220735_0001_m_000000_0: log.index ./attempt_201011220735_0001_m_000001_0: log.index ./attempt_201011220735_0001_m_000002_0: log.index ./attempt_201011220735_0001_m_000003_0: log.index ./attempt_201011220735_0001_m_000005_0: log.index stderr stdout syslog |
同样，在datanode03的hadoop-tasktracker-datanode03.log可以看到TaskTracker运行的过程。
在datanode03的logs/users下面，也有一组文件夹，每个reduce task一个文件夹，也是多个reduce task共用一个JVM:
|
datanode03:/data/hadoop-0.19.2/logs/userlogs$ ls -R .: attempt_201011220735_0001_r_000000_0 attempt_201011220735_0001_r_000001_0 ./attempt_201011220735_0001_r_000000_0: log.index stderr stdout syslog ./attempt_201011220735_0001_r_000001_0: log.index |
