Tomcatのメモリ利用状況を調査・分析するための参考情報

概要

現代においても、まだまだTomcatを利用したWebアプリケーションが多数存在しています。
（別に批判ではなく、多くのサービスで利用され、バージョンアップも継続され、情報も多い製品なので優秀なアプリケーションサーバーだと思っています。）

開発会社が環境構築し、Javaで構築したシステムをそのサーバーに配置してしばらく運用していると、どうしても性能面などで問題が出てくることがあります。

例えば、ログを出力しているのはいいが、ローテーションやファイルの破棄サイクルを考慮していないため、ストレージを圧迫していきなりストンとサーバーが落ちたり、徐々にヒープメモリの利用状況が右肩上がりとなり、OutOfMemoryErrorなどでTomcatが死んだり、死なないまでもシステムのレスポンスが悪化し、トラブルが発生したりと、いろんなことが発生します。

ストレージを圧迫していることが判明した場合は、不要だと判断したファイルを削除して暫定対応し、恒久対応はまた今度となることがよくあります。

なんかシステムのレスポンスが悪く、軽く調べたところメモリが原因と思われるとき、すぐに解消しなければ業務影響が大きいとなると、Tomcatを再起動して暫定対応し、恒久対応するための原因調査は、開発会社の魔法の言葉でまた再現するようでしたら、その際に調べますみたいなことを言われ、永遠に恒久対応は訪れることがありません。（個人的な実体験であり、世の中全てに当てはまるわけではありません。）

長々と愚痴のようなことを記載しましたが、メモリの利用状況分析は、実際に問題が起きてみないとわからないこともあるし、本番環境と開発会社が持っている開発環境では状況も異なるため、再現も難しいというのはわかります。
ユーザー企業から保守契約も渋られ絞られ、時間のかかる調査作業に掛けられる状況でもないというのが現状でしょう。

であれば、ユーザー企業側が自分たちで調査すればいいじゃない。というふうに思い立ち、とにかく調査や分析するための方法について自分なりにまとめてみようと思ってこの記事を残します。

Tomcatが使っているメモリの状況を調査する方法

Tomcatのpid確認方法

この記事でいろんなコマンドを利用し、調査することがありますが、Tomcatのpidを事前に知る必要があったりします。
pidの確認方法はいくつかあり、以下のコマンドで確認できます。

Javaを利用するプロセスがTomcatのみの場合はpidofというコマンドで確認できます。

# pidof java
3344

Tomcatのみかどうかわからない場合は、jcmdを利用してリスト表示し、TomcatのPIDを判断した方がいいでしょう。

# jcmd -l
3344 org.apache.catalina.startup.Bootstrap start  ←  これがTomcatのPID
4894 jdk.jcmd/sun.tools.jcmd.JCmd -l

CentOSのtopコマンドを使ってメモリの利用状況を確認する

TomcatのPIDを指定して、topコマンドでメモリなどの利用状況を確認します。

# top -p 3344
top - 11:22:30 up 23 min,  1 user,  load average: 0.00, 0.00, 0.00
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3939.0 total,   3295.9 free,    273.2 used,    369.9 buff/cache
MiB Swap:   2048.0 total,   2048.0 free,      0.0 used.   3445.0 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                           
 3344 root      20   0 4204172 190864  28536 S   0.0   4.7   0:03.04 java        

• VIRT
  • Virtual Image。確保された仮想メモリ全て。スワップしたメモリ使用量を含む。（単位：kb）
• RES
  • Resident size。 スワップしていない、使用した物理メモリのサイズ。（単位：kb）
• SHR
  • Shared Mem size。 他のプロセスと共有される可能性のあるメモリのサイズ。（単位：kb）

jcmdを使ってJVMの起動パラメータ（オプション）を確認する

Tomcatの起動オプション（JVMの起動オプション）で、-Xmsや-Xmxなどを指定し、Tomcatが利用するメモリサイズなどを設定することがあると思います。

その設定方法としては

• tomcatユーザーの~/bash_profileにCATALINA_OPTSの環境変数をexportするように設定
• tomcat.serviceの起動スクリプト内に指定する方法
• {tomcat-root}/bin/setenv.shに指定する方法

などが存在し、Tomcatの環境構築手順や資料、Ansibleなどで構築したスクリプトなどが残っていないと、
設定としては何を設定して起動するようにしているのか、確認するのが面倒な時があります。
（特に開発会社に環境構築や開発、リリースをお願いし、ユーザー企業としてそのサーバーの面倒だけ少しみている場合などは特に困ります。）

