详解 WordCount 运行后历史日志记录

在 《Hadoop-2.5.0-cdh5.3.2 HA 安装》 一文中我们已经详细讲述了如何搭建 HA 模式，同时最后还演示了运行其自带的 wordcount 程序，详情请参考 运行 Hadoop自带 wordcount 程序 。先简要回顾下：

---

一. Hadoop 日志基本概念

1. Hadoop 系统服务日志

2. Mapreduce 程序日志

• 作业运行日志
• 任务运行日志 (Container 日志)

其中需要我们关注容易混淆的概念：

• Mapreduce 程序日志 的查看是需要开启 历史日志服务器 后才能查看到
• 其中 日志聚集 功能是针对 任务运行日志 (Container 日志) 而言的！

更多关于Hadoop 日志原理以及相应配置请参考：http://blog.csdn.net/u011414200/article/details/50338073

---

1.1 运行 wordcount 程序

• 已经启动了必需的各项进程：namenode、datanode、resourcemanager、nodemanager、JobHistoryServer 等

• 确保当前 hdfs 不处于安全模式

hdfs dfsadmin -safemode leave

• 确保已经在 HDFS 中创建了相关目录 /data/wordcount 、/output ，以下 /tmp 及其以下目录是启动 JobHistoryServer 后系统自动生成的
  
  

• 上传了测试数据集 slaves
  
  

hadoop fs -put /usr/local/cluster/hadoop/etc/hadoop/slaves /data/wordcount/

• 进入程序所在目录，并运行程序

cd /usr/local/cluster/hadoop/share/hadoop/mapreduce hadoop jar hadoop-mapreduce-examples-2.5.0-cdh5.3.2.jar wordcount /data/wordcount /output/wordcount

---

1.2 控制台输出结果

15/12/22 00:30:36 INFO input.FileInputFormat: Total input paths to process : 115/12/22 00:30:37 INFO mapreduce.JobSubmitter: number of splits:115/12/22 00:30:37 INFO mapreduce.JobSubmitter: Submitting tokens for job: job_1450714294593_000115/12/22 00:30:37 INFO impl.YarnClientImpl: Submitted application application_1450714294593_000115/12/22 00:30:37 INFO mapreduce.Job: The url to track the job: http://master5:8088/proxy/application_1450714294593_0001/15/12/22 00:30:37 INFO mapreduce.Job: Running job: job_1450714294593_000115/12/22 00:30:43 INFO mapreduce.Job: Job job_1450714294593_0001 running in uber mode : false15/12/22 00:30:43 INFO mapreduce.Job:  map 0% reduce 0%15/12/22 00:30:49 INFO mapreduce.Job:  map 100% reduce 0%15/12/22 00:31:04 INFO mapreduce.Job:  map 100% reduce 100%15/12/22 00:31:05 INFO mapreduce.Job: Job job_1450714294593_0001 completed successfully15/12/22 00:31:05 INFO mapreduce.Job: Counters: 49        File System Counters                FILE: Number of bytes read=48                FILE: Number of bytes written=212385                FILE: Number of read operations=0                FILE: Number of large read operations=0                FILE: Number of write operations=0                HDFS: Number of bytes read=125                HDFS: Number of bytes written=30                HDFS: Number of read operations=6                HDFS: Number of large read operations=0                HDFS: Number of write operations=2        Job Counters                Launched map tasks=1                Launched reduce tasks=1                Data-local map tasks=1                Total time spent by all maps in occupied slots (ms)=2347                Total time spent by all reduces in occupied slots (ms)=13060                Total time spent by all map tasks (ms)=2347                Total time spent by all reduce tasks (ms)=13060                Total vcore-seconds taken by all map tasks=2347                Total vcore-seconds taken by all reduce tasks=13060                Total megabyte-seconds taken by all map tasks=2403328                Total megabyte-seconds taken by all reduce tasks=13373440        Map-Reduce Framework                Map input records=3                Map output records=3                Map output bytes=36                Map output materialized bytes=48                Input split bytes=101                Combine input records=3                Combine output records=3                Reduce input groups=3                Reduce shuffle bytes=48                Reduce input records=3                Reduce output records=3                Spilled Records=6                Shuffled Maps =1                Failed Shuffles=0                Merged Map outputs=1                GC time elapsed (ms)=98                CPU time spent (ms)=1250                Physical memory (bytes) snapshot=440475648                Virtual memory (bytes) snapshot=4203302912                Total committed heap usage (bytes)=342360064        Shuffle Errors                BAD_ID=0                CONNECTION=0                IO_ERROR=0                WRONG_LENGTH=0                WRONG_MAP=0                WRONG_REDUCE=0        File Input Format Counters                Bytes Read=24        File Output Format Counters                Bytes Written=30

