[CAIレシピ] 大量のメモリ処理によるエラー発生時の動作を理解する - OOM(OutOfMemory)

はじめに

この記事ではSecure AgentにデプロイしたCAIプロセスにて大量のメモリ処理を要求してJavaのOOM(OutOfMemory)エラーを発生させた場合の動作についてにまとめてみました。

意図的に負荷をかける実験的な動作確認は 必ず Secure AgentにデプロイしたCAIプロセスを利用します。

この記事は次の記事の内容を理解していることを前提としています。

• はじめてCAIを使う際に
• プロセスの作成と実行(匿名認証と基本認証)
• 割り当てステップと、各種変数フィールドの利用

JavaのOOMとは？

サンプルコードによる理解

Javaのプロセスには、プロセスが利用できる最大のヒープメモリ(以降ではメモリと記載します)が設定されております。Javaのプロセスは、GC(ガベージコレクション)を実行して利用可能なメモリを確保できるようにメモリ領域の整理整頓をしますが、GCを繰り返してもメモリを確保できない状況が発生するとOOMエラーが発生します。

Secure AgentにてCAIサービスを実行しているprocess engineもJavaのプロセスとして実行されているため、メモリ不足により発生するOOMについて理解を深めておくと、問題が発生した際のトラブルシューティングが円滑に行えます。

ここでは、実際にOOMが発生するJavaコードを確認してみましょう。
次のJavaコードでは、ループ処理1回毎に 0123456789 という文字を2万回結合した文字列を生成してメモリから解放されないようにする処理を実行しています。

JavaOom.java (OOM発生させる君)

import java.util.ArrayList;
public class JavaOom{
   public static void main(String[] args){
      try{
         ArrayList<LargeInst> lst = new ArrayList<LargeInst>();
         for(int i = 1; i < 1000000000; i++){
            lst.add(new LargeInst());
            long total = Runtime.getRuntime().totalMemory()/1024/1024; //Totalメモリ取得
            long free = Runtime.getRuntime().freeMemory()/1024/1024;   //Freeメモリ取得
            System.out.printf("%8d Total=%dMB, Free=%dMB\n", i, total, free);
         }
      }catch(Exception e){
         e.printStackTrace();
      }
   }
}

class LargeInst{
   public String _data = null;
   public LargeInst(){
      StringBuilder sb = new StringBuilder();
      for(int i = 0; i < 20000; i++) sb.append("0123456789");
      _data = sb.toString();
   }
}

次のコマンドで、Secure AgentインストールディレクトリのJDKを利用して、コンパイル&実行するとOOMが発生する動作を確認できます。

OOM動作の確認

$ export PATH=$PATH:~/infaagent/jdk/bin
$ javac JavaOom.java
$ java -Xmx32m -verbose:gc JavaOom

       1 Total=31MB, Free=29MB
       2 Total=31MB, Free=27MB
       3 Total=31MB, Free=25MB
       4 Total=31MB, Free=24MB
       5 Total=31MB, Free=22MB
[GC (Allocation Failure)  8624K->2389K(31744K), 0.0186051 secs]
       6 Total=31MB, Free=27MB
...省略
      55 Total=28MB, Free=6MB
      56 Total=28MB, Free=4MB
[Full GC (Ergonomics)  24773K->22452K(29184K), 0.0098257 secs]
      57 Total=28MB, Free=5MB
      58 Total=28MB, Free=4MB
[Full GC (Ergonomics)  25267K->23089K(29184K), 0.0091649 secs]
      59 Total=28MB, Free=4MB
[Full GC (Ergonomics)  24951K->23624K(29184K), 0.0088815 secs]
      60 Total=28MB, Free=4MB
[Full GC (Ergonomics)  25184K->24015K(29184K), 0.0087370 secs]
      61 Total=28MB, Free=4MB
[Full GC (Ergonomics)  25294K->24262K(29184K), 0.0081742 secs]
[Full GC (Ergonomics)  25167K->24694K(29184K), 0.0183157 secs]
      62 Total=28MB, Free=3MB