そんな時に、jcmdを使ってとりあえず現在動いているTomcatがどのようなJVMオプションで起動しているのか確認することが可能です。

確認するために、事前にTomcatのPIDが必要です。

# jcmd -l
899 org.apache.catalina.startup.Bootstrap start
4894 jdk.jcmd/sun.tools.jcmd.JCmd -l

# jcmd 899 VM.flags
899:
-XX:CICompilerCount=2 -XX:InitialHeapSize=62914560 -XX:MaxHeapSize=991952896 -XX:MaxNewSize=330301440 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=20971520 -XX:OldSize=41943040 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseParallelGC

-Xmxに該当するのが-XX:MaxHeapSizeというように、パラメータの設定がどのようになっているかは上記のように確認することが可能です。

Tomcatのヒープダンプを取得する

ヒープダンプとは、Javaのメモリー利用状況のスナップショットログみたいなものです。
ヒープダンプを取得して分析することで、どんな感じでJavaがメモリを使っているのかがなんとなくわかります。
ここでは、Java7から使えるjcmdを利用してヒープダンプを取得します。

# jcmd -l
899 org.apache.catalina.startup.Bootstrap start
4894 jdk.jcmd/sun.tools.jcmd.JCmd -l

# jcmd 899 GC.heap_dump /var/log/heapdump/heapdmp.hprof
899:
Heap dump file created

# ls
heapdmp.hprof

Java VisualVMツールでヒープダンプを分析する

jcmdで取得したヒープダンプをJava VisualVMというツールで確認していく。
分析するには、ローカルPC環境（GUIがある環境）で行いますが、事前にJREがインストールされている必要があります。

私の環境はJavaの1.8がセットアップされ、パスが通っている状況でした。

$ java -version
java version "1.8.0_241"
Java(TM) SE Runtime Environment (build 1.8.0_241-b07)
Java HotSpot(TM) 64-Bit Server VM (build 25.241-b07, mixed mode)

この環境で、以下コマンドを実行すると、Java VisualVMツールが起動します。

$ jvisualvm

ファイルを開くから取得したヒープダンプのファイルを指定して開く。

ヒープダンプから余計なオブジェクトが作られていないかなどを確認することができるようです。
ただ、私の期待としては、グラフでメモリの利用状況やGCによりメモリが解放される姿が確認できるといいなと思っていました。
なので、このヒープダンプだけでメモリの利用状況を把握し、原因のあたりをつけて、恒久対応のためのきっかけにする。というのは難しいかなと思いました。

Java Monitoring & Management Consoleを利用した分析

JConsoleとも呼ばれるツールを利用して、グラフィカルにメモリの利用状況などを分析することが可能なようです。
https://docs.oracle.com/javase/jp/8/docs/technotes/guides/management/jconsole.html

ここでは、ローカルPCからCentOSサーバー上に構築されたTomcatに対し、JMXエージェントを経由してJConsoleでJVMのモニタリングを行います。

TomcatのJVM起動オプションにJMX関連の設定を追加

TomcatのJVM起動オプションの指定方法としてはいろいろな方法があるとは思いますが、ここではsetenv.shに指定する方法で設定を追加します。

{tomcat-root}/bin/setenv.sh

# !/bin/sh

JAVA_OPTS="-server -Xms512M -Xmx2G -Dspring.profiles.active=production　-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=8888 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.rmi.server.hostname=192.168.33.10"

Dcom.sun.management.jmxremote.portでJMXエージェントが利用するポートを指定しています。
仮に、Tomcatが8080ポートを利用しているので、それ以外のポートを指定しました。

また、ローカルPCからTomcatのサーバーにリモートでアクセスし、JVMモニタリングを行うため、Djava.rmi.server.hostnameのパラメータを指定しています。
このパラメータを指定しない場合、JConsoleで192.168.33.10:8888に接続しようとすると、「セキュアな接続が失敗しました。非セキュアで再試行しますか。」などのメッセージが表示され、どんだけ再試行しても接続することができませんでした。
なので、リモートアクセスする必要がある場合には注意が必要です。

上記設定をしたうえで、Tomcatを再起動した後、指定したポート8888がちゃんとリッスンされているか確認します。

# systemctl restart tomcat

# ss -antup | grep 8888
tcp   LISTEN  0       50                         *:8888                *:*       users:(("java",pid=4211,fd=17))  

# ps -ef | grep jmx

