S-JIS[2010-03-27/2010-04-04] 変更履歴

Hadoop 擬似分散環境

Hadoopの擬似分散モードをWindowsで試す方法について。

擬似分散環境は、分散環境の各サービス(デーモン)を1台のマシン上で動かすモード。
したがって、各サービスの動作方法は本来の分散モードと全く同じになる。


擬似分散環境の構築

Hadoop0.20.2の擬似分散環境をWindowsXP(とCygwin)で構築してみる。

HadoopはUNIXを想定しているので、Windows+Cygwinだと、意外なところで障害が発生する。
以下の設定はWindows用なので、UNIXで擬似分散環境を構築するときは、もっと最小限の設定だけで済むのではないかと思う。

  1. sshをパスフレーズ無しでlocalhostにログインできるよう設定しておく。
    CygwinのOpenSSHの設定
     
  2. 設定ファイルを変更(最初は空なので、実質的には追加)する。
    設定ファイル 内容 備考
    C:\cygwin\usr\local\hadoop-0.20.2\conf\
    core-site.xml
    <configuration>
      <property>
        <name>fs.default.name</name>
        <value>hdfs://localhost:9000</value>
      </property>
    NameNodeの指定。
      <property>
        <name>hadoop.tmp.dir</name>
        <value>C:/cygwin/var/hadoop/hadoop-hishidama</value>
      </property>
    </configuration>
    HDFSの実体を置く場所の指定。
    ローカルパスを指定する。
    C:\cygwin\usr\local\hadoop-0.20.2\conf\
    hdfs-site.xml
    <configuration>
      <property>
        <name>dfs.replication</name>
        <value>1</value>
      </property>
    </configuration>
    レプリケーション数の設定。
    擬似分散環境ではデータの複製を作らないので、1。
    C:\cygwin\usr\local\hadoop-0.20.2\conf\
    mapred-site.xml
    <configuration>
      <property>
        <name>mapred.job.tracker</name>
        <value>localhost:9001</value>
      </property>
    JobTrackerの指定。
      <property>
        <name>mapred.system.dir</name>
        <value>/mapred/system</value>
      </property>
    Map/Reduceのディレクトリー。
    (HDFS内の場所を指定する)
    左記の例では、実際のURLは
    hdfs://localhost:9000/mapred/system
    になる。つまり、
    bin/hadoop fs -ls /mapred/system
    で参照できる。
      <property>
        <name>mapred.child.tmp</name>
        <value>../work2/tmp</value>
      </property>
    </configuration>
    Windows+Cygwinのバグを回避する為の設定。
  3. 分散ファイルシステムを作成する(HDFSのフォーマットを行う)。
    $ /usr/local/hadoop-0.20.2/bin/hadoop namenode -format
  4. Hadoopデーモンを起動する。
    $ /usr/local/hadoop-0.20.2/bin/start-all.sh

Hadoopデーモンを終了させるには、以下のコマンドを実行する。

$ /usr/local/hadoop-0.20.2/bin/stop-all.sh

Webインターフェースによる確認

Hadoopデーモンが起動したら、Webインターフェースで内容を確認することが出来る。

対象 URL 概要 備考
NameNode http://localhost:50070/ クラスターの状態を確認できる。
HDFS(ファイルシステム)が生きているかどうかや、
ログの内容・置かれているファイルの中身も参照できる。
ポート番号を変えたい場合は、hdfs-site.xml
プロパティー「dfs.http.address」を追加する。
デフォルトは「0.0.0.0:50070
HADOOP_HOME/src/hdfs/hdfs-default.xml参照)
JobTracker http://localhost:50030/ Map/Reduceの実行状況を確認できる。 ポート番号を変えたい場合は、mapred-site.xml
プロパティー「mapred.job.tracker.http.address」を追加する。
デフォルトは「0.0.0.0:50030
HADOOP_HOME/src/mapred/mapred-default.xml参照)

Hadoopプロセスの確認

HadoopデーモンはJavaのプログラムなので、jpsコマンド(やpsコマンド)でプロセスが動いている事を確認できる。

