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.hive.ql.exec; import java.io.IOException; import java.io.Serializable; import java.text.SimpleDateFormat; import java.util.ArrayList; import java.util.Calendar; import java.util.Collections; import java.util.Enumeration; import java.util.HashMap; import java.util.HashSet; import java.util.List; import java.util.Map; import java.util.Set; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.hive.common.JavaUtils; import org.apache.hadoop.hive.conf.HiveConf; import org.apache.hadoop.hive.ql.MapRedStats; import org.apache.hadoop.hive.ql.exec.Operator.ProgressCounter; import org.apache.hadoop.hive.ql.exec.errors.ErrorAndSolution; import org.apache.hadoop.hive.ql.exec.errors.TaskLogProcessor; import org.apache.hadoop.hive.ql.history.HiveHistory.Keys; import org.apache.hadoop.hive.ql.session.SessionState; import org.apache.hadoop.hive.ql.session.SessionState.LogHelper; import org.apache.hadoop.hive.ql.stats.ClientStatsPublisher; import org.apache.hadoop.hive.shims.ShimLoader; import org.apache.hadoop.mapred.Counters; import org.apache.hadoop.mapred.Counters.Counter; import org.apache.hadoop.mapred.JobClient; import org.apache.hadoop.mapred.JobConf; import org.apache.hadoop.mapred.RunningJob; import org.apache.hadoop.mapred.TaskCompletionEvent; import org.apache.hadoop.mapred.TaskReport; import org.apache.log4j.Appender; import org.apache.log4j.FileAppender; import org.apache.log4j.LogManager; public class HadoopJobExecHelper { static final private Log LOG = LogFactory.getLog(HadoopJobExecHelper.class.getName()); protected transient JobConf job; protected Task<? extends Serializable> task; protected transient int mapProgress = 0; protected transient int reduceProgress = 0; public transient String jobId; private LogHelper console; private HadoopJobExecHook callBackObj; /** * Update counters relevant to this task. */ private void updateCounters(Counters ctrs, RunningJob rj) throws IOException { mapProgress = Math.round(rj.mapProgress() * 100); reduceProgress = Math.round(rj.reduceProgress() * 100); task.taskCounters.put("CNTR_NAME_" + task.getId() + "_MAP_PROGRESS", Long.valueOf(mapProgress)); task.taskCounters.put("CNTR_NAME_" + task.getId() + "_REDUCE_PROGRESS", Long.valueOf(reduceProgress)); if (ctrs == null) { // hadoop might return null if it cannot locate the job. // we may still be able to retrieve the job status - so ignore return; } if (callBackObj != null) { callBackObj.updateCounters(ctrs, rj); } } /** * This msg pattern is used to track when a job is started. * * @param jobId * @return */ private static String getJobStartMsg(String jobId) { return "Starting Job = " + jobId; } /** * this msg pattern is used to track when a job is successfully done. * * @param jobId * @return the job end message */ public static String getJobEndMsg(String jobId) { return "Ended Job = " + jobId; } private String getTaskAttemptLogUrl(String taskTrackerHttpAddress, String taskAttemptId) { return taskTrackerHttpAddress + "/tasklog?taskid=" + taskAttemptId + "&all=true"; } public boolean mapStarted() { return mapProgress > 0; } public boolean reduceStarted() { return reduceProgress > 0; } public boolean mapDone() { return mapProgress == 100; } public boolean reduceDone() { return reduceProgress == 100; } public String getJobId() { return jobId; } public void setJobId(String jobId) { this.jobId = jobId; } public HadoopJobExecHelper() { } public HadoopJobExecHelper(JobConf job, LogHelper console, Task<? extends Serializable> task, HadoopJobExecHook hookCallBack) { this.job = job; this.console = console; this.task = task; this.callBackObj = hookCallBack; } /** * A list of the currently running jobs spawned in this Hive instance that is used to kill all * running jobs in the event of an unexpected shutdown - i.e., the JVM shuts down while there are * still jobs running. */ public static Map<String, String> runningJobKillURIs = Collections .synchronizedMap(new HashMap<String, String>()); /** * In Hive, when the user control-c's the command line, any running jobs spawned from that command * line are best-effort killed. * * This static constructor registers a shutdown thread to iterate over all the running job kill * URLs and do a get on them. * */ static { if (new org.apache.hadoop.conf.Configuration().getBoolean("webinterface.private.actions", false)) { Runtime.getRuntime().addShutdownHook(new Thread() { @Override public void run() { killRunningJobs(); } }); } } public static void killRunningJobs() { synchronized (runningJobKillURIs) { for (String uri : runningJobKillURIs.values()) { try { System.err.println("killing job with: " + uri); java.net.HttpURLConnection conn = (java.net.HttpURLConnection) new java.net.URL(uri) .openConnection(); conn.setRequestMethod("POST"); int retCode = conn.getResponseCode(); if (retCode != 200) { System.err.println("Got an error trying to kill job with URI: " + uri + " = " + retCode); } } catch (Exception e) { System.err.println("trying to kill job, caught: " + e); // do nothing } } } } public boolean checkFatalErrors(Counters ctrs, StringBuilder errMsg) { if (ctrs == null) { // hadoop might return null if it cannot locate the job. // we may still be able to retrieve the job status - so ignore return false; } // check for number of created files long numFiles = ctrs.getCounter(ProgressCounter.CREATED_FILES); long upperLimit = HiveConf.getLongVar(job, HiveConf.ConfVars.MAXCREATEDFILES); if (numFiles > upperLimit) { errMsg.append("total number of created files now is " + numFiles + ", which exceeds ") .append(upperLimit); return true; } return this.callBackObj.checkFatalErrors(ctrs, errMsg); } private MapRedStats progress(ExecDriverTaskHandle th) throws IOException { JobClient jc = th.getJobClient(); RunningJob rj = th.getRunningJob(); String lastReport = ""; SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss,SSS"); //DecimalFormat longFormatter = new DecimalFormat("###,###"); long reportTime = System.currentTimeMillis(); long maxReportInterval = 60 * 1000; // One minute boolean fatal = false; StringBuilder errMsg = new StringBuilder(); long pullInterval = HiveConf.getLongVar(job, HiveConf.ConfVars.HIVECOUNTERSPULLINTERVAL); boolean initializing = true; boolean initOutputPrinted = false; long cpuMsec = -1; int numMap = -1; int numReduce = -1; List<ClientStatsPublisher> clientStatPublishers = getClientStatPublishers(); while (!rj.isComplete()) { try { Thread.sleep(pullInterval); } catch (InterruptedException e) { } if (initializing && ShimLoader.getHadoopShims().isJobPreparing(rj)) { // No reason to poll untill the job is initialized continue; } else { // By now the job is initialized so no reason to do // rj.getJobState() again and we do not want to do an extra RPC call initializing = false; } if (!initOutputPrinted) { SessionState ss = SessionState.get(); String logMapper; String logReducer; TaskReport[] mappers = jc.getMapTaskReports(rj.getJobID()); if (mappers == null) { logMapper = "no information for number of mappers; "; } else { numMap = mappers.length; if (ss != null) { ss.getHiveHistory().setTaskProperty(SessionState.get().getQueryId(), getId(), Keys.TASK_NUM_MAPPERS, Integer.toString(numMap)); } logMapper = "number of mappers: " + numMap + "; "; } TaskReport[] reducers = jc.getReduceTaskReports(rj.getJobID()); if (reducers == null) { logReducer = "no information for number of reducers. "; } else { numReduce = reducers.length; if (ss != null) { ss.getHiveHistory().setTaskProperty(SessionState.get().getQueryId(), getId(), Keys.TASK_NUM_REDUCERS, Integer.toString(numReduce)); } logReducer = "number of reducers: " + numReduce; } console.printInfo("Hadoop job information for " + getId() + ": " + logMapper + logReducer); initOutputPrinted = true; } RunningJob newRj = jc.getJob(rj.getJobID()); if (newRj == null) { // under exceptional load, hadoop may not be able to look up status // of finished jobs (because it has purged them from memory). From // hive's perspective - it's equivalent to the job having failed. // So raise a meaningful exception throw new IOException("Could not find status of job:" + rj.getJobID()); } else { th.setRunningJob(newRj); rj = newRj; } // If fatal errors happen we should kill the job immediately rather than // let the job retry several times, which eventually lead to failure. if (fatal) { continue; // wait until rj.isComplete } Counters ctrs = th.getCounters(); if (fatal = checkFatalErrors(ctrs, errMsg)) { console.printError("[Fatal Error] " + errMsg.toString() + ". Killing the job."); rj.killJob(); continue; } errMsg.setLength(0); updateCounters(ctrs, rj); // Prepare data for Client Stat Publishers (if any present) and execute them if (clientStatPublishers.size() > 0 && ctrs != null) { Map<String, Double> exctractedCounters = extractAllCounterValues(ctrs); for (ClientStatsPublisher clientStatPublisher : clientStatPublishers) { try { clientStatPublisher.run(exctractedCounters, rj.getID().toString()); } catch (RuntimeException runtimeException) { LOG.error( "Exception " + runtimeException.getClass().getCanonicalName() + " thrown when running clientStatsPublishers. The stack trace is: ", runtimeException); } } } String report = " " + getId() + " map = " + mapProgress + "%, reduce = " + reduceProgress + "%"; if (!report.equals(lastReport) || System.currentTimeMillis() >= reportTime + maxReportInterval) { // find out CPU msecs // In the case that we can't find out this number, we just skip the step to print // it out. if (ctrs != null) { Counter counterCpuMsec = ctrs.findCounter("org.apache.hadoop.mapred.Task$Counter", "CPU_MILLISECONDS"); if (counterCpuMsec != null) { long newCpuMSec = counterCpuMsec.getValue(); if (newCpuMSec > 0) { cpuMsec = newCpuMSec; report += ", Cumulative CPU " + (cpuMsec / 1000D) + " sec"; } } } // write out serialized plan with counters to log file // LOG.info(queryPlan); String output = dateFormat.format(Calendar.getInstance().getTime()) + report; SessionState ss = SessionState.get(); if (ss != null) { ss.getHiveHistory().setTaskCounters(SessionState.get().getQueryId(), getId(), ctrs); ss.getHiveHistory().setTaskProperty(SessionState.get().getQueryId(), getId(), Keys.TASK_HADOOP_PROGRESS, output); ss.getHiveHistory().progressTask(SessionState.get().getQueryId(), this.task); this.callBackObj.logPlanProgress(ss); } console.printInfo(output); lastReport = report; reportTime = System.currentTimeMillis(); } } if (cpuMsec > 0) { console.printInfo("MapReduce Total cumulative CPU time: " + Utilities.formatMsecToStr(cpuMsec)); } boolean success; Counters ctrs = th.getCounters(); if (fatal) { success = false; } else { // check for fatal error again in case it occurred after // the last check before the job is completed if (checkFatalErrors(ctrs, errMsg)) { console.printError("[Fatal Error] " + errMsg.toString()); success = false; } else { SessionState ss = SessionState.get(); if (ss != null) { ss.getHiveHistory().setTaskCounters(SessionState.get().getQueryId(), getId(), ctrs); } success = rj.isSuccessful(); } } if (ctrs != null) { Counter counterCpuMsec = ctrs.findCounter("org.apache.hadoop.mapred.Task$Counter", "CPU_MILLISECONDS"); if (counterCpuMsec != null) { long newCpuMSec = counterCpuMsec.getValue(); if (newCpuMSec > cpuMsec) { cpuMsec = newCpuMSec; } } } MapRedStats mapRedStats = new MapRedStats(numMap, numReduce, cpuMsec, success, rj.getID().toString()); mapRedStats.setCounters(ctrs); this.task.setDone(); // update based on the final value of the counters updateCounters(ctrs, rj); SessionState ss = SessionState.get(); if (ss != null) { this.callBackObj.logPlanProgress(ss); } // LOG.info(queryPlan); return mapRedStats; } private String getId() { return this.task.getId(); } /** * from StreamJob.java. */ public void jobInfo(RunningJob rj) { if (ShimLoader.getHadoopShims().isLocalMode(job)) { console.printInfo("Job running in-process (local Hadoop)"); } else { if (SessionState.get() != null) { SessionState.get().getHiveHistory().setTaskProperty(SessionState.get().getQueryId(), getId(), Keys.TASK_HADOOP_ID, rj.getJobID()); } console.printInfo(getJobStartMsg(rj.getJobID()) + ", Tracking URL = " + rj.getTrackingURL()); console.printInfo("Kill Command = " + HiveConf.getVar(job, HiveConf.ConfVars.HADOOPBIN) + " job -kill " + rj.getJobID()); } } /** * This class contains the state of the running task Going forward, we will return this handle * from execute and Driver can split execute into start, monitorProgess and postProcess. */ private static class ExecDriverTaskHandle extends TaskHandle { JobClient jc; RunningJob rj; JobClient getJobClient() { return jc; } RunningJob getRunningJob() { return rj; } public ExecDriverTaskHandle(JobClient jc, RunningJob rj) { this.jc = jc; this.rj = rj; } public void setRunningJob(RunningJob job) { rj = job; } @Override public Counters getCounters() throws IOException { return rj.getCounters(); } } // Used for showJobFailDebugInfo private static class TaskInfo { String jobId; HashSet<String> logUrls; public TaskInfo(String jobId) { this.jobId = jobId; logUrls = new HashSet<String>(); } public void addLogUrl(String logUrl) { logUrls.add(logUrl); } public HashSet<String> getLogUrls() { return logUrls; } public String getJobId() { return jobId; } } @SuppressWarnings("deprecation") private void showJobFailDebugInfo(JobConf conf, RunningJob rj) throws IOException { // Mapping from task ID to the number of failures Map<String, Integer> failures = new HashMap<String, Integer>(); // Successful task ID's Set<String> successes = new HashSet<String>(); Map<String, TaskInfo> taskIdToInfo = new HashMap<String, TaskInfo>(); int startIndex = 0; console.printError("Error during job, obtaining debugging information..."); // Loop to get all task completion events because getTaskCompletionEvents // only returns a subset per call while (true) { TaskCompletionEvent[] taskCompletions = rj.getTaskCompletionEvents(startIndex); if (taskCompletions == null || taskCompletions.length == 0) { break; } boolean more = true; boolean firstError = true; for (TaskCompletionEvent t : taskCompletions) { // getTaskJobIDs returns Strings for compatibility with Hadoop versions // without TaskID or TaskAttemptID String[] taskJobIds = ShimLoader.getHadoopShims().getTaskJobIDs(t); if (taskJobIds == null) { console.printError("Task attempt info is unavailable in this Hadoop version"); more = false; break; } // For each task completion event, get the associated task id, job id // and the logs String taskId = taskJobIds[0]; String jobId = taskJobIds[1]; if (firstError) { console.printError("Examining task ID: " + taskId + " (and more) from job " + jobId); firstError = false; } TaskInfo ti = taskIdToInfo.get(taskId); if (ti == null) { ti = new TaskInfo(jobId); taskIdToInfo.put(taskId, ti); } // These tasks should have come from the same job. assert (ti.getJobId() != null && ti.getJobId().equals(jobId)); String taskAttemptLogUrl = ShimLoader.getHadoopShims().getTaskAttemptLogUrl(conf, t.getTaskTrackerHttp(), t.getTaskId()); if (taskAttemptLogUrl != null) { ti.getLogUrls().add(taskAttemptLogUrl); } // If a task failed, then keep track of the total number of failures // for that task (typically, a task gets re-run up to 4 times if it // fails if (t.getTaskStatus() != TaskCompletionEvent.Status.SUCCEEDED) { Integer failAttempts = failures.get(taskId); if (failAttempts == null) { failAttempts = Integer.valueOf(0); } failAttempts = Integer.valueOf(failAttempts.intValue() + 1); failures.put(taskId, failAttempts); } else { successes.add(taskId); } } if (!more) { break; } startIndex += taskCompletions.length; } // Remove failures for tasks that succeeded for (String task : successes) { failures.remove(task); } if (failures.keySet().size() == 0) { return; } // Find the highest failure count int maxFailures = 0; for (Integer failCount : failures.values()) { if (maxFailures < failCount.intValue()) { maxFailures = failCount.intValue(); } } // Display Error Message for tasks with the highest failure count String jtUrl = JobTrackerURLResolver.getURL(conf); for (String task : failures.keySet()) { if (failures.get(task).intValue() == maxFailures) { TaskInfo ti = taskIdToInfo.get(task); String jobId = ti.getJobId(); String taskUrl = jtUrl + "/taskdetails.jsp?jobid=" + jobId + "&tipid=" + task.toString(); TaskLogProcessor tlp = new TaskLogProcessor(conf); for (String logUrl : ti.getLogUrls()) { tlp.addTaskAttemptLogUrl(logUrl); } List<ErrorAndSolution> errors = tlp.getErrors(); StringBuilder sb = new StringBuilder(); // We use a StringBuilder and then call printError only once as // printError will write to both stderr and the error log file. In // situations where both the stderr and the log file output is // simultaneously output to a single stream, this will look cleaner. sb.append("\n"); sb.append("Task with the most failures(" + maxFailures + "): \n"); sb.append("-----\n"); sb.append("Task ID:\n " + task + "\n\n"); sb.append("URL:\n " + taskUrl + "\n"); for (ErrorAndSolution e : errors) { sb.append("\n"); sb.append("Possible error:\n " + e.getError() + "\n\n"); sb.append("Solution:\n " + e.getSolution() + "\n"); } sb.append("-----\n"); console.printError(sb.toString()); // Only print out one task because that's good enough for debugging. break; } } return; } public void localJobDebugger(int exitVal, String taskId) { StringBuilder sb = new StringBuilder(); sb.append("\n"); sb.append("Task failed!\n"); sb.append("Task ID:\n " + taskId + "\n\n"); sb.append("Logs:\n"); console.printError(sb.toString()); for (Appender a : Collections.list((Enumeration<Appender>) LogManager.getRootLogger().getAllAppenders())) { if (a instanceof FileAppender) { console.printError(((FileAppender) a).getFile()); } } } public int progressLocal(Process runningJob, String taskId) { int exitVal = -101; try { exitVal = runningJob.waitFor(); //TODO: poll periodically } catch (InterruptedException e) { } if (exitVal != 0) { console.printError("Execution failed with exit status: " + exitVal); console.printError("Obtaining error information"); if (HiveConf.getBoolVar(job, HiveConf.ConfVars.SHOW_JOB_FAIL_DEBUG_INFO)) { // Since local jobs are run sequentially, all relevant information is already available // Therefore, no need to fetch job debug info asynchronously localJobDebugger(exitVal, taskId); } } else { console.printInfo("Execution completed successfully"); console.printInfo("Mapred Local Task Succeeded . Convert the Join into MapJoin"); } return exitVal; } public int progress(RunningJob rj, JobClient jc) throws IOException { jobId = rj.getJobID(); int returnVal = 0; // remove the pwd from conf file so that job tracker doesn't show this // logs String pwd = HiveConf.getVar(job, HiveConf.ConfVars.METASTOREPWD); if (pwd != null) { HiveConf.setVar(job, HiveConf.ConfVars.METASTOREPWD, "HIVE"); } // replace it back if (pwd != null) { HiveConf.setVar(job, HiveConf.ConfVars.METASTOREPWD, pwd); } // add to list of running jobs to kill in case of abnormal shutdown runningJobKillURIs.put(rj.getJobID(), rj.getTrackingURL() + "&action=kill"); ExecDriverTaskHandle th = new ExecDriverTaskHandle(jc, rj); jobInfo(rj); MapRedStats mapRedStats = progress(th); // Not always there is a SessionState. Sometimes ExeDriver is directly invoked // for special modes. In that case, SessionState.get() is empty. if (SessionState.get() != null) { SessionState.get().getLastMapRedStatsList().add(mapRedStats); } boolean success = mapRedStats.isSuccess(); String statusMesg = getJobEndMsg(rj.getJobID()); if (!success) { statusMesg += " with errors"; returnVal = 2; console.printError(statusMesg); if (HiveConf.getBoolVar(job, HiveConf.ConfVars.SHOW_JOB_FAIL_DEBUG_INFO) || HiveConf.getBoolVar(job, HiveConf.ConfVars.JOB_DEBUG_CAPTURE_STACKTRACES)) { try { JobDebugger jd; if (SessionState.get() != null) { jd = new JobDebugger(job, rj, console, SessionState.get().getStackTraces()); } else { jd = new JobDebugger(job, rj, console); } Thread t = new Thread(jd); t.start(); t.join(HiveConf.getIntVar(job, HiveConf.ConfVars.JOB_DEBUG_TIMEOUT)); } catch (InterruptedException e) { console.printError("Timed out trying to grab more detailed job failure" + " information, please check jobtracker for more info"); } } } else { console.printInfo(statusMesg); } return returnVal; } private Map<String, Double> extractAllCounterValues(Counters counters) { Map<String, Double> exctractedCounters = new HashMap<String, Double>(); for (Counters.Group cg : counters) { for (Counter c : cg) { exctractedCounters.put(cg.getName() + "::" + c.getName(), new Double(c.getCounter())); } } return exctractedCounters; } private List<ClientStatsPublisher> getClientStatPublishers() { List<ClientStatsPublisher> clientStatsPublishers = new ArrayList<ClientStatsPublisher>(); String confString = HiveConf.getVar(job, HiveConf.ConfVars.CLIENTSTATSPUBLISHERS); confString = confString.trim(); if (confString.equals("")) { return clientStatsPublishers; } String[] clientStatsPublisherClasses = confString.split(","); for (String clientStatsPublisherClass : clientStatsPublisherClasses) { try { clientStatsPublishers.add((ClientStatsPublisher) Class .forName(clientStatsPublisherClass.trim(), true, JavaUtils.getClassLoader()).newInstance()); } catch (Exception e) { LOG.warn(e.getClass().getName() + " occured when trying to create class: " + clientStatsPublisherClass.trim() + " implementing ClientStatsPublisher interface"); LOG.warn("The exception message is: " + e.getMessage()); LOG.warn("Program will continue, but without this ClientStatsPublisher working"); } } return clientStatsPublishers; } }