Java tutorial
/** * Licensed to the Apache Software Foundation (ASF) under one * or more contributor license agreements. See the NOTICE file * distributed with this work for additional information * regarding copyright ownership. The ASF licenses this file * to you under the Apache License, Version 2.0 (the * "License"); you may not use this file except in compliance * with the License. You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ package org.apache.hadoop.fs; import java.io.BufferedReader; import java.io.BufferedWriter; import java.io.DataInputStream; import java.io.DataOutputStream; import java.io.IOException; import java.io.InputStream; import java.io.InputStreamReader; import java.io.OutputStreamWriter; import java.text.SimpleDateFormat; import java.util.ArrayList; import java.util.Collection; import java.util.Date; import java.util.Map; import java.util.StringTokenizer; import java.util.HashMap; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.io.LongWritable; import org.apache.hadoop.io.SequenceFile; import org.apache.hadoop.io.Text; import org.apache.hadoop.io.SequenceFile.CompressionType; import org.apache.hadoop.io.compress.CompressionCodec; import org.apache.hadoop.io.compress.GzipCodec; import org.apache.hadoop.mapred.*; import org.apache.hadoop.util.ReflectionUtils; import org.apache.hadoop.util.StringUtils; /** * Job History Log Analyzer. * * <h3>Description.</h3> * This a tool for parsing and analyzing history logs of map-reduce jobs. * History logs contain information about execution of jobs, tasks, and * attempts. This tool focuses on submission, launch, start, and finish times, * as well as the success or failure of jobs, tasks, and attempts. * <p> * The analyzer calculates <em>per hour slot utilization</em> for the cluster * as follows. * For each task attempt it divides the time segment from the start of the * attempt t<sub>S</sub> to the finish t<sub>F</sub> into whole hours * [t<sub>0</sub>, ..., t<sub>n</sub>], where t<sub>0</sub> <= t<sub>S</sub> * is the maximal whole hour preceding t<sub>S</sub>, and * t<sub>n</sub> >= t<sub>F</sub> is the minimal whole hour after t<sub>F</sub>. * Thus, [t<sub>0</sub>, ..., t<sub>n</sub>] covers the segment * [t<sub>S</sub>, t<sub>F</sub>], during which the attempt was executed. * Each interval [t<sub>i</sub>, t<sub>i+1</sub>] fully contained in * [t<sub>S</sub>, t<sub>F</sub>] corresponds to exactly one slot on * a map-reduce cluster (usually MAP-slot or REDUCE-slot). * If interval [t<sub>i</sub>, t<sub>i+1</sub>] only intersects with * [t<sub>S</sub>, t<sub>F</sub>] then we say that the task * attempt used just a fraction of the slot during this hour. * The fraction equals the size of the intersection. * Let slotTime(A, h) denote the number of slots calculated that way for a * specific attempt A during hour h. * The tool then sums all slots for all attempts for every hour. * The result is the slot hour utilization of the cluster: * <tt>slotTime(h) = SUM<sub>A</sub> slotTime(A,h)</tt>. * <p> * Log analyzer calculates slot hours for <em>MAP</em> and <em>REDUCE</em> * attempts separately. * <p> * Log analyzer distinguishes between <em>successful</em> and <em>failed</em> * attempts. Task attempt is considered successful if its own status is SUCCESS * and the statuses of the task and the job it is a part of are also SUCCESS. * Otherwise the task attempt is considered failed. * <p> * Map-reduce clusters are usually configured to have a fixed number of MAP * and REDUCE slots per node. Thus the maximal possible number of slots on * the cluster is <tt>total_slots = total_nodes * slots_per_node</tt>. * Effective slot hour cannot exceed <tt>total_slots</tt> for successful * attempts. * <p> * <em>Pending time</em> characterizes the wait time of attempts. * It is calculated similarly to the slot hour except that the wait interval * starts when the job is submitted and ends when an attempt starts execution. * In addition to that pending time also includes intervals between attempts * of the same task if it was re-executed. * <p> * History log analyzer calculates two pending time variations. First is based * on job submission time as described above, second, starts the wait interval * when the job is launched rather than submitted. * * <h3>Input.</h3> * The following input parameters can be specified in the argument string * to the job log analyzer: * <ul> * <li><tt>-historyDir inputDir</tt> specifies the location of the directory * where analyzer will be looking for job history log files.</li> * <li><tt>-resFile resultFile</tt> the name of the result file.</li> * <li><tt>-usersIncluded | -usersExcluded userList</tt> slot utilization and * pending time can be calculated for all or for all but the specified users. * <br> * <tt>userList</tt> is a comma or semicolon separated list of users.</li> * <li><tt>-gzip</tt> is used if history log files are compressed. * Only {@link GzipCodec} is currently supported.</li> * <li><tt>-jobDelimiter pattern</tt> one can concatenate original log files into * larger file(s) with the specified delimiter to recognize the end of the log * for one job from the next one.<br> * <tt>pattern</tt> is a java regular expression * {@link java.util.regex.Pattern}, which should match only the log delimiters. * <br> * E.g. pattern <tt>".!!FILE=.*!!"</tt> matches delimiters, which contain * the original history log file names in the following form:<br> * <tt>"$!!FILE=my.job.tracker.com_myJobId_user_wordcount.log!!"</tt></li> * <li><tt>-clean</tt> cleans up default directories used by the analyzer.</li> * <li><tt>-test</tt> test one file locally and exit; * does not require map-reduce.</li> * <li><tt>-help</tt> print usage.</li> * </ul> * * <h3>Output.</h3> * The output file is formatted as a tab separated table consisting of four * columns: <tt>SERIES, PERIOD, TYPE, SLOT_HOUR</tt>. * <ul> * <li><tt>SERIES</tt> one of the four statistical series;</li> * <li><tt>PERIOD</tt> the start of the time interval in the following format: * <tt>"yyyy-mm-dd hh:mm:ss"</tt>;</li> * <li><tt>TYPE</tt> the slot type, e.g. MAP or REDUCE;</li> * <li><tt>SLOT_HOUR</tt> the value of the slot usage during this * time interval.</li> * </ul> */ @SuppressWarnings("deprecation") public class JHLogAnalyzer { private static final Log LOG = LogFactory.getLog(JHLogAnalyzer.class); // Constants private static final String JHLA_ROOT_DIR = System.getProperty("test.build.data", "stats/JHLA"); private static final Path INPUT_DIR = new Path(JHLA_ROOT_DIR, "jhla_input"); private static final String BASE_INPUT_FILE_NAME = "jhla_in_"; private static final Path OUTPUT_DIR = new Path(JHLA_ROOT_DIR, "jhla_output"); private static final Path RESULT_FILE = new Path(JHLA_ROOT_DIR, "jhla_result.txt"); private static final Path DEFAULT_HISTORY_DIR = new Path("history"); private static final int DEFAULT_TIME_INTERVAL_MSEC = 1000 * 60 * 60; // 1 hour static { Configuration.addDefaultResource("hdfs-default.xml"); Configuration.addDefaultResource("hdfs-site.xml"); } static enum StatSeries { STAT_ALL_SLOT_TIME(AccumulatingReducer.VALUE_TYPE_LONG + "allSlotTime"), STAT_FAILED_SLOT_TIME( AccumulatingReducer.VALUE_TYPE_LONG + "failedSlotTime"), STAT_SUBMIT_PENDING_SLOT_TIME( AccumulatingReducer.VALUE_TYPE_LONG + "submitPendingSlotTime"), STAT_LAUNCHED_PENDING_SLOT_TIME( AccumulatingReducer.VALUE_TYPE_LONG + "launchedPendingSlotTime"); private String statName = null; private StatSeries(String name) { this.statName = name; } public String toString() { return statName; } } private static class FileCreateDaemon extends Thread { private static final int NUM_CREATE_THREADS = 10; private static volatile int numFinishedThreads; private static volatile int numRunningThreads; private static FileStatus[] jhLogFiles; FileSystem fs; int start; int end; FileCreateDaemon(FileSystem fs, int start, int end) { this.fs = fs; this.start = start; this.end = end; } public void run() { try { for (int i = start; i < end; i++) { String name = getFileName(i); Path controlFile = new Path(INPUT_DIR, "in_file_" + name); SequenceFile.Writer writer = null; try { writer = SequenceFile.createWriter(fs, fs.getConf(), controlFile, Text.class, LongWritable.class, CompressionType.NONE); String logFile = jhLogFiles[i].getPath().toString(); writer.append(new Text(logFile), new LongWritable(0)); } catch (Exception e) { throw new IOException(e); } finally { if (writer != null) writer.close(); writer = null; } } } catch (IOException ex) { LOG.error("FileCreateDaemon failed.", ex); } numFinishedThreads++; } private static void createControlFile(FileSystem fs, Path jhLogDir) throws IOException { fs.delete(INPUT_DIR, true); jhLogFiles = fs.listStatus(jhLogDir); numFinishedThreads = 0; try { int start = 0; int step = jhLogFiles.length / NUM_CREATE_THREADS + ((jhLogFiles.length % NUM_CREATE_THREADS) > 0 ? 1 : 0); FileCreateDaemon[] daemons = new FileCreateDaemon[NUM_CREATE_THREADS]; numRunningThreads = 0; for (int tIdx = 0; tIdx < NUM_CREATE_THREADS && start < jhLogFiles.length; tIdx++) { int end = Math.min(start + step, jhLogFiles.length); daemons[tIdx] = new FileCreateDaemon(fs, start, end); start += step; numRunningThreads++; } for (int tIdx = 0; tIdx < numRunningThreads; tIdx++) { daemons[tIdx].start(); } } finally { int prevValue = 0; while (numFinishedThreads < numRunningThreads) { if (prevValue < numFinishedThreads) { LOG.info("Finished " + numFinishedThreads + " threads out of " + numRunningThreads); prevValue = numFinishedThreads; } try { Thread.sleep(500); } catch (InterruptedException e) { } } } } } private static void createControlFile(FileSystem fs, Path jhLogDir) throws IOException { LOG.info("creating control file: JH log dir = " + jhLogDir); FileCreateDaemon.createControlFile(fs, jhLogDir); LOG.info("created control file: JH log dir = " + jhLogDir); } private static String getFileName(int fIdx) { return BASE_INPUT_FILE_NAME + Integer.toString(fIdx); } /** * If keyVal is of the form KEY="VALUE", then this will return [KEY, VALUE] */ private static String[] getKeyValue(String t) throws IOException { String[] keyVal = t.split("=\"*|\""); return keyVal; } /** * JobHistory log record. */ private static class JobHistoryLog { String JOBID; String JOB_STATUS; long SUBMIT_TIME; long LAUNCH_TIME; long FINISH_TIME; long TOTAL_MAPS; long TOTAL_REDUCES; long FINISHED_MAPS; long FINISHED_REDUCES; String USER; Map<String, TaskHistoryLog> tasks; boolean isSuccessful() { return (JOB_STATUS != null) && JOB_STATUS.equals("SUCCESS"); } void parseLine(String line) throws IOException { StringTokenizer tokens = new StringTokenizer(line); if (!tokens.hasMoreTokens()) return; String what = tokens.nextToken(); // Line should start with one of the following: // Job, Task, MapAttempt, ReduceAttempt if (what.equals("Job")) updateJob(tokens); else if (what.equals("Task")) updateTask(tokens); else if (what.indexOf("Attempt") >= 0) updateTaskAttempt(tokens); } private void updateJob(StringTokenizer tokens) throws IOException { while (tokens.hasMoreTokens()) { String t = tokens.nextToken(); String[] keyVal = getKeyValue(t); if (keyVal.length < 2) continue; if (keyVal[0].equals("JOBID")) { if (JOBID == null) JOBID = new String(keyVal[1]); else if (!JOBID.equals(keyVal[1])) { LOG.error("Incorrect JOBID: " + keyVal[1].substring(0, Math.min(keyVal[1].length(), 100)) + " expect " + JOBID); return; } } else if (keyVal[0].equals("JOB_STATUS")) JOB_STATUS = new String(keyVal[1]); else if (keyVal[0].equals("SUBMIT_TIME")) SUBMIT_TIME = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("LAUNCH_TIME")) LAUNCH_TIME = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("FINISH_TIME")) FINISH_TIME = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("TOTAL_MAPS")) TOTAL_MAPS = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("TOTAL_REDUCES")) TOTAL_REDUCES = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("FINISHED_MAPS")) FINISHED_MAPS = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("FINISHED_REDUCES")) FINISHED_REDUCES = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("USER")) USER = new String(keyVal[1]); } } private void updateTask(StringTokenizer tokens) throws IOException { // unpack TaskHistoryLog task = new TaskHistoryLog().parse(tokens); if (task.TASKID == null) { LOG.error("TASKID = NULL for job " + JOBID); return; } // update or insert if (tasks == null) tasks = new HashMap<String, TaskHistoryLog>((int) (TOTAL_MAPS + TOTAL_REDUCES)); TaskHistoryLog existing = tasks.get(task.TASKID); if (existing == null) tasks.put(task.TASKID, task); else existing.updateWith(task); } private void updateTaskAttempt(StringTokenizer tokens) throws IOException { // unpack TaskAttemptHistoryLog attempt = new TaskAttemptHistoryLog(); String taskID = attempt.parse(tokens); if (taskID == null) return; if (tasks == null) tasks = new HashMap<String, TaskHistoryLog>((int) (TOTAL_MAPS + TOTAL_REDUCES)); TaskHistoryLog existing = tasks.get(taskID); if (existing == null) { existing = new TaskHistoryLog(taskID); tasks.put(taskID, existing); } existing.updateWith(attempt); } } /** * TaskHistory log record. */ private static class TaskHistoryLog { String TASKID; String TASK_TYPE; // MAP, REDUCE, SETUP, CLEANUP String TASK_STATUS; long START_TIME; long FINISH_TIME; Map<String, TaskAttemptHistoryLog> attempts; TaskHistoryLog() { } TaskHistoryLog(String taskID) { TASKID = taskID; } boolean isSuccessful() { return (TASK_STATUS != null) && TASK_STATUS.equals("SUCCESS"); } TaskHistoryLog parse(StringTokenizer tokens) throws IOException { while (tokens.hasMoreTokens()) { String t = tokens.nextToken(); String[] keyVal = getKeyValue(t); if (keyVal.length < 2) continue; if (keyVal[0].equals("TASKID")) { if (TASKID == null) TASKID = new String(keyVal[1]); else if (!TASKID.equals(keyVal[1])) { LOG.error("Incorrect TASKID: " + keyVal[1].substring(0, Math.min(keyVal[1].length(), 100)) + " expect " + TASKID); continue; } } else if (keyVal[0].equals("TASK_TYPE")) TASK_TYPE = new String(keyVal[1]); else if (keyVal[0].equals("TASK_STATUS")) TASK_STATUS = new String(keyVal[1]); else if (keyVal[0].equals("START_TIME")) START_TIME = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("FINISH_TIME")) FINISH_TIME = Long.parseLong(keyVal[1]); } return this; } /** * Update with non-null fields of the same task log record. */ void updateWith(TaskHistoryLog from) throws IOException { if (TASKID == null) TASKID = from.TASKID; else if (!TASKID.equals(from.TASKID)) { throw new IOException("Incorrect TASKID: " + from.TASKID + " expect " + TASKID); } if (TASK_TYPE == null) TASK_TYPE = from.TASK_TYPE; else if (!TASK_TYPE.equals(from.TASK_TYPE)) { LOG.error( "Incorrect TASK_TYPE: " + from.TASK_TYPE + " expect " + TASK_TYPE + " for task " + TASKID); return; } if (from.TASK_STATUS != null) TASK_STATUS = from.TASK_STATUS; if (from.START_TIME > 0) START_TIME = from.START_TIME; if (from.FINISH_TIME > 0) FINISH_TIME = from.FINISH_TIME; } /** * Update with non-null fields of the task attempt log record. */ void updateWith(TaskAttemptHistoryLog attempt) throws IOException { if (attempt.TASK_ATTEMPT_ID == null) { LOG.error("Unexpected TASK_ATTEMPT_ID = null for task " + TASKID); return; } if (attempts == null) attempts = new HashMap<String, TaskAttemptHistoryLog>(); TaskAttemptHistoryLog existing = attempts.get(attempt.TASK_ATTEMPT_ID); if (existing == null) attempts.put(attempt.TASK_ATTEMPT_ID, attempt); else existing.updateWith(attempt); // update task start time if (attempt.START_TIME > 0 && (this.START_TIME == 0 || this.START_TIME > attempt.START_TIME)) START_TIME = attempt.START_TIME; } } /** * TaskAttemptHistory log record. */ private static class TaskAttemptHistoryLog { String TASK_ATTEMPT_ID; String TASK_STATUS; // this task attempt status long START_TIME; long FINISH_TIME; long HDFS_BYTES_READ; long HDFS_BYTES_WRITTEN; long FILE_BYTES_READ; long FILE_BYTES_WRITTEN; /** * Task attempt is considered successful iff all three statuses * of the attempt, the task, and the job equal "SUCCESS". */ boolean isSuccessful() { return (TASK_STATUS != null) && TASK_STATUS.equals("SUCCESS"); } String parse(StringTokenizer tokens) throws IOException { String taskID = null; while (tokens.hasMoreTokens()) { String t = tokens.nextToken(); String[] keyVal = getKeyValue(t); if (keyVal.length < 2) continue; if (keyVal[0].equals("TASKID")) { if (taskID == null) taskID = new String(keyVal[1]); else if (!taskID.equals(keyVal[1])) { LOG.error("Incorrect TASKID: " + keyVal[1] + " expect " + taskID); continue; } } else if (keyVal[0].equals("TASK_ATTEMPT_ID")) { if (TASK_ATTEMPT_ID == null) TASK_ATTEMPT_ID = new String(keyVal[1]); else if (!TASK_ATTEMPT_ID.equals(keyVal[1])) { LOG.error("Incorrect TASKID: " + keyVal[1] + " expect " + taskID); continue; } } else if (keyVal[0].equals("TASK_STATUS")) TASK_STATUS = new String(keyVal[1]); else if (keyVal[0].equals("START_TIME")) START_TIME = Long.parseLong(keyVal[1]); else if (keyVal[0].equals("FINISH_TIME")) FINISH_TIME = Long.parseLong(keyVal[1]); } return taskID; } /** * Update with non-null fields of the same task attempt log record. */ void updateWith(TaskAttemptHistoryLog from) throws IOException { if (TASK_ATTEMPT_ID == null) TASK_ATTEMPT_ID = from.TASK_ATTEMPT_ID; else if (!TASK_ATTEMPT_ID.equals(from.TASK_ATTEMPT_ID)) { throw new IOException( "Incorrect TASK_ATTEMPT_ID: " + from.TASK_ATTEMPT_ID + " expect " + TASK_ATTEMPT_ID); } if (from.TASK_STATUS != null) TASK_STATUS = from.TASK_STATUS; if (from.START_TIME > 0) START_TIME = from.START_TIME; if (from.FINISH_TIME > 0) FINISH_TIME = from.FINISH_TIME; if (from.HDFS_BYTES_READ > 0) HDFS_BYTES_READ = from.HDFS_BYTES_READ; if (from.HDFS_BYTES_WRITTEN > 0) HDFS_BYTES_WRITTEN = from.HDFS_BYTES_WRITTEN; if (from.FILE_BYTES_READ > 0) FILE_BYTES_READ = from.FILE_BYTES_READ; if (from.FILE_BYTES_WRITTEN > 0) FILE_BYTES_WRITTEN = from.FILE_BYTES_WRITTEN; } } /** * Key = statName*date-time*taskType * Value = number of msec for the our */ private static class IntervalKey { static final String KEY_FIELD_DELIMITER = "*"; String statName; String dateTime; String taskType; IntervalKey(String stat, long timeMSec, String taskType) { statName = stat; SimpleDateFormat dateF = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss"); dateTime = dateF.format(new Date(timeMSec)); this.taskType = taskType; } IntervalKey(String key) { StringTokenizer keyTokens = new StringTokenizer(key, KEY_FIELD_DELIMITER); if (!keyTokens.hasMoreTokens()) return; statName = keyTokens.nextToken(); if (!keyTokens.hasMoreTokens()) return; dateTime = keyTokens.nextToken(); if (!keyTokens.hasMoreTokens()) return; taskType = keyTokens.nextToken(); } void setStatName(String stat) { statName = stat; } String getStringKey() { return statName + KEY_FIELD_DELIMITER + dateTime + KEY_FIELD_DELIMITER + taskType; } Text getTextKey() { return new Text(getStringKey()); } public String toString() { return getStringKey(); } } /** * Mapper class. */ private static class JHLAMapper extends IOMapperBase<Object> { /** * A line pattern, which delimits history logs of different jobs, * if multiple job logs are written in the same file. * Null value means only one job log per file is expected. * The pattern should be a regular expression as in * {@link String#matches(String)}. */ String jobDelimiterPattern; int maxJobDelimiterLineLength; /** Count only these users jobs */ Collection<String> usersIncluded; /** Exclude jobs of the following users */ Collection<String> usersExcluded; /** Type of compression for compressed files: gzip */ Class<? extends CompressionCodec> compressionClass; JHLAMapper() throws IOException { } JHLAMapper(Configuration conf) throws IOException { configure(new JobConf(conf)); } public void configure(JobConf conf) { super.configure(conf); usersIncluded = getUserList(conf.get("jhla.users.included", null)); usersExcluded = getUserList(conf.get("jhla.users.excluded", null)); String zipClassName = conf.get("jhla.compression.class", null); try { compressionClass = (zipClassName == null) ? null : Class.forName(zipClassName).asSubclass(CompressionCodec.class); } catch (Exception e) { throw new RuntimeException("Compression codec not found: ", e); } jobDelimiterPattern = conf.get("jhla.job.delimiter.pattern", null); maxJobDelimiterLineLength = conf.getInt("jhla.job.delimiter.length", 512); } @Override public void map(Text key, LongWritable value, OutputCollector<Text, Text> output, Reporter reporter) throws IOException { String name = key.toString(); long longValue = value.get(); reporter.setStatus("starting " + name + " ::host = " + hostName); long tStart = System.currentTimeMillis(); parseLogFile(fs, new Path(name), longValue, output, reporter); long tEnd = System.currentTimeMillis(); long execTime = tEnd - tStart; reporter.setStatus("finished " + name + " ::host = " + hostName + " in " + execTime / 1000 + " sec."); } public Object doIO(Reporter reporter, String path, // full path of history log file long offset // starting offset within the file ) throws IOException { return null; } void collectStats(OutputCollector<Text, Text> output, String name, long execTime, Object jobObjects) throws IOException { } private boolean isEndOfJobLog(String line) { if (jobDelimiterPattern == null) return false; return line.matches(jobDelimiterPattern); } /** * Collect information about one job. * * @param fs - file system * @param filePath - full path of a history log file * @param offset - starting offset in the history log file * @throws IOException */ public void parseLogFile(FileSystem fs, Path filePath, long offset, OutputCollector<Text, Text> output, Reporter reporter) throws IOException { InputStream in = null; try { // open file & seek FSDataInputStream stm = fs.open(filePath); stm.seek(offset); in = stm; LOG.info("Opened " + filePath); reporter.setStatus("Opened " + filePath); // get a compression filter if specified if (compressionClass != null) { CompressionCodec codec = (CompressionCodec) ReflectionUtils.newInstance(compressionClass, new Configuration()); in = codec.createInputStream(stm); LOG.info("Codec created " + filePath); reporter.setStatus("Codec created " + filePath); } BufferedReader reader = new BufferedReader(new InputStreamReader(in)); LOG.info("Reader created " + filePath); // skip to the next job log start long processed = 0L; if (jobDelimiterPattern != null) { for (String line = reader.readLine(); line != null; line = reader.readLine()) { if ((stm.getPos() - processed) > 100000) { processed = stm.getPos(); reporter.setStatus("Processing " + filePath + " at " + processed); } if (isEndOfJobLog(line)) break; } } // parse lines and update job history JobHistoryLog jh = new JobHistoryLog(); int jobLineCount = 0; for (String line = readLine(reader); line != null; line = readLine(reader)) { jobLineCount++; if ((stm.getPos() - processed) > 20000) { processed = stm.getPos(); long numTasks = (jh.tasks == null ? 0 : jh.tasks.size()); String txt = "Processing " + filePath + " at " + processed + " # tasks = " + numTasks; reporter.setStatus(txt); LOG.info(txt); } if (isEndOfJobLog(line)) { if (jh.JOBID != null) { LOG.info("Finished parsing job: " + jh.JOBID + " line count = " + jobLineCount); collectJobStats(jh, output, reporter); LOG.info("Collected stats for job: " + jh.JOBID); } jh = new JobHistoryLog(); jobLineCount = 0; } else jh.parseLine(line); } if (jh.JOBID == null) { LOG.error("JOBID = NULL in " + filePath + " at " + processed); return; } collectJobStats(jh, output, reporter); } catch (Exception ie) { // parsing errors can happen if the file has been truncated LOG.error("JHLAMapper.parseLogFile", ie); reporter.setStatus("JHLAMapper.parseLogFile failed " + StringUtils.stringifyException(ie)); throw new IOException("Job failed.", ie); } finally { if (in != null) in.close(); } } /** * Read lines until one ends with a " ." or "\" " */ private StringBuffer resBuffer = new StringBuffer(); private String readLine(BufferedReader reader) throws IOException { resBuffer.setLength(0); reader.mark(maxJobDelimiterLineLength); for (String line = reader.readLine(); line != null; line = reader.readLine()) { if (isEndOfJobLog(line)) { if (resBuffer.length() == 0) resBuffer.append(line); else reader.reset(); break; } if (resBuffer.length() == 0) resBuffer.append(line); else if (resBuffer.length() < 32000) resBuffer.append(line); if (line.endsWith(" .") || line.endsWith("\" ")) { break; } reader.mark(maxJobDelimiterLineLength); } String result = resBuffer.length() == 0 ? null : resBuffer.toString(); resBuffer.setLength(0); return result; } private void collectPerIntervalStats(OutputCollector<Text, Text> output, long start, long finish, String taskType, StatSeries... stats) throws IOException { long curInterval = (start / DEFAULT_TIME_INTERVAL_MSEC) * DEFAULT_TIME_INTERVAL_MSEC; long curTime = start; long accumTime = 0; while (curTime < finish) { // how much of the task time belonged to current interval long nextInterval = curInterval + DEFAULT_TIME_INTERVAL_MSEC; long intervalTime = ((finish < nextInterval) ? finish : nextInterval) - curTime; IntervalKey key = new IntervalKey("", curInterval, taskType); Text val = new Text(String.valueOf(intervalTime)); for (StatSeries statName : stats) { key.setStatName(statName.toString()); output.collect(key.getTextKey(), val); } curTime = curInterval = nextInterval; accumTime += intervalTime; } // For the pending stat speculative attempts may intersect. // Only one of them is considered pending. assert accumTime == finish - start || finish < start; } private void collectJobStats(JobHistoryLog jh, OutputCollector<Text, Text> output, Reporter reporter) throws IOException { if (jh == null) return; if (jh.tasks == null) return; if (jh.SUBMIT_TIME <= 0) throw new IOException("Job " + jh.JOBID + " SUBMIT_TIME = " + jh.SUBMIT_TIME); if (usersIncluded != null && !usersIncluded.contains(jh.USER)) return; if (usersExcluded != null && usersExcluded.contains(jh.USER)) return; int numAttempts = 0; long totalTime = 0; boolean jobSuccess = jh.isSuccessful(); long jobWaitTime = jh.LAUNCH_TIME - jh.SUBMIT_TIME; // attemptSubmitTime is the job's SUBMIT_TIME, // or the previous attempt FINISH_TIME for all subsequent attempts for (TaskHistoryLog th : jh.tasks.values()) { if (th.attempts == null) continue; // Task is successful iff both the task and the job are a "SUCCESS" long attemptSubmitTime = jh.LAUNCH_TIME; boolean taskSuccess = jobSuccess && th.isSuccessful(); for (TaskAttemptHistoryLog tah : th.attempts.values()) { // Task attempt is considered successful iff all three statuses // of the attempt, the task, and the job equal "SUCCESS" boolean success = taskSuccess && tah.isSuccessful(); if (tah.START_TIME == 0) { LOG.error("Start time 0 for task attempt " + tah.TASK_ATTEMPT_ID); continue; } if (tah.FINISH_TIME < tah.START_TIME) { LOG.error("Finish time " + tah.FINISH_TIME + " is less than " + "Start time " + tah.START_TIME + " for task attempt " + tah.TASK_ATTEMPT_ID); tah.FINISH_TIME = tah.START_TIME; } if (!"MAP".equals(th.TASK_TYPE) && !"REDUCE".equals(th.TASK_TYPE) && !"CLEANUP".equals(th.TASK_TYPE) && !"SETUP".equals(th.TASK_TYPE)) { LOG.error("Unexpected TASK_TYPE = " + th.TASK_TYPE + " for attempt " + tah.TASK_ATTEMPT_ID); } collectPerIntervalStats(output, attemptSubmitTime, tah.START_TIME, th.TASK_TYPE, StatSeries.STAT_LAUNCHED_PENDING_SLOT_TIME); collectPerIntervalStats(output, attemptSubmitTime - jobWaitTime, tah.START_TIME, th.TASK_TYPE, StatSeries.STAT_SUBMIT_PENDING_SLOT_TIME); if (success) collectPerIntervalStats(output, tah.START_TIME, tah.FINISH_TIME, th.TASK_TYPE, StatSeries.STAT_ALL_SLOT_TIME); else collectPerIntervalStats(output, tah.START_TIME, tah.FINISH_TIME, th.TASK_TYPE, StatSeries.STAT_ALL_SLOT_TIME, StatSeries.STAT_FAILED_SLOT_TIME); totalTime += (tah.FINISH_TIME - tah.START_TIME); numAttempts++; if (numAttempts % 500 == 0) { reporter.setStatus("Processing " + jh.JOBID + " at " + numAttempts); } attemptSubmitTime = tah.FINISH_TIME; } } LOG.info("Total Maps = " + jh.TOTAL_MAPS + " Reduces = " + jh.TOTAL_REDUCES); LOG.info("Finished Maps = " + jh.FINISHED_MAPS + " Reduces = " + jh.FINISHED_REDUCES); LOG.info("numAttempts = " + numAttempts); LOG.info("totalTime = " + totalTime); LOG.info("averageAttemptTime = " + (numAttempts == 0 ? 0 : totalTime / numAttempts)); LOG.info("jobTotalTime = " + (jh.FINISH_TIME <= jh.SUBMIT_TIME ? 0 : jh.FINISH_TIME - jh.SUBMIT_TIME)); } } public static class JHLAPartitioner implements Partitioner<Text, Text> { static final int NUM_REDUCERS = 9; public void configure(JobConf conf) { } public int getPartition(Text key, Text value, int numPartitions) { IntervalKey intKey = new IntervalKey(key.toString()); if (intKey.statName.equals(StatSeries.STAT_ALL_SLOT_TIME.toString())) { if (intKey.taskType.equals("MAP")) return 0; else if (intKey.taskType.equals("REDUCE")) return 1; } else if (intKey.statName.equals(StatSeries.STAT_SUBMIT_PENDING_SLOT_TIME.toString())) { if (intKey.taskType.equals("MAP")) return 2; else if (intKey.taskType.equals("REDUCE")) return 3; } else if (intKey.statName.equals(StatSeries.STAT_LAUNCHED_PENDING_SLOT_TIME.toString())) { if (intKey.taskType.equals("MAP")) return 4; else if (intKey.taskType.equals("REDUCE")) return 5; } else if (intKey.statName.equals(StatSeries.STAT_FAILED_SLOT_TIME.toString())) { if (intKey.taskType.equals("MAP")) return 6; else if (intKey.taskType.equals("REDUCE")) return 7; } return 8; } } private static void runJHLA(Class<? extends Mapper<Text, LongWritable, Text, Text>> mapperClass, Path outputDir, Configuration fsConfig) throws IOException { JobConf job = new JobConf(fsConfig, JHLogAnalyzer.class); job.setPartitionerClass(JHLAPartitioner.class); FileInputFormat.setInputPaths(job, INPUT_DIR); job.setInputFormat(SequenceFileInputFormat.class); job.setMapperClass(mapperClass); job.setReducerClass(AccumulatingReducer.class); FileOutputFormat.setOutputPath(job, outputDir); job.setOutputKeyClass(Text.class); job.setOutputValueClass(Text.class); job.setNumReduceTasks(JHLAPartitioner.NUM_REDUCERS); JobClient.runJob(job); } private static class LoggingCollector implements OutputCollector<Text, Text> { public void collect(Text key, Text value) throws IOException { LOG.info(key + " == " + value); } } /** * Run job history log analyser. */ public static void main(String[] args) { Path resFileName = RESULT_FILE; Configuration conf = new Configuration(); try { conf.setInt("test.io.file.buffer.size", 0); Path historyDir = DEFAULT_HISTORY_DIR; String testFile = null; boolean cleanup = false; boolean initControlFiles = true; for (int i = 0; i < args.length; i++) { // parse command line if (args[i].equalsIgnoreCase("-historyDir")) { historyDir = new Path(args[++i]); } else if (args[i].equalsIgnoreCase("-resFile")) { resFileName = new Path(args[++i]); } else if (args[i].equalsIgnoreCase("-usersIncluded")) { conf.set("jhla.users.included", args[++i]); } else if (args[i].equalsIgnoreCase("-usersExcluded")) { conf.set("jhla.users.excluded", args[++i]); } else if (args[i].equalsIgnoreCase("-gzip")) { conf.set("jhla.compression.class", GzipCodec.class.getCanonicalName()); } else if (args[i].equalsIgnoreCase("-jobDelimiter")) { conf.set("jhla.job.delimiter.pattern", args[++i]); } else if (args[i].equalsIgnoreCase("-jobDelimiterLength")) { conf.setInt("jhla.job.delimiter.length", Integer.parseInt(args[++i])); } else if (args[i].equalsIgnoreCase("-noInit")) { initControlFiles = false; } else if (args[i].equalsIgnoreCase("-test")) { testFile = args[++i]; } else if (args[i].equalsIgnoreCase("-clean")) { cleanup = true; } else if (args[i].equalsIgnoreCase("-jobQueue")) { conf.set("mapred.job.queue.name", args[++i]); } else if (args[i].startsWith("-Xmx")) { conf.set("mapred.child.java.opts", args[i]); } else { printUsage(); } } if (cleanup) { cleanup(conf); return; } if (testFile != null) { LOG.info("Start JHLA test ============ "); LocalFileSystem lfs = FileSystem.getLocal(conf); conf.set("fs.defaultFS", "file:///"); JHLAMapper map = new JHLAMapper(conf); map.parseLogFile(lfs, new Path(testFile), 0L, new LoggingCollector(), Reporter.NULL); return; } FileSystem fs = FileSystem.get(conf); if (initControlFiles) createControlFile(fs, historyDir); long tStart = System.currentTimeMillis(); runJHLA(JHLAMapper.class, OUTPUT_DIR, conf); long execTime = System.currentTimeMillis() - tStart; analyzeResult(fs, 0, execTime, resFileName); } catch (IOException e) { System.err.print(StringUtils.stringifyException(e)); System.exit(-1); } } private static void printUsage() { String className = JHLogAnalyzer.class.getSimpleName(); System.err.println("Usage: " + className + "\n\t[-historyDir inputDir] | [-resFile resultFile] |" + "\n\t[-usersIncluded | -usersExcluded userList] |" + "\n\t[-gzip] | [-jobDelimiter pattern] |" + "\n\t[-help | -clean | -test testFile]"); System.exit(-1); } private static Collection<String> getUserList(String users) { if (users == null) return null; StringTokenizer tokens = new StringTokenizer(users, ",;"); Collection<String> userList = new ArrayList<String>(tokens.countTokens()); while (tokens.hasMoreTokens()) userList.add(tokens.nextToken()); return userList; } /** * Result is combined from all reduce output files and is written to * RESULT_FILE in the format * column 1: */ private static void analyzeResult(FileSystem fs, int testType, long execTime, Path resFileName) throws IOException { LOG.info("Analyzing results ..."); DataOutputStream out = null; BufferedWriter writer = null; try { out = new DataOutputStream(fs.create(resFileName)); writer = new BufferedWriter(new OutputStreamWriter(out)); writer.write("SERIES\tPERIOD\tTYPE\tSLOT_HOUR\n"); FileStatus[] reduceFiles = fs.listStatus(OUTPUT_DIR); assert reduceFiles.length == JHLAPartitioner.NUM_REDUCERS; for (int i = 0; i < JHLAPartitioner.NUM_REDUCERS; i++) { DataInputStream in = null; BufferedReader lines = null; try { in = fs.open(reduceFiles[i].getPath()); lines = new BufferedReader(new InputStreamReader(in)); String line; while ((line = lines.readLine()) != null) { StringTokenizer tokens = new StringTokenizer(line, "\t*"); String attr = tokens.nextToken(); String dateTime = tokens.nextToken(); String taskType = tokens.nextToken(); double val = Long.parseLong(tokens.nextToken()) / (double) DEFAULT_TIME_INTERVAL_MSEC; writer.write(attr.substring(2)); // skip the stat type "l:" writer.write("\t"); writer.write(dateTime); writer.write("\t"); writer.write(taskType); writer.write("\t"); writer.write(String.valueOf((float) val)); writer.newLine(); } } finally { if (lines != null) lines.close(); if (in != null) in.close(); } } } finally { if (writer != null) writer.close(); if (out != null) out.close(); } LOG.info("Analyzing results ... done."); } private static void cleanup(Configuration conf) throws IOException { LOG.info("Cleaning up test files"); FileSystem fs = FileSystem.get(conf); fs.delete(new Path(JHLA_ROOT_DIR), true); } }