---

其中需要我们关注的是：

1. 生成 job 和 application ID

15/12/22 00:30:37 INFO mapreduce.JobSubmitter: Submitting tokens for job: job_1450714294593_000115/12/22 00:30:37 INFO impl.YarnClientImpl: Submitted application application_1450714294593_0001

将这里的时间戳 “1450714294593” 中精确到秒的 “1450714294” 部分转化为北京时间为 “2015/12/22 0:11:34” 。这个时间就是 active resourcemanager 启动的时间，如下图 （绝对会有点小误差的）

今后若该 resourcemanager 进程一直保持正常工作，那么运行在其上的任务的 ID ，时间戳依旧不变，改变的是将尾部的 “0001” 不断递增，如下图：

---

2. mapreduce 跟踪任务

15/12/22 00:30:37 INFO mapreduce.Job: The url to track the job: http://master5:8088/proxy/application_1450714294593_0001/

但笔者打开一看却发生如下错误（字面上原因是路径没找到，具体原因不详）：

---

3. 不处于 uber Mode

15/12/22 00:30:43 INFO mapreduce.Job: Job job_1450714294593_0001 running in uber mode : false

• uber Mode 是针对于在 Hadoop2.x 中，对于 MapReuduce Job 小作业来说的一种优化方式（重用 JVM 的方式）

• 小作业指的是 MapReduce Job 运行处理的数据量，当数据量（大小）小于 HDFS 存储数据时 block 的大小（128M），默认是没有启动的。

---

二. Hadoop History 服务器网页详解

Web 页面中，若文字下有下划线，则说明该文字是个超链接

---

2.1 ResourceManager Web 界面

从图中可以可以得到几点信息：

• 整个集群目前包含 3 个存活的计算节点，提交的一个任务已经完成
• 整个 YARN 资源能够最大提供 60 GB 内存，9 个 CPU
• application ID 是由 “application_RM启动时间戳_数字“，数字是从 0001 开始递增，且此处提供查看更多详细信息

---

2.2 application 界面

点击 ID 一栏中的 application_1450714294593_0001 ，画面跳转至 application Overview 界面，浏览器中 URL 为以下所示：

http://10.6.3.43:8088/cluster/app/application_1450714294593_0001

---

1. 查看 ApplicationMaster 所在节点 NodeManager information 信息

点击 Node 一栏中的 slave53:8042 ，画面跳转至 NodeManager information 界面，浏览器中 URL 为以下所示：

http://slave53:8042/node

---

2. 查看 container 日志

点击 Logs 一栏中的 logs ，画面跳转至 container_1450714294593_0001_01_000001 界面，浏览器中 URL 为以下所示：

http://slave53:8042/node/containerlogs/container_1450714294593_0001_01_000001/hadoop5

出现这个 Failed ，估计跟笔者已经设置了 Container 日志聚合有关系。但作业运行完毕之后，NodeManager 本地上的 Container 日志被转移至 HDFS 上。而此时 URL 重定向到 Slave53 这台机器上时 （默认本地位置为 $HADOOP_HOME/logs/userlogs/），肯定找不到了…

解决办法：
如果开启了 Container 日志聚合功能，则在yarn-site.xml下增加如下内容：

<property> <name>yarn.log.server.url</name> <value>http://master5:19888/jobhistory/logs/</value> </property> 

• 其中 master5 是在 mapred-site.xml 中设置历史服务器的主机名，这里也可以写上 IP 地址

修改配置文件，并重启之后，之前已经运行过的任务不会有任何实质性变化，唯一变的就是报错的信息改变了：

而在此之后运行的任务却发生了改变，首先页面会跳转到下面这个页面：

进而接着跳转真正的 Container 日志网页界面，这些日志其实是存放在 HDFS 上的

---

2.3 Job Overview 界面

重返 2.1 中的 ResourceManager Web 界面，点击 Tracking UI 一栏中的 History ，画面跳转至 Job Overview 界面，浏览器中 URL 为以下所示：

http://master5:19888/jobhistory/job/job_1450714294593_0001/jobhistory/job/job_1450714294593_0001