クラス名 説明
NameNode ディレクトリー名やファイル名を保持し、
それらがどのDataNodeに格納されているかを管理する。
DataNode 実際のファイル内のデータを保持する。
SecondaryNameNode NameNodeのバックアップ? 擬似分散環境ではあまり必要ないかも。
TaskTracker Map/Reduceの実行を制御する。

ところで、WindowsXPで普通にjpsを実行した場合は、NameNodeとTaskTrackerくらいしか表示されないかもしれない。
NameNodeとTaskTrackerは直接起動されるが、その他のクラスはssh経由で起動されるという違いがある。
ssh経由の場合(CygwinのOpenSSHの場合?)、環境変数はWindowsの各ユーザー用のものは反映されないようだ。つまりシステム共通の環境変数しか使用できない。
jpsコマンドは環境変数TMP(あるいはTEMP)を使用しており、WindowsXPのデフォルトは以下のようになっているのではないかと思う。

定義 環境変数TMPの値
ユーザー環境変数 C:\Documents and Settings\hishidama\Local Settings\Temp
システム環境変数 C:\WINDOWS\TEMP

つまり直接起動されたNameNodeのTMPはユーザー環境変数の値が使われ、jpsコマンド実行時も同じなのでプロセスIDが表示される。
一方、DataNodeはssh経由なのでシステム環境変数の値が使われ、jpsコマンド実行時のTMPとは一致せず、プロセスIDが表示されない。

したがって、jpsコマンド実行前にTMPの値を変更することによって、両方をチェックすることが出来る。

$ TMP="/cygdrive/c/Documents and Settings/hishidama/Local Settings/Temp"
$ jps

$ TMP=/cygdrive/c/WINDOWS/TEMP
$ jps

あるいはユーザー環境変数の内容をシステム環境変数に合わせて「C:\WINDOWS\TEMP」にしてしまえば、jpsコマンド一発で全て表示されるようになる。


HDFSへputする時のエラー

Hadoopデーモンを起動した状態で)HDFSにファイルをコピーしようとしたら、エラーが発生した!

$ cd /home/hadoop/tutorial
$ /usr/local/hadoop-0.20.2/bin/hadoop fs -put input input
2010/03/25 05:36:09 WARN hdfs.DFSClient: DataStreamer Exception: org.apache.hadoop.ipc.RemoteException:
 java.io.IOException: File /user/hishidama/input/file01 could only be replicated to 0 nodes, instead of 1
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:1271)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.addBlock(NameNode.java:422)
〜
	at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2288)

2010/03/25 05:36:09 WARN hdfs.DFSClient: Error Recovery for block null bad datanode[0] nodes == null
2010/03/25 05:36:09 WARN hdfs.DFSClient: Could not get block locations. Source file "/user/hishidama/input/file01" - Aborting...
put: java.io.IOException: File /user/hishidama/input/file01 could only be replicated to 0 nodes, instead of 1
〜

ローカルにある「/home/hadoop/tutorial/input/file*」をHDFSの「/user/hishidama/input〜」にコピーしようとしたもの。
(ちなみに、人によって「hadoop fs -put」としていたり「hadoop dfs -put」としていたりするが、実行されるクラスはどちらも同じ)

HDFSの中を見てみると、ディレクトリーは作られてファイルも(1個は)存在しているのに、中身が空。

$ /usr/local/hadoop-0.20.2/bin/hadoop fs -lsr
drwxr-xr-x   - hishidama supergroup          0 2010-03-25 20:32 /user/hishidama/input
-rw-r--r--   1 hishidama supergroup          0 2010-03-25 20:32 /user/hishidama/input/file01

まぁディレクトリー構造やファイル名はNameNodeが管理していて 実際のデータはDataNodeが保持すると思われるので、
NameNodeは正常に動いたんだけど実際のデータ保持の時点でエラーになったという事だろう。

エラーメッセージも「replicated to 0 nodes, instead of 1」=複製を1個作ろうとしたけど0ノードしか作れなかった→つまり全然作成できなかった、という内容(だと思う)。


ssh(CygwinのOpenSSH)経由で起動しているから、何かの権限不足でディレクトリーにアクセスできないのかもしれないと思って、
DataNodeだけsshを経由させずに直接起動してみた。

