Java on Linux でのトラブルシューティング

こんにちは。次世代システム研究室のY.I.です。
最近参画した歴史あるプロジェクトで行ったトラブルシューティングの話題です。

アプリケーションの概要は
CentOS 上の Tomcat で動作するサーバサイド Java アプリケーションとなっています。

今回は
「メモリ不足によるトラブルの対処」と「Java スレッドがデッドロックしてしまった件」をどのように調べて解決したかをお伝えします。

◆メモリ不足によるトラブルの対処について

連携先との兼ね合いで Tomcat サーバから Apache サーバへ ssh して連携媒体と通信する機能がありました。こちらが2日に1回程度エラーになり Tomcat を再起動するまで失敗し続けるという状況になっていました。

エラーログ

ERROR [InitAction.postProcess:132] ssh error web server ip=192.168.XXX.XXX

こちらのエラーが Tomcat を再起動するまで出力され続けていました。
これだけでは原因究明も難しい状況で何を契機として発生するのがわからない状況でした。

調査方法

まとめると以下の順番で確認を行いました。

障害時のサーバリソース状況の確認（sar）
↓
メモリ使用状況の確認（free/vmstat/top）
↓
Tomcat(JVM)メモリ割当の削減（jstat）

障害時のサーバリソース状況の確認

今回は Linux コマンドの sar コマンドを使って確認しました。 sar コマンドはメモリ使用状況、CPU使用状況、ロードアベレージ、DISK I/O、NW I/O　などを確認することができます。また、過去数日分の履歴を持っているため振り返って過去の状況を確認することができます。そのため障害時の復旧を再優先しても後からリソース状況を確認することができます。

sar -f /var/log/sa/sa01　（過去日のリソースを表示）

-f で sa ファイルを指定します。
 sa01 だと1日
 sa02 だと2日
 sa10 だと10日
という指定の仕方になります。

sar -r -f /var/log/sa/sa01（1日のメモリ使用状況を確認できます）

4列目の %memused にメモリ使用率をご覧ください。
エラーはメモリ使用率99%を越えている時間帯に発生していました。
但し kbbuffersとkbcachedに4GB以上割あたっているのでメモリの余裕はあるという謎が残りました。

00時00分01秒 kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
00時10分01秒    832556  11462828     93.23    450740   4349456   2096896       248      0.01         0
00時20分01秒    823304  11472080     93.30    450748   4349848   2096896       248      0.01         0
11時10分01秒    812980  11482404     93.39    450836   4335068   2096896       248      0.01         0
11時20分01秒    524760  11770624     95.73    450840   4335852   2096896       248      0.01         0
11時30分01秒     68400  12226984     99.44    450788   4286160   2096896       248      0.01         0
11時40分01秒    121816  12173568     99.01    449372   4133184   2096896       248      0.01         0
11時50分01秒    110592  12184792     99.10    449376   4133760   2096896       248      0.01         0
12時00分01秒    101120  12194264     99.18    449380   4134288   2096896       248      0.01         0
12時10分01秒     92684  12202700     99.25    449388   4134180   2096896       248      0.01         0
12時20分01秒     81540  12213844     99.34    449388   4134608   2096896       248      0.01         0
12時30分01秒     69788  12225596     99.43    449388   4135048   2096896       248      0.01         0
12時40分01秒    112316  12183068     99.09    449388   4135420   2096896       248      0.01         0
12時50分01秒    105316  12190068     99.14    449388   4135864   2096896       248      0.01         0

他には以下をはじめ多くの内容を表示することができます。

sar -u（CPU使用状況を確認できます）
sar -q（ロードアベレージを確認できます）
sar -n DEV 1 | grep eth0（NW使用状況を確認できます。例では NIC を eth0 のみとしてます）
sar -n SOCK（ソケット使用状況を確認できます）

メモリ使用状況の確認

sar コマンドによりメモリ使用率が99%になっているためにエラーが発生している可能性があると原因が見えてきたので、次に OS のメモリ使用状況および Tomcat のメモリ使用状況を確認しました。

