Pivotal Knowledge Base

フォローする

yarn mapreduceジョブに関するログの探し方と見方

環境 

製品 バージョン
PHD 1.1.1
Centos  6.4
ホスト hdm1 全てのマスタサービスが稼働するHadoopマスタノード
ホスト hdw1、hdw2、hdw3 DataNodeとNodeManagerサービスが稼働するHadoop ワーカーノード

目的

この記事では、失敗したMapreduceジョブのトラブルシューティング手法を例に添えて、MapReduceジョブに関する基本的なワークフローを取り上げる。また、NodeManagerがどのようにコンテナの全てのログを運用・管理するのか、詳しい説明を行う。

Job Client

Job Clientは、MapReduceのジョブの実行を容易にするためにユーザによって使用される。ユーザはMapReduceのジョブを記述する際、通常、ジョブを設定し立ち上げるためにメインクラス内でJob Clientを起動する。以下の例では、Mapperタスクを長時間スリープさせるSleepJobを使用することで、どのようにNodeManagerがジョブを実行しているのか見ることを可能としている。

    Job job = createJob(numMapper, numReducer, mapSleepTime,
                mapSleepCount, reduceSleepTime, reduceSleepCount);
    return job.waitForCompletion(true) ? 0 : 1; 

関数がjob.WaitForCompletionをコールすると、最初に/user/gpadmin/.stagingディレクトリがなければ作り、その後実行ジョブで使用する全てのHadoopパラメータを含むjob.<timestamp>.conf.xml、つまりjob.xmlを作成する。

job.WaitForCompletion のコールで、"hadoop jar" コマンドで使用される "hadoop-mapreduce-client-jobclient.jar" を、/user/gpadmin/.staging ディレクトリーにコピーして、そのコピーしたjar ファイルの名前を "job.jar" に変更する。 "job.jar"ファイルはmapreduceジョブを実行するために全てのコンテナで使用される。

: .staging ディレクトリは /user/${username} 配下に作成される。この記事ではユーザーとしてgpadminを使用している。

[gpadmin@hdw1 ~]$ hdfs dfs -ls /user/gpadmin/.staging/job_1389385968629_0025
Found 7 items
-rw-r--r--   3 gpadmin hadoop          7 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/appTokens
-rw-r--r--  10 gpadmin hadoop    1383034 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job.jar
-rw-r--r--  10 gpadmin hadoop        151 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job.split
-rw-r--r--   3 gpadmin hadoop         19 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job.splitmetainfo
-rw-r--r--   3 gpadmin hadoop      64874 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job.xml
-rw-r--r--   3 gpadmin hadoop          0 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job_1389385968629_0025_1.jhist
-rw-r--r--   3 gpadmin hadoop      75335 2014-02-01 15:28 /user/gpadmin/.staging/job_1389385968629_0025/job_1389385968629_0025_1_conf.xml 

.stagingが作られた後は、Job ClientはジョブをResource Managerサービスに投入する(Application Masterのポート番号:8032)。そしてJob Clientはジョブの実行を監視し続け、MapやReduceの進捗をコンソールに返す。したがって、ジョブを実行している間、"map 5% reduce 0%" といった出力内容を見ることができる。ジョブが完了したら、Job Clientは実行中に取得したいくつかの統計情報を返す。ここでは、Job ClientがApplication Masterから直接、MapとReduceのコンテナの状況を所得することに注目してほしい。こちらについては、もう少し後に詳しく説明するが、ひとまず、以下の例では、Mapコンテナの実行を観察している間、sleep jobにより長い間停止していることが分かる。

[gpadmin@hdm1 ~]$ hadoop jar /usr/lib/gphd/hadoop-mapreduce/hadoop-mapreduce-client-jobclient.jar sleep -m 3 -r 1 -mt 6000000
14/02/01 15:27:59 INFO service.AbstractService: Service:org.apache.hadoop.yarn.client.YarnClientImpl is inited.
14/02/01 15:27:59 INFO service.AbstractService: Service:org.apache.hadoop.yarn.client.YarnClientImpl is started.
14/02/01 15:28:00 INFO mapreduce.JobSubmitter: number of splits:3
14/02/01 15:28:00 INFO mapreduce.JobSubmitter: Submitting tokens for job: job_1389385968629_0025
14/02/01 15:28:01 INFO client.YarnClientImpl: Submitted application application_1389385968629_0025 to ResourceManager at hdm1.hadoop.local/192.168.2.101:8032
14/02/01 15:28:01 INFO mapreduce.Job: The url to track the job: http://hdm1.hadoop.local:8088/proxy/application_1389385968629_0025/
14/02/01 15:28:01 INFO mapreduce.Job: Running job: job_1389385968629_0025
14/02/01 15:28:12 INFO mapreduce.Job: Job job_1389385968629_0025 running in uber mode : false
14/02/01 15:28:12 INFO mapreduce.Job:  map 0% reduce 0%
14/02/01 15:29:06 INFO mapreduce.Job:  map 1% reduce 0%
14/02/01 15:30:37 INFO mapreduce.Job:  map 2% reduce 0%
14/02/01 15:32:08 INFO mapreduce.Job:  map 3% reduce 0%
14/02/01 15:33:38 INFO mapreduce.Job:  map 4% reduce 0%