●現在稼働中のDataNodeのPIDを確認
$ jps
2304 SecondaryNameNode
2128 DataNode
2676 NameNode
3272 Jps

$ ps | head -1
      PID    PPID    PGID     WINPID  TTY  UID    STIME COMMAND
$ ps | grep 2128
      876       1    3908       2128    ? 1003 01:16:27 /cygdrive/c/Program Files/Java/jdk1.6.0_13/bin/java
●DataNodeのプロセスを停止
$ kill -TERM 876
●DataNodeを(sshを経由せずに)直接起動
$ /usr/local/hadoop-0.20.2/bin/hadoop-daemon.sh start datanode

$ jps
3732 DataNode
2304 SecondaryNameNode
2612 Jps
2676 NameNode
●HDFSへデータコピー
$ cd /home/hadoop/tutorial

$ /usr/local/hadoop-0.20.2/bin/hadoop fs -rmr input
Deleted hdfs://localhost/user/hishidama/input

$ /usr/local/hadoop-0.20.2/bin/hadoop fs -put input input

$ /usr/local/hadoop-0.20.2/bin/hadoop fs -lsr
drwxr-xr-x   - hishidama supergroup          0 2010-03-26 01:29 /user/hishidama/input
-rw-r--r--   1 hishidama supergroup         21 2010-03-26 01:29 /user/hishidama/input/file01
-rw-r--r--   1 hishidama supergroup         27 2010-03-26 01:29 /user/hishidama/input/file02

出来た!


しかしそもそも根本原因は何なのか?を調査する為、DataNodeのログを見てみた。

C:\cygwin\usr\local\hadoop-0.20.2\logs\hadoop-hishidama-datanode-ホスト名.log:

2010-03-26 01:13:33,031 WARN org.apache.hadoop.hdfs.server.datanode.DataNode: java.io.IOException: Expecting a line not the end of stream
	at org.apache.hadoop.fs.DF.parseExecResult(DF.java:109)
	at org.apache.hadoop.util.Shell.runCommand(Shell.java:179)
	at org.apache.hadoop.util.Shell.run(Shell.java:134)
	at org.apache.hadoop.fs.DF.getCapacity(DF.java:63)
	at org.apache.hadoop.hdfs.server.datanode.FSDataset$FSVolume.getCapacity(FSDataset.java:346)
	at org.apache.hadoop.hdfs.server.datanode.FSDataset$FSVolumeSet.getCapacity(FSDataset.java:512)
	at org.apache.hadoop.hdfs.server.datanode.FSDataset.getCapacity(FSDataset.java:708)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.offerService(DataNode.java:702)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.run(DataNode.java:1186)
	at java.lang.Thread.run(Thread.java:619)

なんか、DF.javaというソースで例外が出ている。
このクラスは、dfコマンドProcessBuilderを使って実行するものらしい。
dfコマンドが上手く実行できなくて落ちているわけだ。

そもそもパスが通ってるんかいなーという確認の為、sshコマンドを実行してみる。

$ ssh localhost df

これでディレクトリーの使用量が表示されればOKだが、出てこない。

環境変数PATHも確認してみる。
(Javaから(Cygwinのコマンド等の)exeファイルを絶対パスで指定せずに実行する際には、パスが通っている必要があるから)

$ ssh localhost echo '$PATH'

これで見ると、通常のパスと違って、Windowsのシステム環境変数のパスしか反映されていない模様。
したがって、システム環境変数のPathに「C:\cygwin\bin」を加えてやればいい。
上記のコマンドで見て、「/bin」が含まれていればOK。(もしかすると、デフォルトでPATHの末尾に「/bin」が入っていたかもしれないが)
(ちなみに、Windowsを再起動しないとsshに反映されないかも…?)

ちなみに自分の環境では「C:\bin」もパスに入っていて、しかもDF.exe(ファイル名は同じだが全然別のソフト)が存在していてそちらが優先されていた(爆)
こればっかりはしょうがないので、C:\bin\DF.exeをリネーム(改名)した。普段はショートカット経由で使ってるから、特に問題ない^^;

