サービスの起動コストが高い原因、どう特定する？

サービスの起動コストが高いとは？

トラフィックを処理できるようになるまでに多くの時間やCPU、あるいはその両方を必要とするサービスは、起動コストが高いと言えます。このコストは3つの指標で表せます。

a. Ready到達までの時間： Ready到達までの時間とは、コンテナの起動からPodがReadyになるまでの時間です。この時間が長いと、ロールアウトが遅れ、スケールアウトが遅くなり、Probe失敗のリスクが高まります。次のコマンドは、appという名前のコンテナについて2つのタイムスタンプを出力します。

kubectl get pod <pod-name> -o jsonpath='{.status.containerStatuses[?(@.name=="app")].state.running.startedAt}{"\n"}{.status.conditions[?(@.type=="Ready")].lastTransitionTime}{"\n"}'

2つの値の差がReady到達までの時間です。Spring Bootのログ行「Started ... in N seconds」はこれより小さい値を示します。計測がアプリケーションの起動時点から始まるため、JVMとコンテナの起動にかかる時間が含まれないからです。

b. Ready到達までのCPU秒： 1 CPU秒とは、1つのCPUが1秒間動作することです。Ready到達までのCPU秒は、起動時のCPU作業量の合計を表します。コンテナは制限値を超えるCPUを使えないため、CPU秒を制限値で割った値が、Ready到達までの理論上の最短時間になります。cgroup v2では、PodがReadyになったらすぐにusage_usecフィールドを読み取ります。

kubectl exec <pod-name> -c app -- cat /sys/fs/cgroup/cpu.stat

usage_usecフィールドは、コンテナが起動してから使用したCPU時間をマイクロ秒単位で示します。1,000,000で割るとCPU秒になります。同じファイルのnr_throttledフィールドとthrottled_usecフィールドは、カーネルがコンテナをどれだけスロットリングしたかを示します。ファイルの読み取りが遅れると、Ready後の作業も値に含まれてしまいます。

c. Ready後のウォームアップ： Readyになったからといって、高速に動作するとは限りません。PodがReadyになった時点でも、JVMはまだ多くのメソッドを低速なインタープリターで実行しており、JITコンパイラはバックグラウンドでコンパイルを続けています。このウォームアップ中、サービスは定常状態より多くのCPUを使用し、最初のリクエストが遅くなることがあります。Readyになった瞬間にリソースを減らすと、ウォームアップが遅くなる可能性があります。Ready到達までだけでなく、Ready後の数分間もCPU使用量を計測すべきです。

起動プロファイリングのツール

起動コストが高い原因を特定するツールは3つあります。最も手軽なものから始め、より詳細が必要になった場合にのみ次のツールを使うとよいでしょう。

a. ログとSpring Bootのstartupエンドポイント： Spring Bootのログ行「Started ... in N seconds」が最初の目安になります。より詳しく知るには、Spring Boot Actuatorのstartupエンドポイントを使うと、各起動ステップとその所要時間を一覧で確認できます。アプリケーション側にBufferingApplicationStartupが必要です。

SpringApplication application = new SpringApplication(MyApplication.class);
application.setApplicationStartup(new BufferingApplicationStartup(4096));
application.run(args);

4096という数値はバッファの容量で、保持できるステップの最大数です。次にエンドポイントを公開します。Probeが動作し続けるように、リストにはhealthを残してください。

management.endpoints.web.exposure.include=health,startup

/actuator/startupへのGETリクエストはステップのスナップショットを返します。POSTリクエストはステップを返したうえでバッファをクリアします。各ステップには名前、所要時間、Bean名などのタグが付きます。まず最も時間の長いステップを確認しましょう。spring.beans.instantiate、spring.context.config-classes.parse、spring.context.refreshといった名前から、どこに時間がかかっているかがわかります。spring.beans.instantiateでは、タグbeanNameがBean名を示すため、最も遅いBeanを特定できます。なお、ステップ名はSpringのバージョンによって変わる可能性があります。

2つのJVMログオプションでさらにデータを追加できます。-Xlog:gc*オプションはガベージコレクションのイベントを、-Xlog:class+loadオプションは各クラスのロードを記録します。どちらもJAVA_TOOL_OPTIONSで渡せます。