ヒント:以下のコマンドを実行することでMapReduceジョブをkillすることができる。

[root@hdw3 yarn]# yarn application -kill application_1389385968629_0025

出力内容:

14/02/01 16:53:30 INFO client.YarnClientImpl: Killing application application_1389385968629_0025
14/02/01 16:53:30 INFO service.AbstractService: Service:org.apache.hadoop.yarn.client.YarnClientImpl is stopped. 

Application Master

一度Application Managerサービスがジョブの開始を決めると、org.apache.hadoop.mapreduce.v2.app.MRAppMaster に呼び出されたMapreduce application master classを起動するNodeManagerを1つ選ぶ。

Application Masterサービスは、環境内で実行されているNodeManagerサーバのいずれかで開始される。Resource ManagerによるNodeManagerの決定はクラスタ内の利用可能なリソースに大きく依存している。Node ManagerサービスはApplication Masterコンテナを実行するために使用されているローカルアプリケーションキャッシュ内にシェルスクリプトを生成する。

ここではNodeManagerのyarn-site.xml内で指定された ${yarn.nodemanager.local-dirs} ディレクトリを参照する。

nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/jobSubmitDir
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/jobSubmitDir/job.split
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/jobSubmitDir/appTokens
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/jobSubmitDir/job.splitmetainfo
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/job.xml
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/.default_container_executor.sh.crc
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/launch_container.sh
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/tmp
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/.container_tokens.crc
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/container_tokens
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/job.jar
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/default_container_executor.sh
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/.launch_container.sh.crc

NodeManagerサービスで起動しているコンテナ実行クラスはアプリケーションマスタクラスを実行するlaunch_container.shを使う。以下のように、stdoutやstderrといった全てのログがyarn-site.xml内の ${yarn.nodemanager.log-dirs} で定義された箇所にリダイレクトされていることが分かる。

[gpadmin@hdw3 yarn]# tail -1 nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000001/launch_container.sh
exec /bin/bash -c "$JAVA_HOME/bin/java -Dlog4j.configuration=container-log4j.properties -Dyarn.app.mapreduce.container.log.dir=/data/dn/yarn/userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001 -Dyarn.app.mapreduce.container.log.filesize=0 -Dhadoop.root.logger=INFO,CLA  -Xmx1024m org.apache.hadoop.mapreduce.v2.app.MRAppMaster 1>/data/dn/yarn/userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001/stdout 2>/data/dn/yarn/userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001/stderr  "

一度起動されると、Application MasterはResource Managerに対して、キュー内のMap・Reduceコンテナのためにリソース割当要求を発行する。Resource Managerは、当該リソース割当要求を許可するためクラスタ上に十分なリソースがあることが分かると、どのNodeManagerサービスでコンテナが実行可能なのか、Application Masterに伝える。Application MasterはNodeManagerに対してコンテナを起動するため要求を行う。

MapコンテナとReduceコンテナ

NodeManagerでのコンテナ実行クラスは、Application Masterクラスにおけるmapまたはreduceコンテナで行ったような動作をする。全てのファイルとシェルスクリプトはnm-local-dir内のコンテナ・アプリケーション・クラスに追加される。

nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003
nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/job.xml nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/.default_container_executor.sh.crc nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/launch_container.sh nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/tmp nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/.job.xml.crc nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/.container_tokens.crc nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/container_tokens nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/job.jar nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/default_container_executor.sh nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/.launch_container.sh.crc

: job.jarはアプリケーションファイルキャッシュディレクトリの実体であるjob.jarへのソフトリンクである。これが、yarnのコンテナに対する分散キャッシュの制御方法である。

[root@hdw1 yarn]# ls -l nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/container_1389385968629_0025_01_000003/
total 96
-rw-r--r-- 1 yarn yarn   108 Feb  1 15:25 container_tokens
-rwx------ 1 yarn yarn   450 Feb  1 15:25 default_container_executor.sh
lrwxrwxrwx 1 yarn yarn   122 Feb  1 15:25 job.jar -> /data/dn/yarn/nm-local-dir/usercache/gpadmin/appcache/application_1389385968629_0025/filecache/4395983903529068766/job.jar
-rw-r----- 1 yarn yarn 76430 Feb  1 15:25 job.xml
-rwx------ 1 yarn yarn  2898 Feb  1 15:25 launch_container.sh
drwx--x--- 2 yarn yarn  4096 Feb  1 15:25 tmp  