[Full GC (Ergonomics)  25246K->24580K(29184K), 0.0094534 secs]
[Full GC (Ergonomics)  25039K->24796K(29184K), 0.0061121 secs]
[Full GC (Allocation Failure)  24796K->24785K(29184K), 0.0163869 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
        at java.util.Arrays.copyOf(Arrays.java:3332)
        at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
        at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
        at java.lang.StringBuilder.append(StringBuilder.java:141)
        at LargeInst.<init>(JavaOom.java:22)
        at JavaOom.main(JavaOom.java:7)

このコードではループ処理毎に、ループ処理用のカウンタ変数値(一番左の数字)、合計メモリ値(Total)、メモリの空き容量(Free)、を出力しています。また、オプション -verbose:gc によりGCイベントを出力しています。

Javaコード実行時には、最大メモリとして32MBが利用されるように -Xmx32m を指定しているためTotalとしては32MBに近似の28MBがループ処理毎に表示されています。

最初の5回のループ処理では徐々にFreeが少なくなり、利用可能なメモリが減っており、その後、GCイベントとして GC (Allocation Failure) が発生して利用可能なメモリが一時的に増えている動作が見れます。

ループ処理55回目以降は、GCSイベントとして Full GC が頻発している動作が見れ、Full GC を繰り返してもメモリをJavaコードを実行可能と判断できるメモリを確保できない状況となり最終的にExceptionとして OOM(OutOfMemoryError) が発生しています。

Full GC には注意が必要です。Full GC 発生時には、Javaプロセス内で生成されている全てのスレッドの処理が一時的に停止して動作が不安定になる・処理が遅延する可能性があるためです。例えば、Secure AgentにCAIプロセスをデプロイして実行している場合、CAIプロセスAと、CAIプロセスBが同時に実行されている状況下にて、プロセスAがメモリ負荷を上げて Full GC が発生するような状況があると、プロセスBの処理時にも遅延が発生し得ます。

JavaのOOM != OSレベルのメモリ不足

JavaのOOMについて理解を深めるうえで JavaのOOMは、OSレベルのメモリ不足とは異なるもの という点を覚えておくと良いと思います。既にサンプルコードも踏まえて動作を見ていたように OOMはJavaのヒープメモリ不足 を意味します。そのため、OOMが発生した際に、例えば仮想マシンにメモリを追加したり、SWAP領域拡張により仮想メモリのサイズをサイズを大きくしたりしても対処にはなりません。

なお、Javaのプログラム実行中にOSレベルのメモリ不足が発生すると次のようなエラー(Cannot allocate memory)が発生したり、Linux環境を利用している場合にはOOMKillerによりJavaのプロセスが強制停止されたりします。

OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x000000074fb39000, 1884057600, 0) failed; error='Cannot allocate memory' (errno=12)
#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 1884057600 bytes for committing reserved memory.
# An error report file with more information is saved as:
# /home/infa1/hs_err_pid1680.log

CAIプロセスに大量のメモリ処理を要求する

CAIプロセスの作成と実行

XQueryにて、Secure Agent実行環境に保存されている1GBのテキストファイルを読み込ませてメモリ使用量の負荷を高めて動作確認をしてみます。
なお、1GBのテキストファイルはLinuxコマンド yes "12345678901234567890" | head -n 50000000 > large.txt にて作成しています。

次の手順にて作成した1GBのテキストファイルを読み込むCAIプロセスを作成します。

1. CAIプロセスを次の設定で作成します。

   • 名前を recipe-psa-unexpectedOOM とする
   • 匿名アクセス を許可する
   • Secure Agent にデプロイする

2. タイプ=テキストの一時フィールド tmpText に 計算式 として fn:unparsed-text('file:///opt/infaUSW5/ff/large.txt') を指定します。ファイルlarge.txtのパスは利用環境に合わせて指定します。
   

curlコマンドによりCAIプロセスを実行すると以下のように Java heap space というメッセージが得られる動作を確認できます。

curlコマンドと実行結果

// curl コマンド
curl -k https://localhost:7443/process-engine/public/rt/recipe-psa-unexpectedOOM