注意，此时已经进入了 master5:19888 的 History Server 界面中，不再是 8088 端口的 ResourceManager 资源界面了。关于更多关于 History Server 的信息，不是本篇博客的重点。我们仅粗略带过…

---

1. 查看 ApplicationMaster 所在节点 NodeManager information 信息

点击 Node 一栏中的 slave53:8042 ，画面跳转至 NodeManager information 界面，和 2.2 步骤 中的一致，就不再赘述。

---

2. 查看 container 日志

点击 Logs 一栏中的 logs ，画面跳转至 container_1450714294593_0001_01_000001 界面，浏览器中 URL 为以下所示：

http://10.6.3.43:19888/jobhistory/logs/slave53:38608/container_1450714294593_0001_01_000001/job_1450714294593_0001/hadoop5

---

3. 查看 Map、Reduce 任务
点击 Task Type 下的 Map 或 Reduce 查看相应日志

• Map 任务

• Reduce 任务

---

2.4 小结

如果对 Hadoop 历史服务器 WEB UI 上提供的数据不满意，我们就可以通过对 mapreduce.jobhistory.done-dir 配置的目录进行分析，得到我们感兴趣的信息，比如统计某天中运行了多少个 map、运行最长的作业用了多少时间、每个用户运行的 Mapreduce 任务数、总共运行了多少 Mapreduce 数等信息，这样对监控 Hadoop 集群是很好的，我们可以根据那些信息来确定怎么给某个用户分配资源等等。

---

三. Hadoop 任务运行日志 (Container 日志) 收集过程详解

在 Job Overview 界面 中的 ”查看 container 日志“ 已经看到相应的 Web 界面，如下所示：

默认情况下，任务运行日志 (Container 日志) 产只会存放在各 NodeManager 的本地磁盘上，且 NodeManager 将日志保存到 yarn.nodemanager.log-dirs 下 ，该属性缺省值为 ${yarn.log.dir}/userlogs，也就是 Hadoop 安装目录下的 logs/userlogs 目录中，通常为了分摊磁盘负载，我们会为该参数设置多个路径。

需要注意的是，ApplicationMaster 的自身的日志也存放在该路目下，因为它也运行在 Container 之中，是一个特殊的 task。举例如下，其中，第一个是某个作业的 ApplicationMaster 日志（编号是000001）。且里面包含 stderr 、stdout 、 syslog 三个文件。

MapReduce 作业的 ApplicationMaster 也运行在 Container 中，且是编号为 000001 的 Container，比如 container_1450714294593_0001_01_000001，它自身可认为是一个特殊的 task，因此，也有自己的运行日志，该日志与 Map Task 和 Reduce Task 类似，但并不是前面介绍的 ”作业运行日志”。

但是将作业和任务日志存放在各个节点上不便于统一管理和分析，为此，我们可以启用日志聚集功能。可以打开日志聚集功能，以便让任务将运行日志推送到 HDFS 上，以便集中管理和分析。打开该功能后，各个任务运行完成后，会将生成的日志推送到 HDFS 的一个目录下。需注意：

• 在开启日志聚合之功能前那些已经产生的本地日志并不会立即删除
• 在 HDFS 上，每个任务产生的三个文件，即 syslog、stderr 和 stdout 将合并一个文件，并通过索引记录各自位置）
• yarn.log-aggregation-enable 参数决定是否启用日志聚集功能，默认值：false
• yarn.nodemanager.remote-app-log-dir 参数决定当应用程序运行结束后，日志被转移到的HDFS目录（仅在启用日志聚集功能时才有效），默认值：HDFS 下的 /tmp/logs 目录
• yarn.nodemanager.remote-app-log-dir-suffix 参数决定远程日志目录子目录名称（仅在启用日志聚集功能时才有效），默认下日志将被转移到目录 ${yarn.nodemanager.remote-app-log-dir}/${user}/${thisParam} 下

以下为笔者开启日志聚合后，在 HDFS 上查看到的信息

hadoop fs -ls -R /tmp/logs

• 在 slave53 的 /usr/local/cluster/hadoop/logs/userlogs 上的日志已经被推送到 HDFS 上，NodeManager 本地上不存在日志了
  
• /tmp/logs/hadoop5/logs/ 即为默认的 yarn.nodemanager.remote-app-log-dir-suffix 参数
• slave52 上的 syslog、stderr 和 stdout 文件合并为 slave52_44024 文件
• slave53 上的 syslog、stderr 和 stdout 文件合并为 slave53_38608 文件