ヒント: 以下のパラメータを設定することで、上記のコンテナの起動スクリプトとユーザキャッシュが指定された期間についてはシステムに残る。そうでなければアプリケーションが完了した後にこれらのファイルが削除される。

<property>
<name>yarn.nodemanager.delete.debug-delay-sec</name> <value>10000000</value>
</property>

ログファイルの場所

ジョブを実行している間 ${yarn.nodemanager.log-dirs} ディレクトリ内の全てのコンテナログが表示される。

[root@hdw3 yarn]# find userlogs/ -print
userlogs/
userlogs/application_1389385968629_0025
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001/stdout
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001/stderr
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000001/syslog
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000002
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000002/stdout
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000002/stderr
userlogs/application_1389385968629_0025/container_1389385968629_0025_01_000002/syslog 

ジョブが完了すると、NodeManagerは ${yarn.nodemanager.log.retain-seconds} でデフォルトにて10800秒(3時間)各コンテナのログを保持しそれらの有効期限が切れた後それらは削除される。しかし、${yarn.log-aggregation-enable} が有効になっているならば、NodeManagerはすぐに一つのファイルにコンテナログをすべて連結してHDFS上の${yarn.nodemanager.remote-app-log-dir}/${user.name}/logs/<application ID> にそれらをアップロードし、ローカルの userlogs ディレクトリからログを削除する。ログの集約はPHDではデフォルトで有効になっておりログ収集が便利になる。

以下、ログの集約が有効である例を示す。ここでは"-m"でmapperを3つとして、4つのコンテナがMapreduceジョブで実行され、4番目のコンテナがApplication Masterであるものとする。NodeManagerは少なくとも1つのコンテナを持っていて、全てのコンテナはHDFS上にログファイルをアップロードする。

[gpadmin@hdm1 ~]$ hdfs dfs -ls /yarn/apps/gpadmin/logs/application_1389385968629_0025/
Found 3 items
-rw-r-----   3 gpadmin hadoop       4496 2014-02-01 16:54 /yarn/apps/gpadmin/logs/application_1389385968629_0025/hdw1.hadoop.local_30825
-rw-r-----   3 gpadmin hadoop       5378 2014-02-01 16:54 /yarn/apps/gpadmin/logs/application_1389385968629_0025/hdw2.hadoop.local_36429
-rw-r-----   3 gpadmin hadoop    1877950 2014-02-01 16:54 /yarn/apps/gpadmin/logs/application_1389385968629_0025/hdw3.hadoop.local_42186

手順

失敗したmapタスクの確認

この記事に添付したものはApache提供のSleepJobにおいて、MapReduceジョブを改修したものである。失敗したMapコンテナのログを検索できるできるように、mapperの作業のうちランダムに25%が失敗するように変更した。これを試すとジョブは同じmapタスクで3回実行に失敗するかもしれない。

