現場から学ぶWebアプリ開発のトラブルハック 第10回

ThreadとHashMapに潜む
無限回廊は実に面白い？

株式会社NTTデータ　基盤システム事業本部
茂呂 範
2008/3/28

本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい（編集部） 。

マルチスレッドのトラブルハックはさっぱり分からない…

今回の主な内容

【第一章】発生る 【第ニ章】調査る 【第三章】突刺る 【第四章】裏取る 【第五章】机上る 【最終章】防止ぐ 【補足】そのほかの マルチスレッド・トラブル

　対処が難しいトラブルといえば、GC（ガベージ・コレクション）とマルチスレッド処理に起因することが多い。

　前々回（「肥え続けるTomcatと胃を痛めるトラブルハッカー 」）と前回（「JavaのGC頻度に惑わされた年末年始の苦いメモリ 」）の2回にわたってGC、特にメモリ周りのトラブルを取り上げた。そこで今回は、マルチスレッド処理のトラブルの1つ、「レースコンディション（競合状態）」下で発生した状態不整合のトラブルを紹介しよう。

■ マルチスレッド・トラブルの主な3つ

　マルチスレッド処理のトラブルハックは実に難しく、できれば避けて通りたいものだ。しかし、ある程度問題を分類することで、解決のための流れを形式化できる。そこで、マルチスレッド処理には主にどのようなトラブルがあるか、簡単に例を挙げてみよう。

1. ロックやリソース取得の競合による性能劣化
2. ロック取得不整合によるデッドロックやウェイトリーク
3. レースコンディション下による内部状態破壊

　今回のトラブルハックでは、3番目の「レースコンディション下による内部状態破壊」を取り上げてみたい。

　なお残りの2つについては、【補足】という形で本編の最後に、「症状」「発見方法」「解析方法」「対策方法」「有用なツール」という5つの観点で簡単にまとめておいたので、興味のある方は参照していただきたい。

■ 【3】レースコンディション下による内部状態破壊

　繰り返すが、レースコンディションにかかわるトラブルのハックは実に難しい。なぜ難しいか、5つの観点で考えてみよう。

表1　レースコンディション下の内部状態破壊によるトラブルハックの難しさ
症状	機能不全やメモリリーク、デッドロック、プロセスダウンなど、さまざまな症状として表れるため、症状からレースコンディションの問題と判断することが難しい
発見方法	・タイミングに依存しているため、負荷試験が最も有用だが、すべての機能試験と同様の検査を負荷試験として実施する必要があり、現実的に困難 ・ソースコードコードレビューも有効ではあるが、全パターンについてレースコンディション発生を意識してレビューすることは、ソースコードの量からして現実的ではない
解析方法	症状として表れる事象が幅広いため、結果としてレースコンディションが問題だったという結論になることが多い。それまでの過程で現実的に実施できる確立された手法はなく、有識者による解析に頼らざるを得ない
対策方法	確実な排他制御
有効なツール	負荷試験、ソースコードレビュー、場合によってソースコード静的検査ツール

　レースコンディションにかかわるトラブルの問題は、ソースコード上のわずかな記述の違い（具体的には、排他制御の有無など）により、幅広い解析が困難なトラブルを発生させてしまうことであろう。ましてや再現性が低い場合は、そのまま迷宮入りしてしまう。現在は、地道なソースコードレビューや解析に頼らざるを得ないところも問題だ。

　さて、前置きが少し長くなってしまったが、事のあらましからお話しよう。

【第一章】発生（トラブ）る

　トラブルのない平和な日々が続いているなと思っていたある日、出社すると突然部長に腕をつかまれた。

　「ちょうどいいところに来た。すぐについてきてほしい」

　話を聞くと、サービス開始を翌々週に控えたシステムにて、突然アプリケーション（以下、AP）・サーバのCPU使用率が100％に急上昇する事象が発生したらしい。単純にハードの性能不足ではないかと尋ねると、それはないという。なんでも、負荷試験実施中に、それまで20％前後を推移していたCPU使用率が、突然100％に跳ね上がったというのだ。

　私たちは、すぐさま現場へと急行した。

■ 状況証拠の収集 − 友との再会

　現場に到着し、すぐさま情報収集に取り掛かった。まずは性能試験担当から一通り状況を伺おう。今回のトラブルで幸運だったのは、性能試験担当が同期のA君だったことだ。ほぼ3年ぶりの再会が、まさかこのような形になるとはと、若干の雑談をしたがここでは省略しよう。

　早速システム構成を確認した。今回のシステムも、これまで同様Web・AP・DBサーバの3層構成のシステムだ。WebサーバにはApache、APサーバにはTomcat、DBサーバにはPostgreSQLが稼働している。

■ 13分の間に起きた悲劇

　次に、トラブル発生時の状況を時系列で確認した。昨日の22時15分より負荷試験を開始し、APサーバのCPUが20％前後推移していることを確認。その後、20時26分にAPサーバ2系がCPU100％にて事実上の無応答状態へと陥った。WebサーバがAPサーバ2系を切り離し、すべての負荷がAPサーバ1系へと偏った2分後の20時28分に、1系でも同様の事象が発生し、システムがサービス停止状態へと陥った。

　サービス開始直前の、わずか13分の間に起きた悲劇である。

表2　トラブル時の時系列状況
負荷試験 開始	APサーバのCPU使用率は20％程度。それ以外のサーバも問題なし。性能も十分に出ていた
11分後	APサーバ2系にてCPU使用率が100％に急上昇する事象が発生し、APサーバ2系がWebサーバより自動で切り離される
13分後	APサーバ1系でもCPU使用率が100％に急上昇する事象が発生し、事実上のAPサーバ両系ダウンとなり、システム停止となる