Java Monitoring & Management Console (JConsole)を起動してJVMモニタリングを行う

以下のコマンドでjconsoleツールを起動し、メモリの使用状況を確認します。
以下のコマンドはローカルPCから実行しています。
jconsoleコマンドも、JREが事前にインストールされ、パスが通っていないと実行できませんのでご注意ください。

jconsole 192.168.33.10:8888

概要タブではメモリ、スレッド、クラス、CPU使用率などが時間経過とともにどのように利用されているのかがグラフィカルに表示されています。
この概要タブの情報だけで十分分析できそうですが、そのほかのタブの内容も、一応どんな内容なのか確認します。

GCViewerを利用した解析

GCViewer
https://github.com/chewiebug/GCViewer/wiki/Changelog

JConsoleの解析では、GCの発生回数を確認することはできても、GCがどのタイミングで発生しているのかまではわかりませんでした。
なので、GCログを取得して、GCViewerを利用し、メモリの利用状況と合わせて、GCの発生頻度や、GCによってどの程度のメモリが解放されているのかなどを確認してみます。

GCログの取得

GCログを取得するために、TomcatのJVMオプションを以下のように設定します。

{tomcat-root}/bin/setenv.sh

JAVA_OPTS="-server -Xms512M -Xmx2G -Dspring.profiles.active=production -verbose:gc -Xlog:gc*=info:file=/var/log/gclog/gc.log:time,uptime,level,tags:filecount=1,filesize=10m"

上記設定が完了後、tomcatサービスを再起動し、しばらく放置します。（Tomcat上のWebアプリにしばらく動作してもらいます。）

取得したログをgcviewerで表示してみると以下のような感じ。

GCViewerのグラフの凡例解説

色々表示されていてどの色がどんな役割なのかいまいちわかりませんね。
メニューのViewから各色がどのようなものなのか、それを表示／非表示できるようになっています。

以下にそれぞれの意味合いを簡単に説明します。

• Full GC Lines:（黒）
  • Full GCを表すライン
• Inc GC Lines:（シアン）
  • Incremental GCを表すライン
• GC Times Line:（緑）
  • GCにかかった時間を表すライン
• GC Times Rectangles:
  • GCにかかった時間などを矩形で表現。色に応じてGCなどの内訳を表す。
  • GCにかかった時間（GC Times Line）の内訳をより詳細に確認したい場合に利用するのだと思われるが、Rectanglesの表現によってどう解釈すべきなのかがよくわからない。。
• Total Heap:（赤）
  • ヒープの合計サイズを表示。
  • -Xmsと-Xmxの設定に応じて、どのようにヒープサイズが推移しているか確認したい場合などは、このTotal Heapのみを表示して確認することもできる。
• Tenured Generation:（ピンク）
  • ヒープ領域の内訳として Young Generation / Tenured Generationがある。
  • Young領域とOld領域とも表現され、Old領域に該当するメモリサイズを表現する。
  • Total Heapを利用せずに、Young Generation / Tenured Generationを利用してメモリの状況を分析するときに利用する。
  • JVMパラメータの-PrintGCDetailsを指定しないと使えないが、Java9以降では-Xlog:gc*のパラメータ指定が必要
• Young Generation:（オレンジ）
  • ヒープ領域の内訳として Young Generation / Tenured Generationがある。
  • Young領域とOld領域とも表現され、Young領域に該当するメモリサイズを表現する。
  • Total Heapを利用せずに、Young Generation / Tenured Generationを利用してメモリの状況を分析するときに利用する。
  • JVMパラメータの-PrintGCDetailsを指定しないと使えないが、Java9以降では-Xlog:gc*のパラメータ指定が必要
• Used Heap:（青）
  • 青色の線がヒープの利用サイズを表す。
• Used Tenured Size:（暗いピンク）
  • Old領域の利用サイズを表す。（めちゃめちゃ見づらい）
• Used Young Size:（灰色）
  • Young領域の利用サイズを表す。（めちゃめちゃ見づらい）
• Initial mark level:
  • initial-markイベントでのヒープの使用状況を示す
• Concurrent collections
  • Cyan vertical line for every begin (concurrent-mark-start)
    and pink vertical line for every end (CMS-concurrent-reset /
    G1: concurrent-cleanup-end) of a concurrent collection cycle

Total HeapとFullGCのみを表示したサンプル

-Xmxの指定サイズに到達した状態が続くと、Full GCが頻繁に発生していることが分かる。
また、Full GC後にヒープサイズが下がると、Full GCの頻度は減少する傾向にあるようです。