读者若有兴趣可以通过以下命名查看其中的内容

hadoop fs -text /tmp/logs/hadoop5/logs/application_1450714294593_0001/slave53_38608

文件的内容就是在 19888 端口的 History Server Web 页面上所显示的 container 日志，在上图已经显示了。

---

四. Hadoop 作业日志收集过程详解

历史作业运行的记录里面包含了一个作业用了多少个 Map、用了多少个 Reduce、作业提交时间、作业启动时间、作业完成时间等信息；这些信息对分析作业是很有帮助的，我们可以通过这些历史作业记录得到每天有多少个作业运行成功、有多少个作业运行失败、每个队列作业运行了多少个作业等很有用的信息。在 Job Overview 界面 中我们已经进入了历史服务器的网页中去，如下所示

作业运行由 MRAppMaster（MapReduce 作业的 ApplicationMaster）产生，详细记录了作业启动时间、运行时间，每个任务启动时间、运行时间、Counter 值等信息，与 Hadoop 1.0 中的 JobHistory 日志是基本一致。

ApplicationMaster 产生的作业运行日志举例如下，日志采用 apache avro（作为日志存储格式是 Hadoop 2.0 唯一使用到 Avro 的地方）工具，以 json 的格式保存：

{"type":"JOB_SUBMITTED","event":{"org.apache.hadoop.mapreduce.jobhistory.JobSubmitted":{"jobid":"job_1450714294593_0001","jobName":"QuasiMonteCarlo","userName":"yarn", "submitTime":1450715437,"jobConfPath":"hdfs://master5/tmp/hadoop-yarn/staging/yarn/.staging/job_1450714294593_0001/job.xml","acls":{},"jobQueueName":"default","workflowId":"","workflowName":"","workflowNodeName":"","workflowAdjacencies":"","workflowTags":""}}}{"type":"JOB_INITED","event":{"org.apache.hadoop.mapreduce.jobhistory.JobInited":{"jobid":"job_1450714294593_0001","launchTime":1450715441,"totalMaps":8,"totalReduces":1,"jobStatus":"INITED","uberized":false}}}{"type":"JOB_INFO_CHANGED","event":{"org.apache.hadoop.mapreduce.jobhistory.JobInfoChange":{"jobid":"job_1450714294593_0001","submitTime":1450715437,"launchTime":145071543741}}}

---

4.1 步骤一：启动作业的 ApplicationMaster 并写日志至 HDFS

1. ResourceManager 启动作业的 ApplicationMaster

在启动进程之后， HDFS 上可以查看到的目录信息：

2. ApplicationMaster 运行过程中，将日志写到 ${yarn.app.mapreduce.am.staging-dir}/${username}/.staging/job_XXXXX_XXX/ 下

• 参数 yarn.app.mapreduce.am.staging-dir 的默认值是 /tmp/hadoop-yarn/staging
• ${username} 为当前的 hadoop5 用户
• job_XXXXX_XXX 即为本次 job 的 id : job_1450714294593_0001
• 其中的 job.jar 、job.split、job.splitmetainfo 和 job.xml 为中间产物，后面会消失

“.jhist”、”.summary” 和 “.xml” 结尾的文件，分别表示作业运行日志、作业概要信息和作业配置属性，其中，作业概要信息只有一句话，举例如下：

jobId=job_1450714294593_0001,submitTime=1450715420,launchTime=1450715437,firstMapTaskLaunchTime=1385393976706,firstReduceTaskLaunchTime=1385393982581,finishTime=1385393985417,resourcesPerMap=1024,resourcesPerReduce=1024,numMaps=1,numReduces=1,user=yarn,queue=default,status=SUCCEEDED,mapSlotSeconds=47,reduceSlotSeconds=5,jobName=QuasiMonteCarlo

---

4.2 步骤二：HDFS 内转移历史运行日志

所有任务运行完成后，意味着，该作业运行完成。此时

1. ApplicationMaster 将三个文件拷贝到 ${ mapreduce.jobhistory.intermediate-done-dir}/${username} 目录下