あるいは、sshログイン時の環境変数を定義してしまうという方法もある。[2010-03-28]
(~/.ssh/environmentに「PATH=/bin」を定義。すると、他のパスは参照できなくなるが、Cygwinのコマンドは使えるのでHadoopの実行としては問題ない)


なお、hadoop fs -putでエラーが発生していると、いつの間にかDataNodeプロセスが落ちていることがあった。
こうなると、プロセスは既に存在していないのに、再始動できなかった。

$ /usr/local/hadoop-0.20.2/bin/start-all.sh
starting namenode, logging to /usr/local/hadoop/bin/../logs/hadoop-hishidama-namenode-hishidama.out
localhost: datanode running as process 1256. Stop it first.
localhost: starting secondarynamenode, logging to /usr/local/hadoop/bin/../logs/hadoop-hishidama-secondarynamenode-hishidama.out
starting jobtracker, logging to /usr/local/hadoop/bin/../logs/hadoop-hishidama-jobtracker-hishidama.out
localhost: starting tasktracker, logging to /usr/local/hadoop/bin/../logs/hadoop-hishidama-tasktracker-hishidama.out

「datanode(プロセスID=1256)が動いているから、先に止めろや」というエラーメッセージが出る。

「kill -0 1256」でプロセスの存在確認をすると正常終了する(プロセスが生きている扱いな)のに、
「kill -TERM 1256」だとプロセスが見つからず、エラーになる…。

$ kill -0 1256
$ echo $?
0

$ kill -TERM 1256
bash: kill: (1256) - No such process

Hadoopのシェルの中では「kill -0」を使ってプロセスの存在確認をしているので、プロセスが存在していると誤解してDataNodeの起動処理を中止してしまう。

この状態に陥ったら、プロセスIDを保持しているファイルを削除して再始動させる。

$ rm /tmp/hadoop-*-datanode.pid
$ /usr/local/hadoop-0.20.2/bin/start-all.sh

今度はnamenodeとかtasktrackerで「既にプロセスが存在している」というエラーが出るが、それはその通りなので問題なし!


putでエラーが起きた際の対処法のまとめ

WindowsXPの擬似分散モードの「bin/hadoop fs -put」でエラーが発生したら、以下の環境構築を行う。


HDFSにアクセスできない場合

「bin/hadoop fs」の「-ls」すら出来ない場合。

$ /usr/local/hadoop-0.20.2/bin/hadoop fs -ls
2010/03/27 02:31:44 INFO ipc.Client: Retrying connect to server: localhost/127.0.0.1:9000. Already tried 0 time(s).
2010/03/27 02:31:46 INFO ipc.Client: Retrying connect to server: localhost/127.0.0.1:9000. Already tried 1 time(s).
〜
2010/03/27 02:32:03 INFO ipc.Client: Retrying connect to server: localhost/127.0.0.1:9000. Already tried 9 time(s).
Bad connection to FS. command aborted.

まずはNameNodeが立ち上がっている事を確認する。
Hadoopのプロセスの確認方法

NameNodeが立ち上がっているなら、ログを確認してみる。

C:\cygwin\usr\local\hadoop-0.20.2\logs\hadoop-hishidama-namenode-ホスト名.log:

2010-03-27 02:30:52,281 INFO org.apache.hadoop.hdfs.server.common.Storage: Storage directory C:\cygwin\var\hadoop\hadoop-hishidama\dfs\name does not exist.
2010-03-27 02:30:52,281 ERROR org.apache.hadoop.hdfs.server.namenode.FSNamesystem: FSNamesystem initialization failed.
org.apache.hadoop.hdfs.server.common.InconsistentFSStateException: Directory C:\cygwin\var\hadoop\hadoop-hishidama\dfs\name is in an inconsistent state: storage directory does not exist or is not accessible.
	at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:290)
	at org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:87)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.initialize(FSNamesystem.java:311)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.(FSNamesystem.java:292)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:201)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.(NameNode.java:279)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:956)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:965)
