ページの先頭行へ戻る
Interstage Big Data Parallel Processing Server V1.2.0 ユーザーズガイド
FUJITSU Software
第3部 運用編 > 第18章 トラブルシューティング > 18.5 外部プログラム並列実行機能でトラブルが発生した場合 > 18.5.1 ログの出力例と内容の確認方法
前次

18.5.1 ログの出力例と内容の確認方法

外部プログラム並列実行機能を利用した際に出力されるログについて、ジョブ成功時とジョブ失敗時を例に説明します。

ジョブを実行したとき、入力データやプログラム、MapReduce設定ファイルに問題がない場合は、Reduceタスクが100%まで進捗したあと、ジョブの情報が出力され、外部プログラム並列実行コマンドが正常終了します。ジョブの情報はHadoopが出力する情報で、Map/Reduceタスクの入出力レコード件数や、タスクの復帰値が出力されます。

ジョブを実行したとき、入力データやプログラム、MapReduce設定ファイルに問題がある場合は、ジョブはエラーで終了します。ただし、タスクでエラーが発生した場合は、Hadoopによりリトライ（デフォルトは3回）され、エラーが繰り返されるとジョブはエラーで終了します。

18.5.1.1 ジョブ成功時の例

以下は、Hadoopジョブの実行が成功した例です。Mapタスク、Reduceタスクが100%まで進捗し、エラーメッセージが出力されることなく、外部プログラム並列実行コマンドが終了しています。

[bdppuser1@develop sample2]$ /opt/FJSVbdpp/bin/bdpp_submitjob -conf ./conf/configuration.conf -files ./lib/sample2.jar
14/08/19 19:55:57 INFO util.NativeCodeLoader: Loaded the native-hadoop library
14/08/19 19:55:58 WARN snappy.LoadSnappy: Snappy native library not loaded
14/08/19 19:55:58 INFO mapred.FileInputFormat: Total input paths to process : 1
14/08/19 19:55:58 INFO mapred.JobClient: Running job: job_201408191146_0023
14/08/19 19:55:59 INFO mapred.JobClient:  map 0% reduce 0%
14/08/19 19:56:16 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:56:26 INFO mapred.JobClient:  map 100% reduce 16%
14/08/19 19:56:29 INFO mapred.JobClient:  map 100% reduce 50%
14/08/19 19:56:33 INFO mapred.JobClient:  map 100% reduce 100%
14/08/19 19:56:33 INFO mapred.JobClient: Job complete: job_201408191146_0023
14/08/19 19:56:33 INFO mapred.JobClient: Counters: 36
14/08/19 19:56:33 INFO mapred.JobClient:   Job Counters
14/08/19 19:56:33 INFO mapred.JobClient:     Launched reduce tasks=4
14/08/19 19:56:33 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=20388
14/08/19 19:56:33 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0
14/08/19 19:56:33 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0
14/08/19 19:56:33 INFO mapred.JobClient:     Launched map tasks=2
14/08/19 19:56:33 INFO mapred.JobClient:     Data-local map tasks=2
14/08/19 19:56:33 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=52354
14/08/19 19:56:33 INFO mapred.JobClient:   File Input Format Counters
14/08/19 19:56:33 INFO mapred.JobClient:     Bytes Read=0
14/08/19 19:56:33 INFO mapred.JobClient:   File Output Format Counters
14/08/19 19:56:33 INFO mapred.JobClient:     Bytes Written=8894
14/08/19 19:56:33 INFO mapred.JobClient:   FileSystemCounters
14/08/19 19:56:33 INFO mapred.JobClient:     FILE_BYTES_READ=180602
14/08/19 19:56:33 INFO mapred.JobClient:     PDFS_BYTES_READ=385698
14/08/19 19:56:33 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=711086
14/08/19 19:56:33 INFO mapred.JobClient:     PDFS_BYTES_WRITTEN=9332
14/08/19 19:56:33 INFO mapred.JobClient:   Extjoiner.ExitStatus
14/08/19 19:56:33 INFO mapred.JobClient:     map.00=0
14/08/19 19:56:33 INFO mapred.JobClient:     reduce.01=0
14/08/19 19:56:33 INFO mapred.JobClient:     map.01=0
14/08/19 19:56:33 INFO mapred.JobClient:     reduce.00=0
14/08/19 19:56:33 INFO mapred.JobClient:     reduce.03=0
14/08/19 19:56:33 INFO mapred.JobClient:     reduce.02=0
14/08/19 19:56:33 INFO mapred.JobClient:   Map-Reduce Framework
14/08/19 19:56:33 INFO mapred.JobClient:     Map output materialized bytes=185782
14/08/19 19:56:33 INFO mapred.JobClient:     Map input records=10000
14/08/19 19:56:33 INFO mapred.JobClient:     Reduce shuffle bytes=185782
14/08/19 19:56:33 INFO mapred.JobClient:     Spilled Records=18078
14/08/19 19:56:33 INFO mapred.JobClient:     Map output bytes=358578
14/08/19 19:56:33 INFO mapred.JobClient:     Total committed heap usage (bytes)=688914432
14/08/19 19:56:33 INFO mapred.JobClient:     CPU time spent (ms)=9650
14/08/19 19:56:33 INFO mapred.JobClient:     Map input bytes=256625
14/08/19 19:56:33 INFO mapred.JobClient:     SPLIT_RAW_BYTES=506
14/08/19 19:56:33 INFO mapred.JobClient:     Combine input records=0
14/08/19 19:56:33 INFO mapred.JobClient:     Reduce input records=9039
14/08/19 19:56:33 INFO mapred.JobClient:     Reduce input groups=1000
14/08/19 19:56:33 INFO mapred.JobClient:     Combine output records=0
14/08/19 19:56:33 INFO mapred.JobClient:     Physical memory (bytes) snapshot=977354752
14/08/19 19:56:33 INFO mapred.JobClient:     Reduce output records=1000
14/08/19 19:56:33 INFO mapred.JobClient:     Virtual memory (bytes) snapshot=8344576000
14/08/19 19:56:33 INFO mapred.JobClient:     Map output records=9039
[bdppuser1@develop sample2]$

