Javaトラブルシューティング メールマガジン
バックナンバー一覧

日付一覧 2011/09/07 14:49:09 2011/06/29 14:48:12 2011/04/13 13:28:19 2011/02/28 14:43:22 2011/01/28 09:38:37 2010/12/22 12:35:18 2010/12/20 10:04:03 2010/08/30 15:30:14 2010/06/23 14:34:27 2010/05/26 14:40:46 2010/05/21 18:23:37 2010/04/27 16:57:13 2010/04/16 16:47:00 2010/03/29 16:53:25 2010/02/19 13:38:46 2009/11/11 14:28:19 2009/08/31 17:08:53 2009/06/19 14:30:51 2009/06/02 16:28:54 2009/05/13 17:25:50 2009/03/17 14:06:50 2009/02/24 16:05:19 2009/01/23 14:50:12 2008/11/19 13:51:45 2008/10/23 11:12:25 2008/10/14 16:23:52 2008/08/29 17:47:43 2008/08/15 18:06:21 2008/07/29 11:05:15 2008/07/02 17:39:04 2008/06/20 16:04:33 2008/06/11 16:00:42 ＝> メルマガ登録ページ

2011/09/07 14:49:09 【JTS】Vol.024：Hadoopを用いたシステムでCPU使用率が高騰しています。 □━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━■         〜全てのJava開発者に贈る〜                      2011/09/07 　　　　　　Javaトラブルシューティング メールマガジン　 Vol.024 　　　　　　https://www.acroquest.co.jp/webworkshop/JTSMM/index.html ■━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━□ 　こんにちは、Acroquestの江里口　温です。 　Javaに関わる様々なトラブルとその対応策を分かりやすく説明する、 　『Javaトラブルシューティング メールマガジン』の第24号です！ ┏━━━━━━━━━━━■□□　CONTENTS　□□■━━━━━━━━━━┓ 　【１】 Javaトラブル事例 　　　Hadoopを用いたシステムでCPU使用率が高騰しています。 ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛ ￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣ 　【１】 Javaトラブル事例 　　Hadoopを用いたシステムでCPU使用率が高騰しています。 ＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿ [問題] 　今回はJava6 update7から標準添付された解析ツール 　VisualVMを用いたトラブルシュートを行う手法を紹介します。 　 　題材は、以下のURLで紹介されている 　HadoopのWordCountタスクです。 　http://hadoop.apache.org/common/docs/r0.20.2/mapred_tutorial.html 　Hadoopを使用しているアプリケーションで、 　CPU使用率が100%に張り付いてしまう現象が発生し、長い処理時間が必要です。 　Java　: Java SE 6.0 update23以降 [解説] 　現象の発生から、問題原因の特定までを解説します。 　�@現象発生 　　DataNodeでjavaプロセスがCPU100%使用しています。 　　まず、topで確認すると、以下の様になっています。 　　 　  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND 　27593 hadoop    25   0  526m 165m  11m S 99.9  8.8   1:35.27 java 　    1 root      15   0 10348  696  584 S  0.0  0.0   0:00.53 init 　    2 root      RT  -5     0    0    0 S  0.0  0.0   0:00.09 migration/0 　    3 root      34  19     0    0    0 S  0.0  0.0   0:00.00 ksoftirqd/0 　    4 root      RT  -5     0    0    0 S  0.0  0.0   0:00.00 watchdog/0 　    5 root      RT  -5     0    0    0 S  0.0  0.0   0:00.10 migration/1        �Aスタックトレースの取得   　何の処理を行っているのかを調査するために、javaのプロセス(PID:27593)に対して   　jstackを実行します。   　   　 >jstack 27593   　   　何度取得しても以下の結果になりました。 　　WordCount.javaの61行目を処理し続けています。    　"main" prio=10 tid=0x000000004fb77800 nid=0x44cc runnable [0x0000000040f8a000] 　   java.lang.Thread.State: RUNNABLE 　at java.util.regex.Pattern$GroupTail.match(Pattern.java:4227) 　at java.util.regex.Pattern$Curly.match0(Pattern.java:3782) 　at java.util.regex.Pattern$Curly.match(Pattern.java:3744) 　at java.util.regex.Pattern$GroupHead.match(Pattern.java:4168) 　at java.util.regex.Pattern$Loop.match(Pattern.java:4295) 　-(略)- 　at java.util.regex.Pattern$Curly.match0(Pattern.java:3782) 　at java.util.regex.Pattern$Curly.match(Pattern.java:3744) 　at java.util.regex.Pattern$GroupHead.match(Pattern.java:4168) 　at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4314) 　at java.util.regex.Pattern$Prolog.match(Pattern.java:4251) 　at java.util.regex.Pattern$Start.match(Pattern.java:3055) 　at java.util.regex.Matcher.search(Matcher.java:1105) 　at java.util.regex.Matcher.find(Matcher.java:535) 　at java.util.regex.Matcher.replaceAll(Matcher.java:809) 　at java.lang.String.replaceAll(String.java:2189) 　at org.myorg.WordCount$Map.map(WordCount.java:61) 　at org.myorg.WordCount$Map.map(WordCount.java:15) 　at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:50) 　at org.apache.hadoop.mapred.MapTask.runOldMapper(MapTask.java:390) 　at org.apache.hadoop.mapred.MapTask.run(MapTask.java:324) 　at org.apache.hadoop.mapred.Child$4.run(Child.java:240) 　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:1115) 　at org.apache.hadoop.mapred.Child.main(Child.java:234) 　 　�Bソースを参照 　　WorkdCount.javaの61行目で呼び出しているString.replaceAllは内部で 　　正規表現を利用します。 　　正規表現として時間がかかるパターンを指定してしまったのが原因と推定できます。 　�Cヒープダンプ取得 　　ヒープダンプを取得して、visualvmでダンプファイルを読み込みます。 　　 　　(ヒープダンプ取得方法は以下を参照してください) 　　　http://www.acroquest.co.jp/seminar/JTSMM/backnumber.cgi?id=121879103926704 　 　　概要タブの「スレッドを表示」をクリックすると、 　　以下の様に、mapメソッドに、3つローカル変数が存在することが分かります。 　at java.lang.String.replaceAll(String.java:2189) 　   Local Variable: java.lang.String#3560 　at org.myorg.WordCount$Map.map(WordCount.java:61) 　   Local Variable: java.lang.String#636 →mapメソッドのローカル変数 　   Local Variable: java.lang.String#635 →mapメソッドのローカル変数 　   Local Variable: java.util.HashMap$KeyIterator#1 →mapメソッドのローカル変数 　at org.myorg.WordCount$Map.map(WordCount.java:15) 　   Local Variable: org.myorg.WordCount$Map#1 　at org.apache.hadoop.mapred.MapRunner.run(MapRunner.java:50) 　   Local Variable: org.apache.hadoop.io.LongWritable#1 　   Local Variable: org.apache.hadoop.mapred.MapTask$OldOutputCollector#1 　   Local Variable: org.apache.hadoop.io.Text#4 　　 　　ソースを参照すると、正規表現のパターンとして利用されているのは、 　　2番目のStringですので、java.lang.String#636をダブルクリックして 　　内容を確認します。 　　※スレッドダンプからローカル変数を参照するには、 　　　Java6 update23以降で実行したヒープダンプを、 　　　VisualVM1.3以降のツールで形跡する必要があります。 　　　Java6 update23以降のJDKにはVisualVM1.3.1以降が同梱されているため、 　　　新たにVisualVMをセットアップする必要はありません。 　�Dローカル変数の内容を確認 　　Stringの内容が"(.*)*^"であることが確認できる。 　　これは、非常に時間がかかる正規表現です。 　　参考:http://moyolab.blog57.fc2.com/blog-entry-73.html 　　 　　ソースを確認すると、この正義表現を 　　単語を数える際にスキップするパターンとして 　　定義ファイルから読み込んでいることが分かりました。 　　hdfsで読み込んだファイルに想定外の文字列が含まれていると推定できます。 　　 　�Ehdfsのファイル確認 　　catすると、確かに(.*)*^がファイルに含まれていました。 　Hadoopでは、扱うデータが巨大になり、意図しないデータが混入した場合に、 　無限ループなどの処理異常が起きた際の解析が難しくなります。 　今回の手法は、他のケースでも使用できますので、 　ご利用ください。 参考URL: 　visualvm 　　http://visualvm.java.net 　●――次号予告――――――――――――――――――――――――――● 　　次号もJaTSで解決した問題に関する情報をお届けする予定です。 　　次号も楽しみにお待ち下さい。 　●――――――――――――――――――――――――――――――――● 　　　　　　　　　　　　　　　　　　　　　　　　◇　2011年09月07日　◇ 　ご意見・ご感想は、jtsmm@acroquest.co.jp までお寄せください。 --------------------------------------------------------------------- ※このメルマガは  「★Acroquest★Ｊａｖａトラブルシューティング メールマガジン」に 　ご登録頂いた方にお届けしております。 　本メールに関するお問合せは、「ご案内元」に記載している 　メールアドレスまでご返信をお願いいたします。 　また、情報配信の停止・削除につきましては「ご案内元」に記載している 　URLにてお手続きをお願いします。 　また、本メールマガジンに掲載されている内容の無断転載を禁じます。 --------------------------------------------------------------------- ──────────────　　ご案内元　　──────────── 　　　　　　　　　　　　Acroquest Technology株式会社 　　　　　　　　　 〜心に響くSmile & Technology〜 　　　　　　　　　　　URL：http://www.acroquest.co.jp/ 　　　　　　　 　　　　　　　　TEL　:045-476-3171 (9:30〜11:30, 12:30〜17:00) 　　　　　　　　　　　　　　　(土日祝日および弊社休業日を除く) 　　メルマガに関するご感想・お問い合わせなど： 　　　jtsmm@acroquest.co.jp 　　メルマガの配信停止、削除等： 　　　https://www.acroquest.co.jp/webworkshop/JTSMM/index.html 　　Acroquest製品に関するお問い合わせ： 　　　https://www.acroquest.co.jp/company/contact.html 　　個人情報開示に関するお問い合わせ　　： 　　　privacy@acroquest.co.jp ──────────────────────────────────

メールマガジン登録ページ