なお、以下のコードをSleep mapperに導入した。

      // Introduce a 25% chance of failing the maptask
      LOG.info("I am checking to see if i should punch myself and fail");
      Random rand = new Random();
      int  n = rand.nextInt(4);
      if ( n == 1 ) {
    	  LOG.info("KAPOW!! owwwwwyy... i failed");
    	  System.exit(123);
      }
      LOG.info("Punching myself seems like a bad idea.. i will just go to sleep instead");
  1. コンテナがジョブの実行中に失敗しているのを見られるだろう。しかしコンテナは再実行しmapreduceジョブが動き続ける。

    14/02/01 17:05:42 INFO client.YarnClientImpl: Submitted application application_1389385968629_0026 to ResourceManager at hdm1.hadoop.local/192.168.2.101:8032
    14/02/01 17:05:42 INFO mapreduce.Job: The url to track the job: http://hdm1.hadoop.local:8088/proxy/application_1389385968629_0026/
    14/02/01 17:05:42 INFO mapreduce.Job: Running job: job_1389385968629_0026
    14/02/01 17:05:52 INFO mapreduce.Job: Job job_1389385968629_0026 running in uber mode : false
    14/02/01 17:05:52 INFO mapreduce.Job:  map 0% reduce 0%
    14/02/01 17:06:28 INFO mapreduce.Job:  map 10% reduce 0%
    14/02/01 17:06:29 INFO mapreduce.Job:  map 15% reduce 0%
    14/02/01 17:06:29 INFO mapreduce.Job: Task Id : attempt_1389385968629_0026_m_000007_0, Status : FAILED
    14/02/01 17:06:30 INFO mapreduce.Job:  map 20% reduce 0%
    14/02/01 17:06:31 INFO mapreduce.Job:  map 25% reduce 0%
    14/02/01 17:06:31 INFO mapreduce.Job: Task Id : attempt_1389385968629_0026_m_000008_0, Status : FAILED
  2. 上出のログから、8回目の現象を詳しく見て処理が失敗する理由を確認してみよう。まず始めに、HDFSからコンテナのログをダウンロードする必要がある。 もし、ログのサイズが大きすぎてダウンロードできない場合は、HDFSから直接catコマンドでログ抽出してもよい。

    [gpadmin@hdm1 logs]$ hdfs dfs -copyToLocal /yarn/apps/gpadmin/logs/application_1389385968629_0026/* ./
    [gpadmin@hdm1 logs]$ ls
    hdw1.hadoop.local_30825  hdw2.hadoop.local_36429  hdw3.hadoop.local_42186
  3. attempt id 8を検索する。時にはcontainer executerはファイルに非ASCIIデータをputすることがあるので、grep -aコマンドでバイナリファイル中のテキスト検索する。最初 "to attempt_1389385968629_0026_m_000008_0" の文字列を検索することで、このattempt IDに対してどのコンテナが割り当てられたか確認することができる。hdw1でApplication Masterサービスが起動しているので、hdw1が当該attempt IDに関連する全ての履歴を保持していることが分かる。Application MasterがMapコンテナと同一マシンで実行可能であることを知っていることは重要である。

    [gpadmin@hdm1 logs]$ egrep -a "to attempt_1389385968629_0026_m_000008_0" *
    hdw1.hadoop.local_30825:2014-02-01 17:03:30,509 INFO [RMCommunicator Allocator] org.apache.hadoop.mapreduce.v2.app.rm.RMContainerAllocator: Assigned container container_1389385968629_0026_01_000010 to attempt_1389385968629_0026_m_000008_0
  4. 次に、上出のログより、コンテナ10が起動した箇所を特定するために、hdw1 の Application Master ログを確認する。以下のログから、当該コンテナはhdw2で起動していたことが分かる。したがって、hdw2 のログファイルを詳しく確認してみる。 

    [gpadmin@hdm1 logs]$ egrep -a "container_1389385968629_0026_01_000010 on NM" hdw1.hadoop.local_30825
    2014-02-01 17:03:30,864 INFO [AsyncDispatcher event handler]
    org.apache.hadoop.mapreduce.v2.app.job.impl.TaskAttemptImpl: TaskAttempt: [attempt_1389385968629_0026_m_000008_0] using containerId: [container_1389385968629_0026_01_000010 on NM: [hdw2.hadoop.local:36429] 
  5. 以下のhdw2のログファイルから根本的な原因が確認できる。このmapタスクは自分自身に障害を加え停止することに決めたようだ(ボールド体で示した添付ファイル内のソースコードを参照)。このように、mapあるいはreduceタスクが失敗した際にコンテナログを確認することは良いことである。なぜなら、タスク失敗時にJob Clientがユーザに報告する java stack trace レポートは、時折、根本的な失敗の原因に関連していない後続のエラーによるものであるからだ。

    (container_1389385968629_0026_01_000010 stderr stdout Fsyslog 2014-02-01 17:03:48,809 WARN [main] org.apache.hadoop.conf.Configuration: job.xml:an attempt to override final parameter: mapreduce.job.end-notification.max.retry.interval;  Ignoring.
    2014-02-01 17:04:11,481 INFO [main] org.apache.hadoop.mapred.MapTask: Processing split: eng.pivotal.hadoop.SleepJobFail$EmptySplit@61ab196b
    2014-02-01 17:04:11,580 INFO [main] org.apache.hadoop.mapred.MapTask: Map output collector class = org.apache.hadoop.mapred.MapTask$MapOutputBuffer
    2014-02-01 17:04:13,883 INFO [main] org.apache.hadoop.mapred.MapTask: (EQUATOR) 0 kvi 134217724(536870896)
    2014-02-01 17:04:13,883 INFO [main] org.apache.hadoop.mapred.MapTask: mapreduce.task.io.sort.mb: 512
    2014-02-01 17:04:13,883 INFO [main] org.apache.hadoop.mapred.MapTask: soft limit at 429496736
    2014-02-01 17:04:13,883 INFO [main] org.apache.hadoop.mapred.MapTask: bufstart = 0; bufvoid = 536870912
    2014-02-01 17:04:13,883 INFO [main] org.apache.hadoop.mapred.MapTask: kvstart = 134217724; length = 33554432
    2014-02-01 17:04:13,953 INFO [main] eng.pivotal.hadoop.SleepJobFail$SleepMapper: I am checking to see if i should punch myself and fail
    2014-02-01 17:04:13,953 INFO [main] eng.pivotal.hadoop.SleepJobFail$SleepMapper: KAPOW!! owwwwwyy... i failed

追加情報

添付ファイル参照のこと: SleepJobFail.tar.gz

コメント

Powered by Zendesk