Hadoopの分散処理モードで、サンプルのMapReduceプログラム「pi」を実行してみたログを記録しておきます。

結論から言うと、Hadoopを動かしているマシンのメモリが貧弱でジョブが失敗しました。AWSの無料条件で使っている稼働環境なので、リソース的に無理がありました。その様子の記録です。

１．ジョブ投入前のWebインターフェース状況

サンプルアプリを実行する前は、以下のとおりのWebインターフェースでした。

次にサンプリアプリを起動します。

２．サンプルアプリの起動

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の無料環境で実行しているのですが、もっとメモリがないとキツイです。

３．ジョブ投入後のWebインターフェース状況

Webインターフェースで状況を見てみると、以下の感じでした。

メモリがないと検証も出来ないという事で、この実行環境ではHadoop検証は終了となります。

「Failed Jobs」の状況が確認できた、というだけですが、以上です。