18.5.1.2 ジョブ失敗時の例（実行する外部プログラムが見つからない例）

以下は、存在しないプログラムをReduceアプリケーションしてMapReduce設定ファイルに指定したことにより、Hadoopジョブの実行が失敗した例です

途中までReduceタスクが進捗します（例では66%まで）が、その後タイムアウトが発生し、Reduceタスクが失敗しています。その後Hadoopによりリトライされますが、同じ結果が繰り返されジョブがエラーで終了しています。

[bdppuser1@bdpp-dev sample2]$ /opt/FJSVbdpp/bin/bdpp_submitjob -conf ./conf/configuration.conf -files ./lib/sample2.jar
14/08/19 19:00:58 INFO util.NativeCodeLoader: Loaded the native-hadoop library
14/08/19 19:00:59 WARN snappy.LoadSnappy: Snappy native library not loaded
14/08/19 19:00:59 INFO mapred.FileInputFormat: Total input paths to process : 1
14/08/19 19:00:59 INFO mapred.JobClient: Running job: job_201408191146_0017
14/08/19 19:01:00 INFO mapred.JobClient:  map 0% reduce 0%
14/08/19 19:01:17 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:01:24 INFO mapred.JobClient:  map 100% reduce 33%
14/08/19 19:01:27 INFO mapred.JobClient:  map 100% reduce 66%
14/08/19 19:01:41 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:01:42 INFO mapred.JobClient: Task Id : attempt_201408191146_0017_r_000000_0, Status : FAILED
Task attempt_201408191146_0017_r_000000_0 failed to report status for 10 seconds. Killing!
14/08/19 19:01:52 INFO mapred.JobClient:  map 100% reduce 33%
14/08/19 19:01:56 INFO mapred.JobClient:  map 100% reduce 66%
14/08/19 19:02:09 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:02:10 INFO mapred.JobClient: Task Id : attempt_201408191146_0017_r_000000_1, Status : FAILED
Task attempt_201408191146_0017_r_000000_1 failed to report status for 10 seconds. Killing!
14/08/19 19:02:19 INFO mapred.JobClient:  map 100% reduce 33%
14/08/19 19:02:22 INFO mapred.JobClient:  map 100% reduce 66%
14/08/19 19:02:35 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:02:36 INFO mapred.JobClient: Task Id : attempt_201408191146_0017_r_000000_2, Status : FAILED
Task attempt_201408191146_0017_r_000000_2 failed to report status for 10 seconds. Killing!
14/08/19 19:02:46 INFO mapred.JobClient:  map 100% reduce 33%
14/08/19 19:02:49 INFO mapred.JobClient:  map 100% reduce 66%
14/08/19 19:03:02 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:03:05 INFO mapred.JobClient: Job complete: job_201408191146_0017
14/08/19 19:03:05 INFO mapred.JobClient: Counters: 28
14/08/19 19:03:05 INFO mapred.JobClient:   Job Counters
14/08/19 19:03:05 INFO mapred.JobClient:     Launched reduce tasks=4
14/08/19 19:03:05 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=20602
14/08/19 19:03:05 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0
14/08/19 19:03:05 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0
14/08/19 19:03:05 INFO mapred.JobClient:     Launched map tasks=2
14/08/19 19:03:05 INFO mapred.JobClient:     Data-local map tasks=2
14/08/19 19:03:05 INFO mapred.JobClient:     Failed reduce tasks=1
14/08/19 19:03:05 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=7237
14/08/19 19:03:05 INFO mapred.JobClient:   File Input Format Counters
14/08/19 19:03:05 INFO mapred.JobClient:     Bytes Read=0
14/08/19 19:03:05 INFO mapred.JobClient:   FileSystemCounters
14/08/19 19:03:05 INFO mapred.JobClient:     FILE_BYTES_READ=138
14/08/19 19:03:05 INFO mapred.JobClient:     PDFS_BYTES_READ=385698
14/08/19 19:03:05 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=296808
14/08/19 19:03:05 INFO mapred.JobClient:     PDFS_BYTES_WRITTEN=138
14/08/19 19:03:05 INFO mapred.JobClient:   Extjoiner.ExitStatus
14/08/19 19:03:05 INFO mapred.JobClient:     map.00=0
14/08/19 19:03:05 INFO mapred.JobClient:     map.01=0
14/08/19 19:03:05 INFO mapred.JobClient:   Map-Reduce Framework
14/08/19 19:03:05 INFO mapred.JobClient:     Map output materialized bytes=182942
14/08/19 19:03:05 INFO mapred.JobClient:     Map input records=10000
14/08/19 19:03:05 INFO mapred.JobClient:     Spilled Records=9039
14/08/19 19:03:05 INFO mapred.JobClient:     Map output bytes=358578
14/08/19 19:03:05 INFO mapred.JobClient:     Total committed heap usage (bytes)=635895808
14/08/19 19:03:05 INFO mapred.JobClient:     CPU time spent (ms)=3330
14/08/19 19:03:05 INFO mapred.JobClient:     Map input bytes=256625
14/08/19 19:03:05 INFO mapred.JobClient:     SPLIT_RAW_BYTES=506
14/08/19 19:03:05 INFO mapred.JobClient:     Combine input records=0
14/08/19 19:03:05 INFO mapred.JobClient:     Combine output records=0
14/08/19 19:03:05 INFO mapred.JobClient:     Physical memory (bytes) snapshot=628264960
14/08/19 19:03:05 INFO mapred.JobClient:     Virtual memory (bytes) snapshot=2754908160
14/08/19 19:03:05 INFO mapred.JobClient:     Map output records=9039
EX0003:ジョブの実行に失敗しました。
[bdppuser1@bdpp-dev sample2]$