OSメモリの確認コマンド

OSメモリの確認に使ったコマンドは以下の通りです。
free コマンドと vmstat コマンドや top コマンドです。

free -m（-m でMB単位で表示）

※当時の free コマンドの結果が残っておらず平常時の結果となっています

             total       used       free     shared    buffers     cached
Mem:         12007      11733        273          0        448       4341
-/+ buffers/cache:       6944       5062
Swap:         2047          0       2047

vmstat -a 3（-a で active/inactive を表示、 ３は３秒おきに繰り返し表示となります）

※当時の vmstat コマンドの結果が残っておらず平常時の結果となっています

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free  inact active   si   so    bi    bo   in   cs us sy id wa st
 1  0    244 276792 1314676 10356872    0    0     0     8    0    0  6  0 93  0  0
 0  0    244 276800 1314676 10356872    0    0     0     0 1889 1104  3  0 96  0  0
 0  0    244 276980 1314672 10356876    0    0     0     0 1945 1002  2  0 98  0  0
 1  0    244 277072 1314672 10356876    0    0     0   916 4377 1370  9  0 90  0  0

Tomcat（JVM）メモリの確認コマンド

JDK で提供される jstat コマンドで確認しました。

jstat -gcutil プロセスID 表示間隔(msec)

（例）jstat -gcutil 29293 5000　（javaプロセス29293のメモリ使用率を 5秒毎に表示）

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
 49.84   0.00  58.48  37.15  15.80  40038  249.218    22   20.509  269.727

ヒープ領域

S0 Survivor領域0のメモリ使用率（現在の容量に対するパーセンテージ）
S1 Survivor領域1のメモリ使用率（現在の容量に対するパーセンテージ）
E　Eden領域のメモリ使用率（現在の容量に対するパーセンテージ）
O　Old領域

パーマネント領域

P　Permanent領域のメモリ使用率（現在の容量に対するパーセンテージ）
※java8では値が表示されません

読み取れる内容

・S0, E ともに50%程度しか使用していない
->もっとヒープメモリを減らせるはず！
->2.5GB程度減らしても問題ないと判断
->FullGCの頻度は増えてしまうが一回のGC時間が短くなるメリットもあるはず
・Pは15.8%程度しか使用していない
->もっとパーマネントメモリを減らせるはず！
->50%程度減らしても問題ないと判断

Tomcat(JVM)メモリ割当の削減

Tomcat起動パラメータのメモリ割当量を以下の通りに変更しました。

変更前
-Xms9216m -Xmx9216m -XX:PermSize=256m -XX:MaxPermSize=512m

変更後
-Xms6553m -Xmx6553m -XX:PermSize=128m -XX:MaxPermSize=256m

変更内容

->ヒープメモリ割当を9GBから6.5GBへ、Permanent割当を512MBから256MBへ

まとめ

上記のようにTomcat（JVM）へのメモリ割り当てを減らして運用を行うと2日に1度は発生していたエラーがピタリと収まりました。今回の原因はメモリ不足により ssh プロセスを起動する事が出来なくてエラーとなっていて、JVMのメモリ割り当てを減らすことで解消しました。
後から確認できる sarコマンド、java の メモリ状況やGCで状況などを確認できる jstat コマンドの便利さが伝わると幸いです。

◆Java スレッドがデッドロックしてしまった件

話は変わって、ある日インフラ担当からここ数日 CPU 使用率が上がり続けているとの連絡をもらいました。 CPU 使用率が Max 1200% のところを 1000% を超える状態となっていました。

調査方法

以下の順番で確認を行いました。

CPU に負荷をかけているプロセスの確認（top）
↓
CPU に負荷をかけているスレッドの確認（ps -L）
↓
CPU に負荷をかけている java クラスの確認（jstack）
↓
java プログラムの修正

CPU に負荷をかけているプロセスの確認