// 実行結果
{"error":{"code":500,"detail":{"reason":"Java heap space"},"message":"Java heap space"}}

アプリケーション統合コンソールを確認すると、プロセスID=20103のステータスがフォールトとなっている動作を確認できます。

大量メモリ処理時のログ

前述した手順で作成しているCAIプロセス recipe-psa-unexpectedOOM 実行時に、process engineにてどのようなログが出力されているかを確認してみましょう。確認したいログはディレクトリ SAインストール先/apps/process-engine/logs に出力されている3つのファイルです。

catalina.2025-12-03.log (カタリナログ)

04-Dec-2025 03:04:22.023 IST ERROR [DefaultWorkManager-WorkerThread-9] [AeException] [{mdc.engine.id=2, mdc.loc.path=/process/flow/assign[@name='Assignment_to_tmpText'], mdc.mutex=AeMutex[104], mdc.plan.id=1027, mdc.plan.ver=1.00, mdc.process.id=20103, mdc.process.initiator=anonymous, mdc.process.name={urn:screenflow:process:recipe-psa-unexpectedOOM}recipe-psa-unexpectedOOM, mdc.tenant.id=$public}] - SaxonApiUncheckedException, Expression: let $newValue := (fn:unparsed-text('file:///opt/infaUSW5/ff/large.txt')) return iomap:createNewProcessData($temp, 'tmpText', $newValue)xquery 3.1 expression evaluation failuretenantId: $public message:Java heap space ProcessId:20103
java.lang.OutOfMemoryError: Java heap space
        at java.util.Arrays.copyOf(Arrays.java:3332)
        at net.sf.saxon.tree.util.FastStringBuffer.ensureCapacity(FastStringBuffer.java:581)
        at net.sf.saxon.tree.util.FastStringBuffer.cat(FastStringBuffer.java:138)
        at net.sf.saxon.value.StringValue$Builder.cat(StringValue.java:558)

カタリナログはprocess engineにて何らかの問題が発生した一番最初に見たいログです。今回はXQuery fn:unparsed-text('file:///opt/infaUSW5/ff/large.txt') を実行している際にOOMが発生している動作を読み取れます。

catalina.out (カタリナアウトログ)

java.lang.OutOfMemoryError: Java heap space
Dumping heap to /opt/infaUSW5/infaagent/apps/process-engine/15124581.24.1/../logs/java_pid640482.hprof ...
Heap dump file created [815141314 bytes in 3.966 secs]

カタリナアウトログからは、OOMエラーの発生により、Javaのヒープダンプ(hprof)が生成されている動作を読み取れます。なおヒープダンプにはヒープメモリ内の情報が格納されております。トラブルシューティング時にヒープダンプを参照する可能性はありますが、基本的なトラブルシューティングはCAIプロセスの実装を見ることが殆どでヒープダンプを参照することは稀です。ヒープダンプはファイルサイズが大きい状況が想定されるため、必要に応じて削除・圧縮するなどして対処すると良いでしょう。

gc.log.0.current (GCログ)