この例では、「attempt_201408191146_0017_r_000000_2」のタスクでエラーが起きていることがわかります。

このため、エラー内容はタスクログを確認する必要があります。

スレーブサーバのタスクログを確認します。

$ more /var/log/hadoop/mapred/userlogs/job_201408191146_0017/attempt_201408191146_0017_r_000000_2/syslog

ログには、タスク実行に伴いHadoopが出力する情報が含まれるため、様々な情報が出力されています。この中から、エラー(ERROR)や例外(Exception)が出力されている箇所を探します。

2014-08-19 19:03:04,279 INFO com.fujitsu.labs.extjoiner.MidFileCommandBuilder: コマンドの起動に失敗しました
java.io.IOException: Cannot run program "Aggregate": 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-08-19 19:03:04,280 ERROR com.fujitsu.labs.extjoiner.MidFileCommandBuilder: コマンド実行の開始に失敗しました。詳細は例外情報を参照してください。
java.lang.RuntimeException: コマンドの起動に失敗しました

メッセージから、「Aggregate」という外部プログラムが見つからないためエラーになっていることがわかります。


18.5.1.3 ジョブ失敗時の例（外部プログラムで実行時エラーが起きている例）

以下は、ReduceタスクとしてJava言語で実装した外部プログラムを実行した際、実行時エラーが発生しHadoopジョブの実行が失敗した例です。

