以下は、存在しないプログラムをReduceアプリケーションとしてMapReduce設定ファイルに指定しHadoopジョブの実行が失敗した例です。
途中までReduceタスクが進捗します（例では66%まで）が、その後タイムアウトが発生し、Reduceタスクが失敗しています。その後Hadoopによりリトライされますが、同じ結果が繰り返されジョブがエラーで終了しています。
[hadoop@hadoop1 hadoop01]$ cobhadoop.sh -conf conf/configuration.xml 14/04/24 16:04:02 INFO util.NativeCodeLoader: Loaded the native-hadoop library 14/04/24 16:04:02 WARN snappy.LoadSnappy: Snappy native library not loaded 14/04/24 16:04:03 INFO mapred.FileInputFormat: Total input paths to process : 1 14/04/24 16:04:03 INFO mapred.FileInputFormat: Total input paths to process : 1 14/04/24 16:04:03 INFO mapred.JobClient: Running job: job_201403281518_0350 14/04/24 16:04:04 INFO mapred.JobClient: map 0% reduce 0% 14/04/24 16:04:17 INFO mapred.JobClient: map 50% reduce 0% 14/04/24 16:04:23 INFO mapred.JobClient: map 75% reduce 0% 14/04/24 16:04:24 INFO mapred.JobClient: map 100% reduce 0% 14/04/24 16:04:26 INFO mapred.JobClient: map 100% reduce 25% 14/04/24 16:04:34 INFO mapred.JobClient: Task Id : attempt_201403281518_0350_r_000000_0, Status : FAILED 14/04/24 16:04:35 INFO mapred.JobClient: map 100% reduce 0% 14/04/24 16:04:42 INFO mapred.JobClient: map 100% reduce 33% 14/04/24 16:04:45 INFO mapred.JobClient: Task Id : attempt_201403281518_0350_r_000000_1, Status : FAILED 14/04/24 16:04:46 INFO mapred.JobClient: map 100% reduce 0% 14/04/24 16:04:53 INFO mapred.JobClient: map 100% reduce 25% 14/04/24 16:04:56 INFO mapred.JobClient: Task Id : attempt_201403281518_0350_r_000000_2, Status : FAILED 14/04/24 16:04:57 INFO mapred.JobClient: map 100% reduce 0% 14/04/24 16:05:04 INFO mapred.JobClient: map 100% reduce 33% 14/04/24 16:05:07 INFO mapred.JobClient: map 100% reduce 0% 14/04/24 16:05:10 INFO mapred.JobClient: Job complete: job_201403281518_0350 14/04/24 16:05:10 INFO mapred.JobClient: Counters: 24 14/04/24 16:05:10 INFO mapred.JobClient: Job Counters 14/04/24 16:05:10 INFO mapred.JobClient: Launched reduce tasks=4 14/04/24 16:05:10 INFO mapred.JobClient: SLOTS_MILLIS_MAPS=30402 14/04/24 16:05:10 INFO mapred.JobClient: Total time spent by all reduces waiting after reserving slots (ms)=0 14/04/24 16:05:10 INFO mapred.JobClient: Total time spent by all maps waiting after reserving slots (ms)=0 14/04/24 16:05:10 INFO mapred.JobClient: Launched map tasks=4 14/04/24 16:05:10 INFO mapred.JobClient: Data-local map tasks=4 14/04/24 16:05:10 INFO mapred.JobClient: Failed reduce tasks=1 14/04/24 16:05:10 INFO mapred.JobClient: SLOTS_MILLIS_REDUCES=50585 14/04/24 16:05:10 INFO mapred.JobClient: File Input Format Counters 14/04/24 16:05:10 INFO mapred.JobClient: Bytes Read=0 14/04/24 16:05:10 INFO mapred.JobClient: FileSystemCounters 14/04/24 16:05:10 INFO mapred.JobClient: HDFS_BYTES_READ=194818 14/04/24 16:05:10 INFO mapred.JobClient: FILE_BYTES_WRITTEN=452088 14/04/24 16:05:10 INFO mapred.JobClient: Map-Reduce Framework 14/04/24 16:05:10 INFO mapred.JobClient: Map output materialized bytes=320604 14/04/24 16:05:10 INFO mapred.JobClient: Map input records=10020 14/04/24 16:05:10 INFO mapred.JobClient: Spilled Records=10020 14/04/24 16:05:10 INFO mapred.JobClient: Map output bytes=300540 14/04/24 16:05:10 INFO mapred.JobClient: Total committed heap usage (bytes)=764739584 14/04/24 16:05:10 INFO mapred.JobClient: CPU time spent (ms)=3130 14/04/24 16:05:10 INFO mapred.JobClient: Map input bytes=190320 14/04/24 16:05:10 INFO mapred.JobClient: SPLIT_RAW_BYTES=1032 14/04/24 16:05:10 INFO mapred.JobClient: Combine input records=0 14/04/24 16:05:10 INFO mapred.JobClient: Combine output records=0 14/04/24 16:05:10 INFO mapred.JobClient: Physical memory (bytes) snapshot=777326592 14/04/24 16:05:10 INFO mapred.JobClient: Virtual memory (bytes) snapshot=4139409408 14/04/24 16:05:10 INFO mapred.JobClient: Map output records=10020 EX0003:ジョブの実行に失敗しました。 [hadoop@hadoop1 hadoop01]$
の例では、「attempt_201403281518_0350_r_000000_0」のタスクでエラーが起きていることがわかります。
このため、エラー内容はタスクログを確認する必要があります。
スレーブサーバのタスクログを確認します。
$ more /var/log/hadoop/mapred/userlogs/job_201403281518_0350/attempt_201403281518_0350_r_000000_0/syslog
ログには、タスク実行に伴いHadoopが出力する情報が含まれるため、様々な情報が出力されています。この中から、エラー(ERROR)や例外(Exception)が出力されている箇所を探します。
2014-04-24 16:04:52,279 INFO com.fujitsu.labs.extjoiner.MidFileCommandBuilder: EX0013:コマンドの起動に失敗しました
java.io.IOException: Cannot run program "./reduce.exe": java.io.IOException: error=2, No such file or directory
at java.lang.ProcessBuilder.start(ProcessBuilder.java:460)
at com.fujitsu.labs.extjoiner.MidFileCommandBuilder.startCommand(MidFileCommandBuilder.java:841)
at com.fujitsu.labs.extjoiner.MidFileCommandBuilder.onConfigure(MidFileCommandBuilder.java:475)
at com.fujitsu.labs.extjoiner.ExtJoinerReduce.configure(ExtJoinerReduce.java:122)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.util.ReflectionUtils.setJobConf(ReflectionUtils.java:88)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:64)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:117)
at org.apache.hadoop.mapred.ReduceTask.runOldReducer(ReduceTask.java:485)
at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:420)
at org.apache.hadoop.mapred.Child$4.run(Child.java:255)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1121)
at org.apache.hadoop.mapred.Child.main(Child.java:249)
Caused by: java.io.IOException: java.io.IOException: error=2, No such file or directory
at java.lang.UNIXProcess.<init>(UNIXProcess.java:148)
at java.lang.ProcessImpl.start(ProcessImpl.java:65)
at java.lang.ProcessBuilder.start(ProcessBuilder.java:453)
... 17 more
2014-04-24 16:04:52,280 ERROR com.fujitsu.labs.extjoiner.MidFileCommandBuilder: EX0075:コマンド実行の開始に失敗しました。詳細は例外情報を参照してください。
java.lang.RuntimeException: コマンドの起動に失敗しましたメッセージから、「./reduce.exe」が見つからないためエラーになっていることがわかります。