はじめに
本記事は Microsoft Azure Tech Advent Calendar 2020 の投稿です。
Web サイトを運用する上でトラブルシューティングは切っても切り離せないものだと思います。そのため、トラブルシューティングが容易なサイトを作ることも、運用を踏まえますと大切になってきます。Web Apps では「高度なツール」ブレードから kudu を起動することによって、Web コンソールからコマンドを入力したり、プロセスエクスプローラを開いたりすることができます。これらを活用することによってトラブルシューティングが容易なサイト運用ができると思っています。
本記事では Java Web Apps を運用するうえで便利なトラブルシューティングの準備や方法を紹介したいと思います。なお、Java Web Apps の Windows 環境をターゲットとさせていただきますが、ここで紹介した方法は Linux 環境でも応用ができますので、ご利用いただけると嬉しいです。
サンプルアプリのデプロイ
せっかくなので、以下の公式ドキュメントのクイックスタートにある Java アプリの作成手順を使ってみましょう。
クイック スタート:Azure App Service で Java アプリを作成する
https://docs.microsoft.com/ja-jp/azure/app-service/quickstart-java?tabs=javase&pivots=platform-windows
以下のコマンドでリポジトリをクローンし、azure-webapp-maven-pluginのconfigで、Windows, Java11, Java SEを選択します。
git clone https://github.com/spring-guides/gs-spring-boot
cd gs-spring-boot/complete
.\mvnw com.microsoft.azure:azure-webapp-maven-plugin:1.12.0:config
以下のコマンドでビルド & Web Apps へのデプロイを実施します。
az login
.\mvnw package azure-webapp:deploy
Web サイトにアクセスします。
たったこれだけの手間でサイトを用意することができました。
トラブルが起きることを踏まえた設定
スタックトレースがアプリケーションのログに出ている場合は、エラー原因を絞り込めるため解析が比較的容易です。
その一方で、性能が一時的に低下したり、Out of Memory (以下、OoM) が発生したりした際に、事象が発生した時点の情報がなければ、原因を特定することは極めて難しいです。
他のプログラミング言語でもあるとは思いますが、Java ではメモリにプロファイリングデータを蓄積し手動や終了時にファイル出力する機能 (JFR: Java Flight Recorder) や、Out of Memory 時にヒープダンプをする機能があり、事象が発生した時点の情報を取得することができます。
なお、メモリに蓄積されたプロファイリングデータは、指定されたメモリサイズの上限を超えると失われたるためご留意ください。
Web Apps のアプリケーション設定におきまして JAVA_OPTS から Java の起動引数を追加することができます。
JFRを有効化し、OoM 時にヒープダンプを実施する JAVA_OPTS の設定値は以下になります。
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=C:\home\LogFiles\catalina.hprof -XX:StartFlightRecording=dumponexit=true
「高度なツール」ブレードから kudu を起動し、以下のスクリーンショットのように Debug Consoleで jcmd を発行し、実際に上記起動引数が設定されているか見てみましょう。
なお、jcmd を使うと java プロセスの様々な情報を取得できるので、トラブルシューティングにご活用いただければと思います。
また、java プロセスの PID はProcess exploreから確認可能です。
無事設定も終わりましたので、無理やりトラブルを起こして解析してみましょう。
Out of Memory エラーの解析
ヒープダンプを取得
サンプルアプリに以下のクラスを追加し、再度デプロイしましょう。
/oomにアクセスをし続けると、そのうち無事？ OoM が発生します。
package com.example.springboot;
import java.util.List;
import java.util.ArrayList;
import java.util.Arrays;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.bind.annotation.RequestMapping;
@RestController
public class OoMController {
private static final List<String> POOL = new ArrayList<>();
@RequestMapping("/oom")
public String feed() {
char[] tmp = new char[200*1024*1024];
Arrays.fill(tmp, 'a');
POOL.add(new String(tmp));
return "Feed Me!";
}
}
前述の設定のおかげで、OoM 時のヒープダンプが以下のようにC:\home\LogFiles\catalina.hprofに存在します。
catalina.hprof のダウンロードボタンを押してヒープダンプファイルを取得しましょう。
ヒープダンプの解析
Zulu Mission Control や VisualVM といったツールを使ってヒープダンプを解析してみましょう。私が VisualVM が好きなので、VisualVM で解析したいと思います。
catalina.hprofを開くとDominators by Retained Size で明らかに大量にヒープを消費しているクラスがあると思います。右クリックで Open in New Tab で開いてみましょう。
以下の画像のように大量にヒープを使っている ArrayList インスタンスのフィールドやそれを参照しているクラス (OoMController) を確認できました。
これで問題が特定できたので、あとはメモリを使わないようにソースを修正する流れになります。
このように OoM が発生してしまった時でも、ヒープダンプがあればスムーズにヒープに関するトラブルシューティングが可能です。
リクエストの応答が遅い
JFR データの取得
性能が出ないときには JFR を使うとボトルネックとなっている処理が分かります。
サンプルアプリに以下のクラスを追加し、OoM の時のように無理やり問題を発生させましょう。
/sleepにアクセスすると嫌になるくらい遅く応答がかかります。
package com.example.springboot;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.bind.annotation.RequestMapping;
@RestController
public class SleepController {
@RequestMapping("/sleep")
public String sleep() {
try {
Thread.currentThread().sleep(10 * 1000);
} catch (InterruptedException ex) {
// Nothing to do.
}
return "I'm not lazy..";
}
}
kudu から以下のコマンドでメモリにある JFR データをダンプし、ヒープダンプの時のようにJFR ファイルをダウンロードしましょう。
JFR データの解析
VisualVMでプロファイリングデータを解析しましょう。
JFRファイルを開いたら、Samplerタブを表示し、CPU ボタンを押下してください。
スレッドアイコンで http-nio--exec- のように Tomcat のスレッドをフィルタするとポイントが絞れます。
いくつかプラスボタンを押して、コールグラフを表示してみましょう。波動拳みたいに深い呼び出し階層ですが、Total Timeが多い sleep まで探し当てることができました。
このように、JFRデータを使うとボトルネックとなっている処理を見つけ出すことができます。
さいごに
アプリケーションが遅かったり、突然ダウンしたりした際にフライトレコーダーの情報やヒープダンプは重宝します。
単純なサンプルの紹介となってしまいましたが、今回紹介したトラブルシューティングの準備や方法が深刻な状況での助けになれば私も嬉しく思います。