2010-03-27 02:30:52,281 INFO org.apache.hadoop.ipc.Server: Stopping server on 9000
2010-03-27 02:30:52,281 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: org.apache.hadoop.hdfs.server.common.InconsistentFSStateException: Directory C:\cygwin\var\hadoop\hadoop-hishidama\dfs\name is in an inconsistent state: storage directory does not exist or is not accessible.
	at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:290)
	at org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:87)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.initialize(FSNamesystem.java:311)
	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.(FSNamesystem.java:292)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:201)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.(NameNode.java:279)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:956)
	at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:965)

これは話が簡単で、${hadoop.tmp.dir}/dfs/nameのディレクトリーが存在していない。

定義ファイルのhadoop.tmp.dirの指定を変えた後にHDFSのフォーマットを行っていないと こういう状態になる。
(厳密には、hadoop.tmp.dirではなく、dfs.name.dirの指定だと思う。これの値は、デフォルトが「${hadoop.tmp.dir}/dfs/name」)
なお、フォーマットする際は、HADOOPデーモンを停止してから行う方が確実。


実行時のFileNotFoundException

やれやれ、ようやくput出来るようになったので 対象Map/Reduceを実行してみたら、またエラーが発生した。orz

$ /usr/local/hadoop-0.20.2/bin/hadoop jar wordcount.jar jp.hishidama.hadoop.tutorial.WordCount input output
〜
2010-03-27 03:00:03,625 WARN org.apache.hadoop.mapred.TaskTracker: Error running child
java.io.FileNotFoundException: File C:/cygwin/var/hadoop/hadoop-hishidama/mapred/local/taskTracker/jobcache/job_201003270251_0001/attempt_201003270251_0001_m_000002_0/work/tmp does not exist.
	at org.apache.hadoop.fs.RawLocalFileSystem.getFileStatus(RawLocalFileSystem.java:361)
	at org.apache.hadoop.fs.FilterFileSystem.getFileStatus(FilterFileSystem.java:245)
	at org.apache.hadoop.mapred.TaskRunner.setupWorkDir(TaskRunner.java:519)
	at org.apache.hadoop.mapred.Child.main(Child.java:155)
2010-03-27 03:00:03,625 INFO org.apache.hadoop.mapred.TaskRunner: Runnning cleanup for the task
2010-03-27 03:00:03,625 INFO org.apache.hadoop.mapred.TaskTracker: Error cleaning upjava.lang.NullPointerException
〜

ワークというかtempというか、一時ディレクトリーが無いという事らしい。

スタックトレースに出ているTaskRunnerクラスのsetupWorkDir()メソッドを見てみると、

public static void setupWorkDir(JobConf conf) throws IOException {
〜
	String tmp = conf.get("mapred.child.tmp", "./tmp");
	Path tmpDir = new Path(tmp);

	// if temp directory path is not absolute
	// prepend it with workDir.
	if (!tmpDir.isAbsolute()) {
		tmpDir = new Path(workDir.toString(), tmp);
		FileSystem localFs = FileSystem.getLocal(conf);
		if (!localFs.mkdirs(tmpDir) && !localFs.getFileStatus(tmpDir).isDir()){	←この中で例外発生
			throw new IOException("Mkdirs failed to create " + tmpDir.toString());
		}
	}
}

workDirが「C:/cygwin/var/hadoop/hadoop-hishidama/mapred/local/〜/work」を指しており、それに「./tmp」を付けたディレクトリー(tmpDir)を作ろうとしている。
mkdirs()でディレクトリーを作り、失敗した場合は既にディレクトリーが存在しているかどうかを確認する為にgetFileStatus()を呼び出しているようだ。
で、ディレクトリーが存在していない場合にはgetFileStatus()内部でFileNotFoundExceptionを発生させている。

このソースを見るとmapred.child.tmpが相対パスの場合にディレクトリー作成および存在チェックをしているので、
とりあえず、絶対パスで指定してやればこれらの処理はスキップされる。

設定ファイル 内容 備考
C:\cygwin\usr\local\hadoop-0.20.2\conf\
mapred-site.xml
  <property>
    <name>mapred.child.tmp</name>
    <value>C:/tmp/hadoop/mapred/child/tmp</value>
  </property>