b. Java Flight Recorder（JFR）： JFRはJDKに組み込まれています。ガベージコレクション、JITコンパイル、実行サンプルなど、JVMのイベントを記録します。デフォルト設定のオーバーヘッドはごくわずかで、profile設定ではより多くのイベントを記録します。-XX:StartFlightRecordingオプションを使うとJFRはJVMと同時に起動するため、起動の全体をキャプチャできます。ファイルをPodからコピーした後、JDKのjfrツールまたはJDK Mission Controlで読み取ります。

jfr summary startup.jfr
jfr print --events jdk.GarbageCollection,jdk.Compilation startup.jfr
jfr print --events jdk.ExecutionSample --stack-depth 8 startup.jfr

1つ目のコマンドはイベントタイプとその件数を一覧表示します。2つ目のコマンドはガベージコレクションイベントとJITコンパイルを所要時間とともに出力します。3つ目のコマンドは、スタック深度8フレームで、各スレッドが実行しているコードのサンプルを出力します。jdk.Compilationイベントが記録するのは、設定のしきい値より長くかかったコンパイルのみです。

c. async-profiler： async-profilerはJava向けのサンプリングプロファイラで、フレームグラフを出力します。起動に関しては2つのモードが重要です。cpuモードはCPUを使用しているスレッドのみをサンプリングするため、何がCPUを消費しているかがわかります。wallモードは、実行中・スリープ中・待機中を問わず、すべてのスレッドを一定間隔でサンプリングするため、待機を含め、どこに時間がかかっているかがわかります。async-profilerはエージェントとしてJVMと同時に起動できるため、最初の1秒間からキャプチャできます。

Kubernetesでの起動プロファイルの取得

記録はJVMと同時に開始し、サービスの実際の稼働条件下で実行する必要があります。重要なポイントは2つです。

a. 本番のCPU制限下でプロファイルを取得する： 本番と同じイメージ、同じJVMフラグ、同じCPU・メモリ設定を使用してください。制限値が異なると起動そのものが変わります。スロットリング、JVMが認識するCPU数、JVMが選択するコレクターが変わるからです。本番の制限を適用せずに取得したプロファイルは、本番とは異なる起動の姿を示します。詳しくはJVM起動時のCPUスロットリングをご覧ください。

次のPodテンプレートは、JVMと同時にJFRを開始し、ファイルをボリュームに書き込みます。

spec:
  template:
    spec:
      containers:
        - name: app
          image: registry.example.com/orders-service:1.8.0
          env:
            - name: JAVA_TOOL_OPTIONS
              value: >-
                -XX:StartFlightRecording=filename=/profiles/startup-%p.jfr,settings=profile,duration=120s,dumponexit=true
          resources:
            requests:
              cpu: 300m
              memory: 2Gi
            limits:
              cpu: "2"
              memory: 2Gi
          volumeMounts:
            - name: profiles
              mountPath: /profiles
      volumes:
        - name: profiles
          emptyDir:
            sizeLimit: 500Mi

各設定の役割は次のとおりです。

• filename=/profiles/startup-%p.jfrはファイルをボリュームに書き込みます。%pの部分はプロセスIDに置き換わります。
• settings=profileはデフォルト設定より多くのイベントを記録します。
• duration=120sは120秒後に記録を停止します。起動と数分間のウォームアップをカバーできる時間を選んでください。
• dumponexit=trueは、たとえばProbeがコンテナを強制終了した場合など、JVMが早期に終了してもファイルを書き込みます。
• emptyDirは、ルートファイルシステムが読み取り専用の場合でも書き込み可能なフォルダを提供します。sizeLimitは、巨大なファイルがノードのディスクを埋め尽くすのを防ぎます。
• CPUとメモリの値は例です。本番の値を使用してください。

コンテナ内ではJVMは通常プロセス1なので、%pは1になり、ファイル名はstartup-1.jfrになります。複数回の実行のファイルを1つのボリュームに残したい場合は、ファイル名に%tを追加してください。タイムスタンプが付加されます。JFRとasync-profilerの両方が%tに対応しています。

async-profilerを使うには、libasyncProfiler.soをイメージに含めるか、async-profilerのリリースアーカイブをinitコンテナで展開したボリュームに配置します。その後、環境変数を変更します。

env:
  - name: JAVA_TOOL_OPTIONS
    value: >-
      -agentpath:/profiler/lib/libasyncProfiler.so=start,event=cpu,threads,timeout=120,file=/profiles/startup-cpu-%p.html