Reduceタスクは100%まで進捗しますが、ジョブはエラーで終了します。

[bdppuser1@develop sample2]$ /opt/FJSVbdpp/bin/bdpp_submitjob -conf ./conf/configuration.conf -files ./lib/sample2.jar
14/08/19 19:49:04 INFO util.NativeCodeLoader: Loaded the native-hadoop library
14/08/19 19:49:05 WARN snappy.LoadSnappy: Snappy native library not loaded
14/08/19 19:49:05 INFO mapred.FileInputFormat: Total input paths to process : 1
14/08/19 19:49:05 INFO mapred.JobClient: Running job: job_201408191146_0022
14/08/19 19:49:06 INFO mapred.JobClient:  map 0% reduce 0%
14/08/19 19:49:21 INFO mapred.JobClient:  map 100% reduce 0%
14/08/19 19:49:31 INFO mapred.JobClient:  map 100% reduce 16%
14/08/19 19:49:33 INFO mapred.JobClient:  map 100% reduce 50%
14/08/19 19:49:35 INFO mapred.JobClient:  map 100% reduce 75%
14/08/19 19:49:36 INFO mapred.JobClient:  map 100% reduce 100%
14/08/19 19:49:37 INFO mapred.JobClient: Job complete: job_201408191146_0022
14/08/19 19:49:37 INFO mapred.JobClient: Counters: 36
14/08/19 19:49:37 INFO mapred.JobClient:   Job Counters
14/08/19 19:49:37 INFO mapred.JobClient:     Launched reduce tasks=4
14/08/19 19:49:37 INFO mapred.JobClient:     SLOTS_MILLIS_MAPS=20661
14/08/19 19:49:37 INFO mapred.JobClient:     Total time spent by all reduces waiting after reserving slots (ms)=0
14/08/19 19:49:37 INFO mapred.JobClient:     Total time spent by all maps waiting after reserving slots (ms)=0
14/08/19 19:49:37 INFO mapred.JobClient:     Launched map tasks=2
14/08/19 19:49:37 INFO mapred.JobClient:     Data-local map tasks=2
14/08/19 19:49:37 INFO mapred.JobClient:     SLOTS_MILLIS_REDUCES=48704
14/08/19 19:49:37 INFO mapred.JobClient:   File Input Format Counters
14/08/19 19:49:37 INFO mapred.JobClient:     Bytes Read=0
14/08/19 19:49:37 INFO mapred.JobClient:   File Output Format Counters
14/08/19 19:49:37 INFO mapred.JobClient:     Bytes Written=0
14/08/19 19:49:37 INFO mapred.JobClient:   FileSystemCounters
14/08/19 19:49:37 INFO mapred.JobClient:     FILE_BYTES_READ=182454
14/08/19 19:49:37 INFO mapred.JobClient:     PDFS_BYTES_READ=385698
14/08/19 19:49:37 INFO mapred.JobClient:     FILE_BYTES_WRITTEN=711020
14/08/19 19:49:37 INFO mapred.JobClient:     PDFS_BYTES_WRITTEN=2290
14/08/19 19:49:37 INFO mapred.JobClient:   Extjoiner.ExitStatus
14/08/19 19:49:37 INFO mapred.JobClient:     map.00=0
14/08/19 19:49:37 INFO mapred.JobClient:     reduce.01=1
14/08/19 19:49:37 INFO mapred.JobClient:     map.01=0
14/08/19 19:49:37 INFO mapred.JobClient:     reduce.00=1
14/08/19 19:49:37 INFO mapred.JobClient:     reduce.03=1
14/08/19 19:49:37 INFO mapred.JobClient:     reduce.02=1
14/08/19 19:49:37 INFO mapred.JobClient:   Map-Reduce Framework
14/08/19 19:49:37 INFO mapred.JobClient:     Map output materialized bytes=185782
14/08/19 19:49:37 INFO mapred.JobClient:     Map input records=10000
14/08/19 19:49:37 INFO mapred.JobClient:     Reduce shuffle bytes=185782
14/08/19 19:49:37 INFO mapred.JobClient:     Spilled Records=18078
14/08/19 19:49:37 INFO mapred.JobClient:     Map output bytes=358578
14/08/19 19:49:37 INFO mapred.JobClient:     Total committed heap usage (bytes)=689766400
14/08/19 19:49:37 INFO mapred.JobClient:     CPU time spent (ms)=9480
14/08/19 19:49:37 INFO mapred.JobClient:     Map input bytes=256625
14/08/19 19:49:37 INFO mapred.JobClient:     SPLIT_RAW_BYTES=506
14/08/19 19:49:37 INFO mapred.JobClient:     Combine input records=0
14/08/19 19:49:37 INFO mapred.JobClient:     Reduce input records=9039
14/08/19 19:49:37 INFO mapred.JobClient:     Reduce input groups=1000
14/08/19 19:49:37 INFO mapred.JobClient:     Combine output records=0
14/08/19 19:49:37 INFO mapred.JobClient:     Physical memory (bytes) snapshot=983425024
14/08/19 19:49:37 INFO mapred.JobClient:     Reduce output records=0
14/08/19 19:49:37 INFO mapred.JobClient:     Virtual memory (bytes) snapshot=8349315072
14/08/19 19:49:37 INFO mapred.JobClient:     Map output records=9039
EX0003:ジョブの実行に失敗しました。
[bdppuser1@develop sample2]$

ログから、Reduceタスクが復帰値1を返していることがわかります。

発生したエラーを確認するために、外部プログラムが出力した情報を参照します。

[bdppuser1@develop sample2]$ hadoop dfs -copyToLocal sample2_output ./sample2_output
14/08/19 19:52:43 INFO util.NativeCodeLoader: Loaded the native-hadoop library
[bdppuser1@develop sample2]$ tail sample2_output/currentdir/part-r-00000/stderr

ログ抜粋

Exception in thread "main" java.lang.NoClassDefFoundError: Join
Caused by: java.lang.ClassNotFoundException: Join
        at java.net.URLClassLoader$1.run(URLClassLoader.java:202)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:190)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
Could not find the main class: Join.  Program will exit.

上記から、実行しようとしたクラスが見つからなかったためにエラーとなっていることがわかります。


前次
Copyright 2015 FUJITSU LIMITED