絶対パスで指定する。
絶対パスで指定する場合、
事前にこのディレクトリーを作っておくこと。

しかしそもそも何故ディレクトリー作成に失敗しているか、なのだが。
どうも、この処理へ来る前にこのworkディレクトリー自体は作られているのだが、一旦削除して再作成する仕様になっているようだ。

public static void setupWorkDir(JobConf conf) throws IOException {
	File workDir = new File(".").getAbsoluteFile();	←ディレクトリー名を取得し
	FileUtil.fullyDelete(workDir);			←削除(しようと)している
〜
}

setupWorkDir()の冒頭で、既に存在している「C:/cygwin/var/hadoop/hadoop-hishidama/mapred/local/〜/work」を削除しようとしているのだが、
このworkディレクトリーをCygwinもロックしていて、完全には削除できないようだ(例外は発生しない)。
(つーか、自分のカレントディレクトリーを削除する仕様って、どうなのよ?って気がしないでもないが…JavaVM内では「.」はuser.dirの場所であって実際のカレントディレクトリーではない、とか?)
例外は発生しないのだが、中途半端に残っている状態で、Windowsやコマンドプロンプトからworkが在るのは見えるけれども、中に入れない(アクセス不可)。 当然、workの下にディレクトリーを作ることも出来ない。dir /qで見ると、workの所有者も不明になっている!
が、Cygwin(bash)からは普通にアクセスできる。(通常のUNIXの様に、ディレクトリーを削除しても、元からロックしているプロセスはそのまま使用できるような仕組みになっているのか? でも別プロセスであるはずのCygwinのコンソール(bash)からアクセスできるのは変だよなー)
Windowsからworkを削除しようとしても出来ない。アンロッカーを使って強制的にロックを解除して削除すると、後続のmkdirs()も正常に処理できる。

という訳で、アクセス出来ないworkの下にtmpを作ろうとするからmkdirs()が失敗するので、
mapred.child.tmpも、work以外の場所を指すようにしてやれば、相対パスでも大丈夫。

設定ファイル 内容 備考
C:\cygwin\usr\local\hadoop-0.20.2\conf\
mapred-site.xml
  <property>
    <name>mapred.child.tmp</name>
    <value>../work2/tmp</value>
  </property>
..」でworkの上に戻り、work以外の場所を指定する。
相対パスで指定する場合は実行時にディレクトリーが作られるので
事前の作成は不要。(つーか、どこに作っておけと言うのだw)

正常な動作の例

Map/Reduceが擬似分散環境で正常に動いた場合の出力例。

$ hadoop fs -rmr output
Deleted hdfs://localhost:9000/user/hishidama/output
$ hadoop jar wordcount.jar jp.hishidama.hadoop.tutorial.WordCount input output
2010/03/27 09:58:18 WARN mapred.JobClient: Use GenericOptionsParser for parsing the arguments. Applications should implement Tool for the same.
2010/03/27 09:58:18 INFO input.FileInputFormat: Total input paths to process : 2
2010/03/27 09:58:19 INFO mapred.JobClient: Running job: job_201003270950_0002
2010/03/27 09:58:20 INFO mapred.JobClient: map 0% reduce 0%
2010/03/27 09:58:37 INFO mapred.JobClient: map 100% reduce 0%
2010/03/27 09:58:52 INFO mapred.JobClient: map 100% reduce 100%
2010/03/27 09:58:57 INFO mapred.JobClient: Job complete: job_201003270950_0002

なんか「Toolを使え」という警告が出ているが、とりあえず擬似分散環境で実行する分には問題なさげ。
だが、分散環境では実行時に専用の設定ファイルを生成して-confオプションで指定して実行する構造になっている感じなので、Toolを実装する形式にしておく方が良いようだ。

$ hadoop fs -ls
Found 2 items
drwxr-xr-x   - hishidama supergroup          0 2010-03-27 09:57 /user/hishidama/input
drwxr-xr-x   - hishidama supergroup          0 2010-03-27 09:58 /user/hishidama/output
$ hadoop fs -cat 'output/*'
Bye     1
Goodbye 1
Hadoop  2
Hello   2
World   2
cat: Source must be a file.
$ hadoop fs -get output output