エージェントオプションの動作は次のとおりです。startはJVM起動時にプロファイリングを開始し、event=cpuはCPUモードを選択し、threadsはスレッドごとに個別にプロファイルし、timeout=120は120秒後に停止し、file=...htmlはフレームグラフを書き出します。ウォールクロックのプロファイルを取るには、event=cpuをevent=wall,interval=10msに置き換えます。コンテナ環境ではperfイベントがブロックされることがよくあります。プロファイラが起動に失敗する場合は、perfイベント不要のevent=ctimerを使用してください。

1回の実行で使うプロファイラは1つだけにし、各実行は3回繰り返してください。1回だけの結果は判断を誤らせる可能性があります。

b. Podからプロファイルをコピーする： kubectl cpでフォルダを手元のマシンにコピーします。

kubectl cp <namespace>/<pod-name>:/profiles ./profiles -c app

このコマンドには、コンテナイメージ内にtarプログラムが必要です。イメージにtarがない場合、コマンドは失敗します。その場合は、tarを持つ小さな2つ目のコンテナに同じボリュームをマウントし、そのコンテナ名を-cで指定します。KubernetesはemptyDirボリュームをPodとともに削除するため、Podが削除される前にファイルをコピーしてください。HTMLファイルはブラウザで開きます。

起動フレームグラフの読み方

フレームグラフは、すべてのサンプルのスタックトレースを表示します。各ボックスはメソッドを表し、その幅は、そのメソッドを含むサンプルの割合を示します。async-profilerのグラフでは、mainなどの最も外側のフレームが下部に、実際の処理を行うリーフフレームが上部にあります。幅の広いボックスが、時間を消費している箇所です。threadsオプションにより、各スレッドが独自のタワーを持ち、タワーはスレッド名を示すボックスから始まります。Linuxはスレッド名を15文字に切り詰めるため、長い名前はグラフ上で短く見えます。重要なスレッドグループは3つあります。

a. アプリケーションスレッド： mainを実行するスレッドは、アプリケーションの起動コードを実行します。そのルートボックスの名前はmainの場合もDestroyJavaVMの場合もあるため、名前ではなくSpringApplication.runフレームで見つけてください。幅の広いSpringApplication.runタワーや幅の広いrefreshタワーは、フレームワークの起動が時間の大半を占めていることを意味します。defineClassやloadClassを含む幅の広いボックスはクラスローディングを意味します。自分のパッケージ名を含む幅の広いボックスは、キャッシュロードやデータベースマイグレーションなど、自分自身の起動コードを意味します。

b. JITコンパイラスレッド： C1 CompilerThreおよびC2 CompilerThreで始まるルートはJITコンパイラです。完全なスレッド名はC1 CompilerThread0、C2 CompilerThread0などです。これらのタワーが起動スレッドのタワーと同じくらい広い場合、JIT処理が起動時CPUの大きな割合を占めています。どのフレームがインタープリターで実行されているかを見るには、拡張子.collapsedのファイルにプロファイルを書き出し、annオプションを追加します。このファイルでは、インタープリター実行のフレームは_[0]、C1フレームは_[1]、その他のコンパイル済みフレームは_[j]、インライン化されたフレームは_[i]で終わります。起動スレッドに_[0]フレームが多い場合、コードがまだコンパイルされていないことを意味します。HTMLグラフにはこれらの接尾辞は付かず、フレームタイプは色で表示されます。

c. GCスレッド： G1では、GC Thread#0、G1 Conc#0、G1 Refine#0などのルートがガベージコレクションの作業を行います。SerialコレクターではVM Threadがこれを行います。CPU制限が1 CPU以下、またはメモリ制限が1792 MB未満の場合、JVMはSerialコレクターを選択するため、そのようなPodから取得したグラフにはGCワーカースレッドが存在しません。最初の数秒間に幅の広いガベージコレクションのタワーがある場合、起動時のアロケーションに対してヒープが小さすぎるか、ヒープが何度も拡張されていることを意味します。この点は、JFRのjdk.GarbageCollectionイベント（イベント名がコレクターを示します。たとえばDefNewとSerialOldはSerialコレクターのものです）、またはログオプション-Xlog:gc*で確認してください。

同じ起動のcpuグラフとwallグラフを比較しましょう。wallグラフにはWebサーバースレッドなど多くのアイドルスレッドも表示されます。それらは無視し、起動スレッドに注目してください。