Hadoopの分散処理モードで、サンプルのMapReduceプログラム「pi」を実行してみたログを記録しておきます。
結論から言うと、Hadoopを動かしているマシンのメモリが貧弱でジョブが失敗しました。AWSの無料条件で使っている稼働環境なので、リソース的に無理がありました。その様子の記録です。
1.ジョブ投入前のWebインターフェース状況
サンプルアプリを実行する前は、以下のとおりのWebインターフェースでした。
次にサンプリアプリを起動します。
2.サンプルアプリの起動
hadoop-examples-1.0.3.jar にて、円周率を計算するプログラム「pi」を動かします。
実行結果は以下のとおりですが、早々に「cannot allocate memory」が出て、最終的に失敗します・・・。
[hadoop@localhost]$ hadoop jar /usr/share/hadoop/hadoop-examples-1.0.3.jar pi 4 10000 Number of Maps = 4 Samples per Map = 10000 Wrote input for Map #0 Wrote input for Map #1 Wrote input for Map #2 Wrote input for Map #3 Starting Job 12/08/21 15:08:48 INFO mapred.FileInputFormat: Total input paths to process : 4 12/08/21 15:08:58 INFO mapred.JobClient: Running job: job_201208211501_0001 12/08/21 15:08:59 INFO mapred.JobClient: map 0% reduce 0% 12/08/21 15:09:44 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000000_0, Status : FAILED java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Task process exit with nonzero status of 137. at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:258) java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more 12/08/21 15:10:30 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000001_0, Status : FAILED java.lang.RuntimeException: Error while running command to get file permissions : java.io.IOException: Cannot run program "/bin/ls": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at org.apache.hadoop.util.Shell.runCommand(Shell.java:200) at org.apache.hadoop.util.Shell.run(Shell.java:182) at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375) at org.apache.hadoop.util.Shell.execCommand(Shell.java:461) at org.apache.hadoop.util.Shell.execCommand(Shell.java:444) at org.apache.hadoop.fs.FileUtil.execCommand(FileUtil.java:710) at org.apache.hadoop.fs.RawLocalFileSystem$RawLocalFileStatus.loadPermissionInfo(RawLocalFileSystem.java:443) at org.apache.hadoop.fs.RawLocalFileSystem$RawLocalFileStatus.getOwner(RawLocalFileSystem.java:426) at org.apache.hadoop.mapred.TaskLog.obtainLogDirOwner(TaskLog.java:267) at org.apache.hadoop.mapred.TaskLogsTruncater.truncateLogs(TaskLogsTruncater.java:124) at org.apache.hadoop.mapred.Child$4.run(Child.java:260) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:416) 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=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 15 more at org.apache.hadoop.fs.RawLocalFileSystem$RawLocalFileStatus.loadPermissionInfo(RawLocalFileSystem.java:468) at org.apache.hadoop.fs.RawLocalFileSystem$RawLocalFileStatus.getOwner(RawLocalFileSystem.java:426) at org.apache.hadoop.mapred.TaskLog.obtainLogDirOwner(TaskLog.java:267) at org.apache.hadoop.mapred.TaskLogsTruncater.truncateLogs(TaskLogsTruncater.java:124) at org.apache.hadoop.mapred.Child$4.run(Child.java:260) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:416) at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1121) at org.apache.hadoop.mapred.Child.main(Child.java:249) 12/08/21 15:14:17 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000001_1, Status : FAILED 12/08/21 15:14:22 WARN mapred.JobClient: Error reading task outputServer returned HTTP response code: 500 for URL: http://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000001_1&filter=stdout 12/08/21 15:14:24 WARN mapred.JobClient: Error reading task outputServer returned HTTP response code: 500 for URL: http://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000001_1&filter=stderr 12/08/21 15:14:33 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000001_2, Status : FAILED java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more 12/08/21 15:14:37 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000001_2&filter=stdout 12/08/21 15:14:37 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000001_2&filter=stderr 12/08/21 15:14:56 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000004_0, Status : FAILED java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more 12/08/21 15:14:56 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_0&filter=stdout 12/08/21 15:14:56 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_0&filter=stderr 12/08/21 15:15:06 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000004_1, Status : FAILED java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more 12/08/21 15:15:06 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_1&filter=stdout 12/08/21 15:15:06 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_1&filter=stderr 12/08/21 15:15:12 INFO mapred.JobClient: Task Id : attempt_201208211501_0001_m_000004_2, Status : FAILED java.lang.Throwable: Child Error at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:271) Caused by: java.io.IOException: Cannot run program "ln": java.io.IOException: error=12, Cannot allocate memory at java.lang.ProcessBuilder.start(ProcessBuilder.java:475) at java.lang.Runtime.exec(Runtime.java:610) at java.lang.Runtime.exec(Runtime.java:448) at java.lang.Runtime.exec(Runtime.java:386) at org.apache.hadoop.fs.FileUtil.symLink(FileUtil.java:567) at org.apache.hadoop.mapred.TaskLog.createTaskAttemptLogDir(TaskLog.java:109) at org.apache.hadoop.mapred.DefaultTaskController.createLogDir(DefaultTaskController.java:71) at org.apache.hadoop.mapred.TaskRunner.prepareLogFiles(TaskRunner.java:316) at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:228) Caused by: java.io.IOException: java.io.IOException: error=12, Cannot allocate memory at java.lang.UNIXProcess.(UNIXProcess.java:164) at java.lang.ProcessImpl.start(ProcessImpl.java:81) at java.lang.ProcessBuilder.start(ProcessBuilder.java:468) ... 8 more 12/08/21 15:15:12 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_2&filter=stdout 12/08/21 15:15:12 WARN mapred.JobClient: Error reading task outputhttp://(省略):50060/tasklog?plaintext=true&attemptid=attempt_201208211501_0001_m_000004_2&filter=stderr 12/08/21 15:15:24 INFO mapred.JobClient: Job complete: job_201208211501_0001 12/08/21 15:15:26 INFO mapred.JobClient: Counters: 7 12/08/21 15:15:26 INFO mapred.JobClient: Job Counters 12/08/21 15:15:26 INFO mapred.JobClient: SLOTS_MILLIS_MAPS=403562 12/08/21 15:15:26 INFO mapred.JobClient: Total time spent by all reduces waiting after reserving slots (ms)=0 12/08/21 15:15:26 INFO mapred.JobClient: Total time spent by all maps waiting after reserving slots (ms)=0 12/08/21 15:15:26 INFO mapred.JobClient: Launched map tasks=6 12/08/21 15:15:26 INFO mapred.JobClient: Data-local map tasks=6 12/08/21 15:15:26 INFO mapred.JobClient: SLOTS_MILLIS_REDUCES=0 12/08/21 15:15:26 INFO mapred.JobClient: Failed map tasks=1 12/08/21 15:15:26 INFO mapred.JobClient: Job Failed: JobCleanup Task Failure, Task: task_201208211501_0001_m_000004 java.io.IOException: Job failed! at org.apache.hadoop.mapred.JobClient.runJob(JobClient.java:1265) at org.apache.hadoop.examples.PiEstimator.estimate(PiEstimator.java:297) at org.apache.hadoop.examples.PiEstimator.run(PiEstimator.java:342) at org.apache.hadoop.util.ToolRunner.run(ToolRunner.java:65) at org.apache.hadoop.examples.PiEstimator.main(PiEstimator.java:351) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.apache.hadoop.util.ProgramDriver$ProgramDescription.invoke(ProgramDriver.java:68) at org.apache.hadoop.util.ProgramDriver.driver(ProgramDriver.java:139) at org.apache.hadoop.examples.ExampleDriver.main(ExampleDriver.java:64) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.apache.hadoop.util.RunJar.main(RunJar.java:156) [hadoop@localhost]$
AWSの無料環境で実行しているのですが、もっとメモリがないとキツイです。
3.ジョブ投入後のWebインターフェース状況
Webインターフェースで状況を見てみると、以下の感じでした。
メモリがないと検証も出来ないという事で、この実行環境ではHadoop検証は終了となります。
「Failed Jobs」の状況が確認できた、というだけですが、以上です。