ただ、ずっと上限サイズに張り付いている状態でもFull GCが頻発せずに上限サイズのままの状態が続く時間帯もあった。

ヒープの内訳（Young領域とOld領域）とFullGCを表示したサンプル

Total Heapではなく、その内訳としてYoung領域（Young Generation:オレンジ）とOld領域（Tenured Generation:ピンク）を表示し、Full GCと組み合わせてメモリの利用状況を分析する。

GCログを取得するためのJVMパラメータがJava9以降で変化していてトラブった話し

Google検索してGCログを取得するJVMオプションを調べたところ、以下のようなオプションだったので試してみました。

{tomcat-root}/bin/setenv.sh

JAVA_OPTS="-server -Xms512M -Xmx2G -Dspring.profiles.active=production -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/log/gclog/gc.log"

上記設定が完了後、tomcatサービスを再起動すると、Tomcatで構築したWebアプリが動かなくなっていました。
なぜ動かなくなったのか調べていると、以下のようなエラーが出ているのを見つけました。

{tomcat-root}/logs/catalina.out

Unrecognized VM option 'PrintGCDateStamps'
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAM

どうやら一部のJVMパラメータはJava9以降で使えなくなった（使うとJVMが起動できなくなった）ようです。
そのため、利用できなくなったパラメータを別のパラメータに置き換える必要があります。

こちらのサイトのConvert GC Logging Flags to Xlogの部分などに参考となる置き換えパラメータの情報などが載っています。
ただ、全てのパラメータが１対１で置き換えられるわけではないので、ちょっとややこしい感じです。

具体的なメモリ分析と考察の例

ヒープ領域のメモリ使用状況がずっと天井に張り付いている状況

以下のグラフをみると、しばらくメモリの使用状況が1.4Gbぐらいの位置で下がっていません。

メモリ使用状況が急激に上昇した20:41ごろのスレッド状況をみると、大体同じような時間でスレッド数のピークに達しているのがわかります。
ただ、その後数分でスレッドの実行数は下限に到達しているため、一時的な同時多発アクセスが発生したのだろうということが推測されます。

スレッド数が下がったあとも、全くヒープメモリの利用状況が改善していないということは、GCが発生しても破棄されずに居座っているオブジェクトが存在しているかもしれない状況です。

この時のサーバーのメモリなど使用状況をtopコマンドで確認すると以下のような感じ。

# top -p 923

top - 11:53:47 up  1:01,  1 user,  load average: 0.00, 0.03, 0.05
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
top - 11:54:02 up  1:01,  1 user,  load average: 0.00, 0.03, 0.05
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.0 sy,  0.0 ni, 99.3 id,  0.0 wa,  0.3 hi,  0.3 si,  0.0 st
MiB Mem :   3939.0 total,   1342.6 free,   1657.3 used,    939.1 buff/cache
MiB Swap:   2048.0 total,   2048.0 free,      0.0 used.   2060.3 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                     
  923 root      20   0 4278196   1.5g  31744 S   0.0  39.7   1:09.33 java  

• VIRT Virtual Image。確保された仮想メモリ全て。スワップしたメモリ使用量を含む。（単位：kb）
  • 4GBぐらいなので、-Xmxで2GBを指定して実行していたTomcatに対し、スワップした処理も含めて4GBまでメモリを使わなければいけない処理が発生してしまったことが分かる。
• RES スワップしていない、使用した物理メモリのサイズ。
  • 1.5GB 実際にスワップせずに物理メモリを利用した。

一時的な処理集中だけであれば、-Xmxのパラメータを見直す必要はないが、頻繁に発生するのであれば、メモリの最大を上げる必要があるかもしれません。

21:00ちょい前にメモリ使用状況が一気に改善したグラフがこちら。

この状態になった場合の topコマンドの結果

# top -p 923

top - 12:04:03 up  1:11,  1 user,  load average: 0.09, 0.04, 0.01
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.0 us,  0.0 sy,  0.0 ni,100.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3939.0 total,   1340.3 free,   1659.6 used,    939.1 buff/cache
MiB Swap:   2048.0 total,   2048.0 free,      0.0 used.   2058.0 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                     
  923 root      20   0 4278196   1.5g  31744 S   0.3  39.8   1:12.06 java    

特にVIRT，RES，SHRなどの値は変化無し。
このことから、topコマンドで確認できるのは、一時的にでも跳ね上がったメモリの最大値がスナップショット的に見れるだけなのではないかということがわかります。