• 其中 mapreduce.jobhistory.intermediate-done-dir 默认值是 ${yarn.app.mapreduce.am.staging-dir}/history/done_intermediate
• 过程中还会有 COMMIT_STARTED 和 COMMIT_SUCCESS 的中间文件生成，随后又消失
• 网上也有教程提到的过程如下 （也许中间过程太快，笔者不断刷新还未见到过 _tmp 的身影）
  
  • ApplicationMaster 将三个文件拷贝到 ${ mapreduce.jobhistory.intermediate-done-dir}/${username} 目录下，拷贝后的文件名后面添加 “_tmp”
  • ApplicationMaster 将拷贝完成的三个文件重新命名成 “.jhist”、”.summary” 和 “.xml” 结尾的文件（去掉 “_tmp”）

2. ApplicationMaster 移除 ${yarn.app.mapreduce.am.staging-dir}/yarn/.staging/job_XXXXX_XXX/ 目录

---

4.3 步骤三： 周期转移 done_intermediate 中的日志文件到 done 目录

在步骤二之后，还会在 HDFS 上看到 Container 日志聚合生效之后，NodeManager 上的本地日志被推送到 HDFS 上，原理参照 “Hadoop 任务运行日志 (Container 日志) 收集过程详解” ，如下所示：

1 .周期性扫描线程定期将 done_intermediate 的日志文件转移到 done 目录

2. 删除 “.summary” 文件（该文件中的信息，.jhist 文件中都有）

• 通过参数 mapreduce.jobhistory.done-dir 配置，默认值为 ${yarn.app.mapreduce.am.staging-dir}/history/done）下
• 由于历史作业记录可能非常多，所以历史作业记录是按照 “年/月/日” 的形式分别存放在相应的目录中，这样便于管理和查找

---

4.4 概念拓展

1. jhist 和 xml 文件内容详解
对于每一个 Hadoop 历史作业记录相关信息都用两个文件存放，后缀名分别为 *.jhist，*.xml。

*.jhist 文件里存放的是具体 Hadoop 作业的详细信息，如下：

{ 　　"type": "JOB_INITED", 　　"event": {    　　"org.apache.hadoop.mapreduce.jobhistory.JobInited": {      　　 "jobid": "job_1450714294593_0001",       　　"launchTime": 1450715437,      　　 "totalMaps": 1,       　　"totalReduces": 1,       　　"jobStatus": "INITED",       　　"uberized": false    　　}　　 }}

这是 Hadoop JOB 初始化的一条信息，通过观察我们知道，*.jhist 文件里面全部都是 Json 格式的数据。根据 type 进行区分这条 Json 的含义，在 Hadoop 中，总共包含了一下几个 type：

"JOB_SUBMITTED","JOB_INITED","JOB_FINISHED","JOB_PRIORITY_CHANGED","JOB_STATUS_CHANGED","JOB_FAILED","JOB_KILLED","JOB_ERROR","JOB_INFO_CHANGED","TASK_STARTED","TASK_FINISHED","TASK_FAILED","TASK_UPDATED","NORMALIZED_RESOURCE","MAP_ATTEMPT_STARTED","MAP_ATTEMPT_FINISHED","MAP_ATTEMPT_FAILED","MAP_ATTEMPT_KILLED","REDUCE_ATTEMPT_STARTED","REDUCE_ATTEMPT_FINISHED","REDUCE_ATTEMPT_FAILED","REDUCE_ATTEMPT_KILLED","SETUP_ATTEMPT_STARTED","SETUP_ATTEMPT_FINISHED","SETUP_ATTEMPT_FAILED","SETUP_ATTEMPT_KILLED","CLEANUP_ATTEMPT_STARTED","CLEANUP_ATTEMPT_FINISHED","CLEANUP_ATTEMPT_FAILED","CLEANUP_ATTEMPT_KILLED","AM_STARTED"

而*.xml文件里面记录的是相应作业运行时候的完整参数配置

2. mapreduce.jobhistory.intermediate-done-dir 路径下存放内容

每一个作业的历史记录都存放在一个单独的文件中。mapreduce.jobhistory.intermediate-done-dir 配置的目录下主要存放的是当前正在运行的 Hadoop 任务的记录相关信息。

3. .jhist 结尾文件的命名来源

job_1450714294593_0001-1450715437503-hadoop5-word+count-1450715441038-1-1-SUCCEEDED-root.hadoop5-1450715420462.jhist

是由 job_ID-Submitted Time-${user-name}-Job Name-Finished Time-Map Task Number-Reduce Task Number-State-Queue-Started Time.jhist 组成的，如下图

• 时间戳 1450715441038 的后 3 位是精确到毫秒，所以笔者只算到秒