■ Tomcat内のどこかで起きた

　最後に、現在の解析状況を確認する。問題となっているプロセスは、Tomcatであるということは確認したが、Tomcat内のどこでCPUを100％使用しているかについては特定できていない状況だった。

　A君はだいぶ疲れている様子だった。おそらく徹夜で調査を続けたのだろう。少しでも早く解決できるよう、早速調査プランの検討を始めた。

【第ニ章】調査（しらべ）る

　さて、Tomcatプロセス内で何かが起きていて、それがCPU使用率100％を引き起こしていることは確かだ。問題は、何が起きているかだ。そして、それをどうやって調べるかだ。今回は、CPU使用率が問題であるため、どのスレッドがCPUを消費しているか特定できれば、解析はグッと容易になる。

　そこで、JavaのスレッドごとのCPU使用率を調べることにした。まずは、その手法を紹介しよう。

　用意する材料は2つ。スレッドダンプとps（process）コマンドの実行結果だ。なおこの手法は、環境に依存してしまうため、ここではOSをLinux、JavaをSun JDK 1.5以上と限定する。Sun JDK 1.4系では、残念ながらこの手法は利用できない。また、スレッドダンプ内のnid（後述）の項目が、LWP（Light Weight Process、スレッドのこと）の値と一致していなければならないという条件がある。Javaのバージョンによっては、親プロセスのプロセスIDが表示されてしまうため、このテクニックは通用しないことに注意する。

■ 手順【1】スレッドダンプの取得

　スレッドダンプの取得は至って簡単だ。

kill -3 <pid>

　JavaプロセスにSIGQUITシグナル（中止の信号）を送信するだけで、Javaプロセスの標準出力にスレッドダンプが出力される。Tomcatならば、catalina.outに出力されるということになる。余談だが、スレッドダンプを解析する際は、数秒置きに2〜3回取得しておくと、後悔することが少ない。

■ スレッドダンプの読み方

　なお、スレッドダンプを読んだことのない方のため、簡単にその読み方を紹介しよう。

Full thread dump Java HotSpot(TM) Server VM (1.5.0_08-b03 mixed mode): "TP-Processor75" daemon prio=1 tid=0x6ba889c8 nid=0x4f8f runnable [0x684c1000..0x684c20b0] at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) ……（中略）…… "VM Periodic Task Thread" prio=1 tid=0x08124440 nid=0x441d waiting on condition

　スレッドダンプには、Javaプロセス上で動作するすべてのスレッドの状態および実行中のスタックトレースが記載されている。項目に記載されている内容を記そう。それぞれのスレッドに関する情報は、下記のフォーマットで出力される（※Java 6では、フォーマットが異なっているため、注意が必要）。

＜スレッド名＞ daemon prio=X tid=0xXXXX nid=0xXXXX <状態> [＜スタックアドレス＞] ＜スタックトレース1行目＞ ＜スタックトレース2行目＞ ・ ・ ・ ＜スタックトレースN行目＞

表3　スレッドダンプに出力されるスレッド情報
スレッド名	スレッドの名前が出力される。「TP-Processor<N>」ならTomcatのリクエスト処理スレッド、「main」ならmainメソッドを実行したスレッド、などとそのスレッドの役割を区別するために利用する
daemon フラグ	スレッドがdaemonスレッド（バックグラウンドで動く常駐プロセス）か否かが出力される。daemonスレッドの場合は、「daemon」と出力され、そうでない場合は何も出力されない。Javaプロセスが終了しないときなど、daemonフラグを持たないスレッドを探すなどに利用する
prio	スレッドの優先度。環境によって異なることに注意する
tid	スレッドID。JavaVM上での管理ID。16進数で出力される
nid	ネイティブID。OS上での管理ID。16進数で出力される。Linuxでは、LWPのIDが出力される
状態	スレッドの状態。スレッドが待ち状態か、動作中かなどを判定する。ボトルネックの解析などに利用する。「runnable」や、「in Object.wait()」などが表示される
スタック アドレス	スタックの開始アドレスと終了アドレス。スタックサイズが妥当であるかを判断するなどに利用する

　ここでポイントとなる点は、「nid」の項目だ。nidは、ネイティブIDの略で、Linux環境ではLWPのIDが表示される。ここで勘の良い読者ならお分かりだろう。このnidを利用して、psコマンドの実行結果と突き合わせると、OSから見たときのスレッドの状況を知ることができる。

■ 手順【2】psコマンドの実行

　psコマンドほど人によって無意識に使うオプションが違うコマンドもないのではないだろうか。本トラブルハックでは、LWPのIDを取得するため、以下のオプションで取得した結果を用いた。

ps -L auxww

 

■ 手順【3】実行結果の突き合わせ

　まず、psコマンドの実行結果よりCPU使用率が高いプロセスのLWPのIDを取得する。そして、LWPのIDと同一のnidを持つスレッドを探し出す。このとき、nidは16進数で表記されているため、10進16進変換を行ってから検索することがポイントだ。

　ここまで説明し終えると、A君の表情に笑顔が戻っていた。早速この手法の実施の承認を得て、調査を開始した。

1-2-3

Index
第10回　ThreadとHashMapに潜む無限回廊は実に面白い？
	Page1 マルチスレッドのトラブルハックはさっぱり分からない… 【第一章】発生る 【第ニ章】調査る
	Page2 【第三章】突刺る 【第四章】裏取る
	Page3 【第五章】机上る 【最終章】防止ぐ 【補足】そのほかのマルチスレッド・トラブル

Java Solution全記事一覧

＠ITメールマガジン　新着情報やスタッフのコラムがメールで届きます（無料）