2025-12-04T02:50:20.742+0530: 1076572.228: [GC (Allocation Failure) [PSYoungGen: 340618K->15375K(347136K)] 637094K->312308K(827392K), 0.0337797 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
2025-12-04T03:04:14.828+0530: 1077406.314: [GC (Allocation Failure) [PSYoungGen: 292087K->19794K(347648K)] 589020K->448246K(827904K), 0.0682044 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
2025-12-04T03:04:14.896+0530: 1077406.382: [Full GC (Ergonomics) [PSYoungGen: 19794K->0K(347648K)] [ParOldGen: 428452K->258844K(614400K)] 448246K->258844K(962048K), [Metaspace: 169153K->168705K(1202176K)], 0.4684625 secs] [Times: user=1.59 sys=0.00, real=0.47 secs]
2025-12-04T03:04:16.812+0530: 1077408.298: [Full GC (Ergonomics) [PSYoungGen: 139020K->0K(347648K)] [ParOldGen: 1045276K->700126K(1048576K)] 1184297K->700126K(1396224K), [Metaspace: 168705K->168705K(1202176K)], 0.3897361 secs] [Times: user=1.51 sys=0.00, real=0.39 secs]
2025-12-04T03:04:17.202+0530: 1077408.688: [GC (Allocation Failure) [PSYoungGen: 0K->0K(347136K)] 700126K->700126K(1395712K), 0.0093158 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2025-12-04T03:04:17.212+0530: 1077408.698: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(347136K)] [ParOldGen: 700126K->692757K(1048576K)] 700126K->692757K(1395712K), [Metaspace: 168705K->168588K(1202176K)], 0.8382759 secs] [Times: user=4.30 sys=0.00, real=0.84 secs]

GCログからは、CAIプロセス recipe-psa-unexpectedOOM を実行居たタイミングでFull GCが数回にわたって発生している状況が読み取れます。また、最後のFull GCには 0.8382759 secs 秒を要した状況が読み取れます。前述のとおり、Full GC発生時には動作が不安定になる可能性があるため(単発・短時間のFull GCでは基本的に影響はない)注意が必要です。

大量メモリ処理時のメモリ使用量の推移確認

process engineが出力しているGCログ(gc.log.0.current)を見るとGCの発生タイミングを確認できますが、メモリ使用量がどのように推移しているかは残念ながらわかりません。
メモリ使用量の推移はJDKに含まれるjstatコマンドで確認できますが出力内容が難解です。そのため、今回はGPTに以下のようにリクエストして、ヒープメモリの合計サイズ・空き容量・Full GCの回数を出力するコマンドを生成してもらいました。

jstatの出力をAWKにパイプして、AWKにてJavaの合計ヒープサイズ、利用可能なヒープサイズ、Full GCの回数を出力したいです。 jstat+AWKのコマンドを生成してほしいよ。

以下ではGPTにより生成されたコマンドを少し手直しして、0.5秒毎に、process engineのプロセス(pgrep -f bootstrap.jar)を対象に情報が出力されるようにして、メモリ使用量の推移を確認しています。

$ jstat -gc `pgrep -f bootstrap.jar` 500 | awk '
NR==1 {next}   # 1行目（ヘッダ）をスキップ
{
  S0C=$1; S1C=$2; S0U=$3; S1U=$4;
  EC=$5; EU=$6; OC=$7; OU=$8; FGC=$15;

  heap_total = S0C + S1C + EC + OC;
  heap_used = S0U + S1U + EU + OU;
  heap_available = heap_total - heap_used;

  printf("合計(MB):%d", heap_total/1024);
  printf(", 空き(MB):%d", heap_available/1024);
  printf(", Full GC:%d\n", FGC);
}'

合計(MB):1410, 空き(MB):726, Full GC:18
合計(MB):1410, 空き(MB):726, Full GC:18
合計(MB):1410, 空き(MB):726, Full GC:18
合計(MB):1410, 空き(MB):464, Full GC:18 ★空きが減る
合計(MB):1410, 空き(MB):207, Full GC:19 ★更に空きが減りFull GC発生
合計(MB):1410, 空き(MB):471, Full GC:19
合計(MB):1518, 空き(MB):839, Full GC:21
合計(MB):1518, 空き(MB):839, Full GC:21

途中、メモリの空き領域が減っているタイミング、Full GCが発生しているタイミングがあります。このタイミングでは前述した手順で作成しているCAIプロセス recipe-psa-unexpectedOOM を実行しています。1つのCAIプロセスが、process engineのプロセスにおいて利用可能なメモリの空き領域を減らしている動作を確認できます。

おわりに

今回動作確認をした限りでは実行したCAIプロセスのみで影響が発生していましたが、並行で実行しているCAIプロセスや、process engineサービスの動作が不安定になる状況も十分に想定できます。

process engineが健康的に稼働していることをチェックするために、GCログ(gc.log.0.current)を定期的にチェックすると良いでしょう。

参照

• Qiita - IICS CAIの実装レシピ - マスターページ