CPU 使用率が確認できるコマンドは top, ps などありますが、top コマンドで確認したところ、java プロセスが CPU 使用率のほとんどを使用していました。

CPU に負荷をかけているスレッドの確認

スレッド毎の CPU 使用率の確認は、ps -L（ラージエル）で確認しました。

ps -L aux（スレッド毎にステータスを表示）

%CPU、START、LWP 列をご覧ください

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND

xxxxx    22532 25766 93.7  118 45.5 6036532 5599948 ?     Rl   Jan23 4168:31 /usr/java/default/bin/java -Djava.util.logging.config.file=（途中省略）org.apache.catalina.startup.Bootstrap start

xxxxx    22532 23023 92.2  118 45.5 6036532 5599948 ?     Rl   Jan21 6312:47 /usr/java/default/bin/java -Djava.util.logging.config.file=（途中省略） org.apache.catalina.startup.Bootstrap start

・・・（省略）・・・

読み取れる内容

・cpu 使用率が90%を超えているスレッドが多数ある
・START に4日前から起動し続けている java スレッドがある
などがわかりました。
次は java の解析を行いました。

CPU に負荷をかけている java クラスの確認

スレッドが起動し続けているという状況でしたので、 java のスレッドダンプを確認しました。前述の ps -L aux で表示した LWP 列の値を使って java スレッドを特定します。

jstack コマンドでスレッドダンプを取得
↓
ps -L の LWP の値を16進数へ変換
↓
スレッドダンプの nid の値が LWP 16進数の値と同じ箇所を探す

jstack pid（javaプロセスIDを指定）

ps -L LWP の値 25766（16進数へ変換すると 0x64a6）を元に nid の値 0x64a6 が一致する箇所が目的の java スレッドダンプになります。

<TP-Processor136> daemon prio=10 tid=0x00002b21b4669000 nid=0x64a6 runnable [0x00002b21aa771000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap.put(HashMap.java:374)
        at GetEnqueteCountCommand.refreshEnqueteIds(GetEnqueteCountCommand.java:287)
        - locked &amp;lt;0x00002b2070117f60&amp;gt; (a GetEnqueteCountCommand)


<TP-Processor2> daemon prio=10 tid=0x0000000048a71800 nid=0x59ef runnable [0x00002b21a97bc000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap.put(HashMap.java:374)
        at GetEnqueteCountCommand.refreshEnqueteIds(GetEnqueteCountCommand.java:287)
        - locked &lt;0x00002b206d53ef30&gt; (a GetEnqueteCountCommand)

読み取れる内容

・locked <0x00002b2070117f60>
・滞留してしまっているスレッドはすべて同じ箇所 HashMap へ put する箇所で詰まっている
・但し、Thread.State は RUNNABLE （BLOCKEDにはなっていませんでした）
->GetEnqueteCountCommand.refreshEnqueteIds()でHashMapの処理でデッドロックに近い状況となっている
->HashMapの利用箇所をスレッドセーフへ修正する！

対応

今回は HashMap をスレッドセーフな状態に修正することで同じ現象が発生しなくなりました。詰まってしまった java スレッドは ps コマンドと jstack コマンドで特定できました。

まとめ

実際に発生してしまったエラーについてどのように調査して原因を特定したかどなたかのお役に立つことを願ってまとめてみました。 Zabbix のようなインフラ監視ツールを運用しておくのももちろん大事ですが、後から各種サーバリソースを CUI で分析出来る sar コマンドの便利さを改めて実感しました。また ps -L でのスレッド毎の状態表示もスレッドアプリケーションの解析で有用だと思います。似たような現象が発生した際に是非。

それではまた。

次世代システム研究室では、アプリケーション開発や設計を行うアーキテクトを募集しています。アプリケーション開発者の方、次世代システム研究室にご興味を持って頂ける方がいらっしゃいましたら、ぜひ 募集職種一覧 からご応募をお願いします。

皆さんのご応募をお待ちしています。