Hadoop MapReduce Job の History ログの見方

今日は。
落合です。

ひしだまさんに引き続き、
2012年12月20日のHadoopアドベントカレンダー2012 #hadoopAC12jp投稿ということで、
Hadoop MapReduce Job の History ログの見方と、
Job実行状況のExcel表示例をご紹介します。

HadoopのMapReduce Jobを実行すると、
JobTrackerサーバのログディレクトリ

/var/log/hadoop/history

に、MapReduceのJob詳細ログがJobごとに作成されます。

WebUIで見ることができるような内容がこのファイルに詰まっています。

Hadoopのバージョンによって、history以下のディレクトリ構成や、
ファイル名の形式が変わっているのが曲者ですが、
とりあえず中を見てみましょう。

このように、一番上の行から順に、
Jobが進むに従って情報が追加されています。

ただ、このまま文字を追ってJobの内容を把握するのは大変ですよね。

赤で囲ったあたりから、
Job ID, Job名、Jobの開始時刻、終了時刻、Jobのステータス、
各 Map, Reduce Task Attempt のID、開始時刻、終了時刻、ステータス
を取り出して、
MapReduce Jobの様子を把握するためにExcelで情報を整形してみましょう。

テキストを解析するのも骨が折れますが、
とりあえず、以下のスクリプトを書いてみました。
引数でログファイル名を指定すると、
標準出力にカンマ区切りの整形済みデータを出力します。
（エラー処理を何もしていないです。悪しからず・・・）

MapReduceJobChart.py

#!/usr/bin/python
# -*- coding: utf-8 -*- 

import sys
import re
import datetime

class attempt:
    def __init__(self,attemptID):
        self.attemptID = attemptID
        self.attemptType = None
        self.attemptStart = None
        self.attemptEnd = None
        self.attemptStatus = None

if __name__ == "__main__":
    filepath = sys.argv[1]
    file = open(filepath,"r")
    
    jobID = ""
    jobName = ""
    jobStart = ""
    jobEnd = ""
    jobStatus = ""

    attempts = {}
    
    for row in file:
        if row.startswith("Job"):
            if jobID == "":
                search = re.search('JOBID="(\\w+)"', row)
                if search is not None:
                    jobID = search.group(1)
            if jobName == "":
                search = re.search('JOBNAME="([^"]+)"', row)
                if search is not None:
                    jobName = search.group(1)
            if jobStart == "":
                search = re.search('SUBMIT_TIME="(\\d+)"', row)
                if search is not None:
                    jobStart = datetime.datetime.fromtimestamp(float(search.group(1))/1000)
            if jobEnd == "":
                search = re.search('FINISH_TIME="(\\d+)"', row)
                if search is not None:
                    jobEnd = datetime.datetime.fromtimestamp(float(search.group(1))/1000)
            search = re.search('JOB_STATUS="(\\w+)"', row)
            if search is not None:
                jobStatus = search.group(1)

        if row.startswith("MapAttempt") or row.startswith("ReduceAttempt"):
            searchAttemptID = re.search('TASK_ATTEMPT_ID="(\\w+)"', row)
            attemptID = searchAttemptID.group(1)
            attemptItem = attempts.get(attemptID)
            if attemptItem is None:
                attemptItem = attempt(attemptID);
            if attemptItem.attemptType is None:
                search = re.search('TASK_TYPE="([^"]+)"', row)
                if search is not None:
                    attemptItem.attemptType = search.group(1)
            if attemptItem.attemptStart is None:
                search = re.search('START_TIME="(\\d+)"', row)
                if search is not None:
                    attemptItem.attemptStart = datetime.datetime.fromtimestamp(float(search.group(1))/1000)
            if attemptItem.attemptEnd is None:
                search = re.search('FINISH_TIME="(\\d+)"', row)
                if search is not None:
                    attemptItem.attemptEnd = datetime.datetime.fromtimestamp(float(search.group(1))/1000)
            search = re.search('TASK_STATUS="(\\w+)"', row)
            if search is not None:
                attemptItem.attemptStatus = search.group(1)
            attempts[attemptID] = attemptItem

    print jobID + ",,,," + jobStart.strftime("%Y/%m/%d %H:%M:%S") + "," + jobEnd.strftime("%Y/%m/%d %H:%M:%S") 
    print jobName
    print jobStatus

    for key in sorted(attempts.keys()):
        result = "," + attempts[key].attemptStatus + "," + attempts[key].attemptType + ","
        result += attempts[key].attemptID + "," + attempts[key].attemptStart.strftime("%Y/%m/%d %H:%M:%S") + ","
        result += attempts[key].attemptEnd.strftime("%Y/%m/%d %H:%M:%S")
        print result

    file.close()
    print ""

実行するとこんな感じで出力されます。

job_201210230540_0007,,,,2012/10/24 02:57:22,2012/10/24 03:02:06
Sleep job
SUCCESS
,SUCCESS,MAP,attempt_201210230540_0007_m_000000_0,2012/10/24 02:57:24,2012/10/24 02:59:26
,SUCCESS,CLEANUP,attempt_201210230540_0007_m_000001_0,2012/10/24 03:02:04,2012/10/24 03:02:05
,SUCCESS,SETUP,attempt_201210230540_0007_m_000002_0,2012/10/24 02:57:23,2012/10/24 02:57:24
,SUCCESS,REDUCE,attempt_201210230540_0007_r_000000_0,2012/10/24 02:59:26,2012/10/24 03:02:04

これを貼り付ける用のExcelシートを用意しました。

MapReduceJobChart_template.xlsx

A4 セルに、出力結果のテキストを貼り付けて、
テキストファイルウィザードでカンマ区切りを選択して出力すると、
準備完了です。

historyログをまとめて解析したい場合、
以下のようなシェルで対象ファイル全部について解析結果を出力させてもいいでしょう。

#!/bin/sh

for filepath in `find /var/log/hadoop/history/done/ -type f -name "job_*"`
do
    python MapReduceJobChart.py $filepath
done

出力例がこちらです。
Map、Reduceにそれぞれどれくらい時間がかかったか、
Map、Reduceがそれぞれ同時にいくつずつ動いていたか、
FailしていたMapReduce Taskはなかったか、
などが把握しやすくなったのではないでしょうか？

MapReduceJobChart.xlsx

JobTrackerサーバにちょうどいいログを持っている方は、
試してみてください。

ちなみに、
ここで可視化した内容は、
halook の MapReduce Job Arrow chart の劣化版です。
なんだかんだで、いちいちスクリプトを実行するのは手間なので、
ブラウザで見えるこっちのほうがいいですね。

スクリプト＋Excelにせよ、可視化ツールにせよ、
実行状況の見える化手法をうまく使って、
トラブルの予防・解決に役立てましょう！

それでは。