$ cat output/*
cat: output/_logs: Is a directory
Bye     1
Goodbye 1
Hadoop  2
Hello   2
World   2

デバッグ実行

HadoopはJDK1.6のJavaプログラムなので、リモートデバッグを行う事が出来る。

Eclipse側のリモートデバッグの設定

Eclipse側でリモートデバッグの接続を行う設定(デバッグ構成)を準備しておく。
ポート番号はデバッグ対象側の番号(9002とか)に合わせる。


自分のMap/Reduceのメインクラスのリモートデバッグ

HADOOP_HOME/bin/hadoopシェルで実行するJavaアプリに対しては、環境変数HADOOP_OPTSでVM引数を指定する事が出来る。
自分のMap/Reduceのプログラムを実行する前にこの環境変数を設定しておけばよい。(ポート番号は適当)

$ export HADOOP_OPTS=-agentlib:jdwp=transport=dt_socket,address=9002,server=y,suspend=y
$ hadoop jar wordcount.jar jp.hishidama.hadoop.tutorial.WordCount input output
Listening for transport dt_socket at address: 9002
ここでリモートデバッグの接続待ちになるので、Eclipseからデバッグ接続する

これで、WordCountのmain()辺りにブレークポイントを置いておけば、そこで実行が一時停止する。
ただしMap/Reduce本体はTaskTrackerから起動されて別VMで動くので、job.waitForCompletion()あるいはjob.submit()内はデバッグできない。

また、HADOOP_OPTSはhadoopシェルの全プログラムで使われるので、別のコマンドを実行した際にも影響が出てしまう。

$ hadoop fs -rmr output
Listening for transport dt_socket at address: 9002
ここでリモートデバッグの接続待ちになるので、Eclipseからデバッグ接続する
Deleted hdfs://localhost:9000/user/hishidama/output

Hadoopの各デーモンの起動も、表面上はstart-all.shを使っているが、内部ではstart-dfs.sh(start-mapred.sh)→hadoop-daemons.sh→hadoop-daemon.shが呼ばれ、最終的にはhadoopシェルが呼ばれる。
したがって、環境変数の共通の初期化箇所(ログイン時とか、conf/hadoop-env.shとか)にはHADOOP_OPTSのデバッグ指定を入れてはいけない。
(全てのデーモンがデバッグ接続可能状態で起動されるが、ポート番号が競合する)


TaskTrackerのデバッグ

Map/Reduceのプログラムでjob.submit()(あるいはjob.waitForCompletion())が呼ばれると、TaskTrackerがMap/Reduceの実行を開始させる。

TaskTrackerの起動時には環境変数HADOOP_TASKTRACKER_OPTSでTaskTracker専用のVM引数を指定する事が出来る。
start-all.sh(start-mapred.sh)の実行前、あるいはHADOOP_HOME/conf/hadoop-env.sh内で設定する。
(hadoop-env.sh内のHADOOP_TASKTRACKER_OPTSの設定は、デフォルトでは空っぽ)

export HADOOP_TASKTRACKER_OPTS=-agentlib:jdwp=transport=dt_socket,address=9003,server=y,suspend=n

ブレークポイントの仕掛け場所は、org.apache.hadoop.mapred.Childクラス内のTaskRunner.setupWorkDir()を呼んでいる付近になるかな。
TaskTrackerはMap/Reduceの実行用のJavaVMを別途起動するので、Map/Reduceの処理そのものをTaskTrackerでデバッグする事は出来ない。
(JavaVMの起動はTaskRunner.setupWorkDir()内のjvmManager.launchJvm()で行われている)
また、TaskTrackerはタスク毎に呼ばれる。つまりMapTaskでもReduceTaskでも個別に呼ばれるし、複数のMapTaskやReduceTaskに分割されていれば、その都度呼ばれる。

TaskTracker自身は本当の分散環境だと各ノード(マシン)毎に存在するはずなので、どれが実行されるかはそのとき次第だろう。(つまりリモート接続する先のマシンがどれになるのか探さないといけない)
擬似分散環境なら1つしかないので、そこで迷うことは無い。


Mapper・Reducerのデバッグ

Map/Reduceの処理本体は、分散環境ではTaskTrackerから新しいJavaVMが起動されて、そこで実行される。
(ちなみに、Mapper#map()やReducer#reduce()からSystem.outでコンソール出力した場合、HADOOP_HOME/logs/userlogs/attempt_〜/stdoutというファイルに出力される。attempt_に続く文字列はタスクID。)

このJavaVMの起動時のVM引数は、mapred-site.xmlで指定する事が出来る。

設定ファイル 内容 備考
C:\cygwin\usr\local\hadoop-0.20.2\conf\
mapred-site.xml
<property>
  <name>mapred.child.java.opts</name>
  <value>-Xmx200m -agentlib:jdwp=transport=dt_socket,address=9004,server=y,suspend=n</value>
</property>
「-Xmx200m」は、デフォルトの設定。

suspend=nだと、いつEclipse側からリモート接続すればいいか確実なところは分からない。
確実にリモート接続する為にはsuspendをyにしたいところだが、コンソールにメッセージが表示されないので接続待ち状態になっているのかどうか分からない。タスクが分割されるとそれ毎にリモート接続をしないと処理が進まなくなるので、けっこう面倒。
Map/Reduceを直接デバッグするのはあまりお勧めできない最後の手段ってことかな。

タイミング的に、タスクが動く際に前のタスクのリモート接続が残っている場合がある模様。[2010-03-28]
すると、以下のようなエラーが発生する。(運が良ければ、リトライ中に回復して続行される。)

2010/03/28 13:29:01 INFO mapred.JobClient: Task Id : attempt_201003281328_0001_m_000001_0, Status : FAILED
java.io.IOException: Task process exit with nonzero status of 1.
        at org.apache.hadoop.mapred.TaskRunner.run(TaskRunner.java:418)

この場合、ユーザーログにエラーメッセージが残っている。

HADOOP_HOME\logs\userlogs\attempt_201003281328_0001_m_000001_0\stderr:

ERROR: transport error 202: bind failed: Address already in use
ERROR: JDWP Transport dt_socket failed to initialize, TRANSPORT_INIT(510)
JDWP exit error AGENT_ERROR_TRANSPORT_INIT(197): No transports initialized [../../../src/share/back/debugInit.c:690]

「JDWP」で「dt_socket failed」とか「bind」「Address already in use」とか出ているので、デバッグ接続用のポート競合に間違いない。
(エラーとなったポート番号もログに出して欲しいところではあるが)


単独環境の再構築

擬似分散環境の構築後に単独環境を別途作成するには、設定ファイルを置くディレクトリーを新しく作ればよい。[2010-04-04]

  作業内容 設定内容・実施コマンド 備考
1 単独環境用のディレクトリーを作成する。
cd /usr/local/hadoop
mkdir standalone-conf
 
2 デフォルトの設定ファイルをコピーしてくる。
cp -p src/core/core-default.xml standalone-conf/core-site.xml
cp -p src/hdfs/hdfs-default.xml standalone-conf/hdfs-site.xml
cp -p src/mapred/mapred-default.xml standalone-conf/mapred-site.xml
設定ファイルのデフォルト値は
単独環境用の設定になっている。
cp -p conf/hadoop-env.sh standalone-conf/
hadoop-env.shは
クラスパス等の設定を変更しているだろうから
擬似分散環境と同じものを使用する。

再構築した単独環境を指定するには、bin/hadoopシェルの実行時に単独環境の設定ディレクトリーを指定してやる。

$ hadoop --config /usr/local/hadoop/standalone-conf jar wordcount.jar jp.hishidama.hadoop.tutorial.WordCount input output

ただ、いちいち--configオプションを指定するのは面倒なので、環境変数を定義しておくとよい。

$ export HADOOP_CONF_DIR=/usr/local/hadoop/standalone-conf
$ hadoop jar wordcount.jar jp.hishidama.hadoop.tutorial.WordCount input output

Hadoop目次へ戻る / Java目次へ行く / 技術メモへ戻る
メールの送信先:ひしだま