AgileWorksのジョブマネージャーがGC overhead limit exceededで停止｜原因調査とヒープ拡張の記録

朝、AgileWorksのジョブマネージャーが停止していました。ジョブ用のerr.logに残っていたのは「GC overhead limit exceeded」というOutOfMemoryErrorです。落ちたというより、AgileWorksが自分でサービスをシャットダウンしていました。その3分後に動くはずだったJP1からの一括申請は、接続できずに失敗しています。

調べていくと、ジョブマネージャーのJavaヒープ上限は導入時から1GBのままでした。しかも原因はヒープ設定だけではなく、前段のジョブが61分かかったことで後続ジョブの開始が押し出され、そこにデータ増大が重なった結果でした。

まず検証環境で最大ヒープを1GBから2GBへ拡張し、設定変更、切り戻しの準備、サービス起動、夜間ジョブまでを一通り確認しています。検証環境では改善を確認できましたが、本番環境はメモリ全体の配分に別の問題があり、現時点では適用を保留しました。どの数字を見て原因を絞り込んだのか、なぜその設定値にしたのか、本番適用を見送った理由まで、実際の作業の順番どおりに残しておきます。

なお、AgileWorksでは過去に別の障害対応も行っています。アップロード処理のトラブルについては、AgileWorksのアップロードタイムアウト対応も参考にしてください。

発生した事象：ジョブマネージャーでOutOfMemoryErrorが発生

異常に気づいたのは障害発生の翌朝でした。AgileWorksのジョブマネージャーが停止していたので、まずジョブマネージャーのエラーログであるD:\apps\agileworks\logs\job\err.logを開きました。そこには、次のエラーが出力されていました。公開用の記事では日付部分のみぼかしていますが、エラー内容と時刻、スタックの種類は実際に確認したものです。

[8月上旬 04:07:10] GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
[8月上旬 04:07:15] Exception At: Queue[SYSTEM]:Executer[00]
java.lang.OutOfMemoryError: GC overhead limit exceeded

GC overhead limit exceededは、Java VMがガベージコレクションに長い時間を使っているのに十分なメモリを回収できず、アプリケーションの処理がほとんど前へ進まなくなったときに出るOutOfMemoryErrorです。「メモリを一瞬使い切った」というより、GCを繰り返しても空きヒープを作れない状態に近づいている、と考えた方が実態に合います。

err.log、info.log、監視ログを突き合わせると、当日の流れはこうなっていました。

ここで確認しておきたかったのは、サービスがOSやハードウェアの都合で落ちたのではなく、OutOfMemoryErrorを検知したAgileWorksが[ABORT]として自分でシャットダウンしている点です。プロセスが消えた形跡を探しても何も出てきません。停止の理由はアプリケーションのログにしか残っていません。

もう一つ、04:00:03の監視では全サービス正常、メモリ使用率も75.45%で普段どおりでした。異常が数字に現れたのは04:05:12のCPU 85.23%で、そこから2分後には停止しています。5分間隔の監視では、ほぼ引っかかりません。

ログにはQueue[SYSTEM]:Executer[00]も記録されていました。ここから、少なくとも今回のエラーはAgileWorksのジョブ実行処理の中で起きていることが分かります。OS全体のメモリ不足だけを疑うのではなく、まずジョブマネージャーを動かしているJava VMのヒープ設定と、実際のヒープ使用状況を見ることにしました。

SYSTEMキューは1スレッド：前のジョブが延びると後続が押し出される

エラーメッセージのExecuter[00]は、ただの識別子ではありませんでした。AgileWorksのSYSTEMキューは実行スレッドが1本しかありません。同じキューに入ったジョブは順番待ちになり、前のジョブが延びるとその分だけ後続の開始時刻がずれます。

03:00:00 ┌─ #DB_OPTIMIZER  データベース最適化
         │  （61分12秒）
04:01:12 └─ 完了
04:01:12 ┌─ #DELEGATION    回付中書類への権限委譲適用
         │  （約6分でヒープ枯渇）
04:07:10 └─ OutOfMemoryError → サービス停止
04:10:10    JP1 一括申請 → 接続失敗

本来#DELEGATIONは3:00に投入され、そのまま動き出す想定です。ところが同じ3:00投入の#DB_OPTIMIZERが61分かかったため、開始が04:01まで押し出されました。そこから約6分でヒープを使い切り、JP1のバッチ時刻である4:10に間に合わなくなっています。

2つのジョブの設定は次のとおりです。どちらもcron指定は0 0 3 ? * * *で、毎日3:00に投入されます。

調べていて分かりにくかったのが、AgileWorks側のJOBIDです。info.logに出てくるJOBIDはAgileWorks内部の連番で、毎日リセットされます。JP1のジョブIDとは無関係で、JP1/AJS3 Viewからは参照できません。JP1側の実行履歴と突き合わせようとすると、ここで一度つまずきます。時刻で照合するしかありません。

#DB_OPTIMIZERが61分かかった点についても、この時間帯に大量のトランザクションログが出ていました。DBの更新を伴う処理が動いていたことになります。JP1側で日中に実行しているインデックス再構築ジョブと内容が重複している可能性があり、こちらは別途確認するつもりです。

なぜヒープ不足を疑ったのか：最大ヒープが導入時の1GBのままだった

次に見たのは、ジョブマネージャーが現在どのJava VMオプションで起動しているかです。実行中のJavaプロセスに対してjcmd <PID> VM.flagsを実行すると、JVMに実際に反映されている主要な設定が確認できます。設定ファイルを探して推測するのではなく、今動いているプロセスがどの値で起動しているかをそのまま見られるので早いです。

-XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 ... -XX:+UseParallelGC

1073741824バイトは1GBです。InitialHeapSizeもMaxHeapSizeも1GBで、初期ヒープと最大ヒープが同じ値になっていました。AgileWorksを導入した2020年当時から、この値は据え置きです。

一方、処理対象のDBはこの規模になっていました。

5,700万行規模のテーブルを、1GBのヒープで処理しようとしていたことになります。しかも本番サーバーの物理メモリは27.9GB積んでいて、SQL Serverが15GBを固定で確保しているほかは、約12GBが使われないまま残っていました。メモリが足りないのではなく、ジョブマネージャーに割り当てていなかっただけです。

出力には-XX:+UseParallelGCも含まれていました。この設定だと、後ほどGC.heap_infoで確認するヒープ領域がPSYoungGenやParOldGenという名称で表示されます。ログ上のOutOfMemoryError、最大ヒープ1GBという設定、5,700万行というデータ規模。この時点で疑いはかなり強くなりましたが、まだ「ヒープを増やせば解決する」とまでは決めていません。

そこで、次に見るべき数字をヒープ内部の使用状況に絞りました。特に、長時間生き残ったJavaオブジェクトが格納される老年世代がどの程度埋まっているか。ここが高い状態で張り付いていれば、GCを実行してもメモリを十分解放できていないという見立てを、より具体的に裏づけられます。

#DELEGATIONの実行時間は6年で0分から60分になっていた

もう一つ確認したのが、#DELEGATIONの実行時間の推移です。info.logから月別の最大実行時間を拾うと、増え方がはっきり出ました。

導入直後はほぼ一瞬で終わっていた処理が、6年かけて60分に届いていました。しかもタイムアウト値の3600秒と同じ水準です。前日まで完走できていたのは、限界すれすれで通っていただけでした。

この推移を見て、今回の障害の見え方が変わりました。単発のメモリ不足ではなく、1年以上前から続いていた夜間バッチの機能不全が、サービス停止という形で表面化した、という整理です。設定は導入時のまま、データだけが増え続けていました。

GC.heap_infoでヒープの使用状況を確認する

ヒープ内部の状態は、実行中のジョブマネージャーに対してjcmd <PID> GC.heap_infoを実行して確認しました。Javaのヒープを普段見ていないと出力される領域名だけでは判断しにくいため、今回注目したポイントを整理しておきます。

問題だったのはParOldGenです。障害後の本番サーバーで確認した時点で、使用率は88%まで上昇していました。老年世代には、Young領域でのGCを何度か生き残ったオブジェクトが移動してきます。この領域が高い状態になると、GCを繰り返しても十分な空き領域を確保できず、処理を続けるのが難しくなります。04:05:12にCPUが85.23%まで跳ね上がっていたのも、GCが空転していた状態と整合します。

もちろん、88%という数字だけを見て「必ずヒープ不足」と断定はできません。ただ今回は、実際にGC overhead limit exceededが発生していること、最大ヒープが1GBであること、ParOldGenが88%まで使用されていること、処理対象が5,700万行規模であることが同時に確認できました。少なくとも「現在の1GBではジョブ処理時のメモリ需要に余裕がない」と判断する材料はそろったと考えています。

変更前にレジストリを退避して切り戻し手順を確保した

ここからは検証環境での作業です。設定変更の前にまずやったのは、いつでも元の設定に戻せる状態を作ることでした。AgileWorksのジョブマネージャーは、Apache Commons Daemonのprocrunを使ってWindowsサービスとして動作しています。この構成では、Javaのヒープ設定が一般的な設定ファイルではなく、Windowsレジストリに登録されています。

今回対象になった設定は、HKLM\SOFTWARE\Wow6432Node\Apache Software Foundation\Procrun 2.0\aw-job-manager配下にありました。設定ファイルを検索してもヒープサイズの記述が見つからなかったのは、この構成が理由です。変更前に、次のコマンドでレジストリをファイルへ退避しました。

New-Item -ItemType Directory -Path "C:\temp" -Force
reg export "HKLM\SOFTWARE\Wow6432Node\Apache Software Foundation\Procrun 2.0\aw-job-manager" "C:\temp\aw-job-manager_backup.reg" /y

設定変更後に問題が起きた場合は、退避したaw-job-manager_backup.regをreg importで戻せます。サービス設定はGUIで変更できるので作業自体は簡単に見えますが、本番運用に近い検証では、戻せることを確認してから変更してください。特にJava Optionsには複数の起動パラメーターが入っているため、誤って別の値まで変更すると原因の切り分けができなくなります。

Wow6432Node配下に設定がある点も見落としやすいところでした。Windowsサービスの設定を追うときに通常のレジストリパスだけを探していると、目的のProcrun設定にたどり着けません。今回のように設定画面から変更できるアプリケーションでも、まずサービス化の仕組みを確認して、変更前の値をレジストリごと保存しておくと安心です。

Maximum memory poolだけを1024MBから2048MBへ変更した

切り戻しの準備ができたら、Procrunのサービス設定画面を開きます。今回実際に使用したコマンドは次のとおりです。

D:\apps\agileworks\job-manager\bin\aw-job-managerw.exe //ES//aw-job-manager

//ES//は、Procrunで対象サービスの設定編集画面を開くための指定です。画面を開いたら「Java」タブを確認し、Maximum memory poolを1024から2048へ変更しました。Initial memory poolは1024のまま変更していません。Java Optionsについても今回は触っていません。

-Xmsに相当するInitial memory poolまで2GBへ上げなかったのには理由があります。検証機の物理メモリは15.9GBで、変更前に確認したメモリ使用率は79%、空きは3.3GB程度でした。Initialを2048MBにすると、ジョブマネージャーは起動時点からより大きなヒープを確保します。その分、SQL ServerやTomcatなど、同じサーバー上で動く他サービスへの余裕が減ります。

今回の目的は「常時2GBを使わせること」ではなく、「ジョブ処理中に1GBでは足りなくなった場合、2GBまで拡張できるようにすること」です。初期値は1GBのままにして、最大値だけ2GBへ広げました。この判断が、後ほど確認したサーバー全体のメモリ使用率にもそのまま効いてきます。

変更後は3段階で確認した：設定反映、メモリ使用率、サービスとログ

設定変更後は、サービスが起動しただけで完了にはしませんでした。設定が本当にJVMへ反映されたか、OS全体と各プロセスのメモリ使用量はどうか、関連サービスとエラーログはどうか。この3段階です。

第1段階では、ジョブマネージャーを再起動した後にPIDを取得し、VM.flagsとGC.heap_infoを再確認しました。

Restart-Service aw-job-manager
Start-Sleep 30
$p = (Get-Process aw-job-manager64).Id
& "D:\apps\jdk\bin\jcmd.exe" $p VM.flags
& "D:\apps\jdk\bin\jcmd.exe" $p GC.heap_info

ここでMaxHeapSize=2147483648、つまり2GBになっていることを確認しました。もし1GBのままであれば、GUI上で保存したつもりでも設定が反映されていないので、作業をやり直すことになります。なお、再起動直後にGet-Process aw-job-manager64が何も返さない場合がありました。サービスがまだ起動途中のためで、数十秒待ってから確認し直します。

第2段階ではサーバー全体のメモリを確認しました。変更前には、最大ヒープを2GBにすればメモリ使用率が約85%まで上がると予測しており、社内基準の80%を超える前提で作業申請していました。ところが実測はまったく違いました。

プロセス別の実使用量も確認すると、ジョブマネージャーの最大ヒープを2GBへ変更したにもかかわらず、aw-job-manager64の実使用量は0.60GBでした。

sqlservr           5.52 GB
java               0.62 GB
aw-job-manager64   0.60 GB
tomcat9            0.54 GB

最大ヒープを2GBにしたからといって、直ちに2GBすべてを使用するわけではありません。今回Initial memory poolを1GBのまま据え置いたこともあり、必要以上にメモリを確保せずに上限だけを広げられました。事前予測では85%だったものが実測74.1%となり、むしろ変更前より低い数字になった点は、実際に検証しなければ分からなかった結果です。

第3段階では関連サービスとerr.logを確認しました。

Get-Service aw-job-manager, asb, aw-mail-server, MSSQLSERVER | Select Name, Status
Get-Content "D:\apps\agileworks\logs\job\err.log" -Encoding Default -Tail 20

aw-job-manager、asb、aw-mail-server、MSSQLSERVERの4サービスがすべてRunningであることを確認し、さらにerr.logに新しいエラーが追加されていないことも確認しました。-Encoding Defaultを付けているのは、日本語を含むログをPowerShellで読んだ際の文字化けを避けるためです。

翌日の夜間ジョブ後にParOldGenを再確認した

サービス再起動直後に正常だったとしても、それだけでは今回の問題が改善したとは判断できません。OutOfMemoryErrorはジョブ実行時に発生していたため、実際に負荷の高い夜間ジョブが流れた後の状態を見る必要があります。AgileWorksでは夜間の2時から4時ごろに複数のジョブが集中していたため、翌朝にinfo.logとヒープ状態を再確認しました。

夜間処理の実行状況を見るために使用したコマンドは次のとおりです。

Get-Content "D:\apps\agileworks\logs\job\info.log" -Encoding Default |
  Select-String "DELEGATION|DB_OPTIMIZER|03:|04:" | Select -Last 40

対象時間帯には、#DELEGATION、#DB_OPTIMIZER、#DOC_ARCHIVE、#WF_CLEANERなど複数のジョブが動作します。今回見たかったのは「サービスが生きているか」ではなく、普段負荷が掛かる夜間処理を通過した後でも老年世代が逼迫していないかどうかです。

翌朝のGC.heap_infoで確認したParOldGenの使用率は6%でした。検証環境で夜間ジョブを通しても、老年世代が高止まりする状態にはなっていません。ただし、この6%は検証環境の値で、88%は本番サーバーの障害後に確認した値です。データ規模が違うので、同じ物差しで並べた比較ではない点は補足しておきます。

夜間バッチは「起動したか」だけでなく、「終了すべき処理が予定どおり終了したか」まで見ないと意味がありません。今回の障害も、実行時間が延びていること自体は1年以上前からログに出ていました。バッチ監視そのものについては、夜間バッチが動かなかった場合の監視方法も参考になります。夜間処理の自動化についてはJP1とFTPを使った夜間バッチ自動化で実運用時の考え方をまとめています。

検証では改善したが、本番環境への適用は保留した

検証環境では、設定変更手順が機能すること、最大ヒープが2GBへ変更されたこと、サービスが正常に再起動すること、夜間ジョブが流れること、ParOldGenが6%にとどまることを確認できました。それでも、本番環境へそのまま適用する判断はしていません。Javaヒープ単体ではなく、サーバー全体のメモリ配分を考える必要があったからです。

本番サーバーは物理メモリ27.9GBで、検証機の15.9GBより多い構成です。ただしSQL Serverがmin/maxとも15GBで固定されています。障害調査の結論としては、ジョブマネージャーのヒープを4GBまで増やす案を最優先の対策として挙げました。SQL Serverが固定されている分、残りメモリの配分を計算しやすいという事情もあります。

引っかかったのが、この約86%という数字です。社内では80%を一つの管理基準にしているため、そのまま適用するには説明が要ります。SQL Serverの上限を約2GB削減すれば全体は約79%まで下がりますが、今度はデータベース性能への影響を考えることになります。物理メモリを増設できれば余裕は作れますが、構成変更と費用、作業計画が必要です。

本番へ適用する場合は、ヒープサイズと合わせてJava Optionsに-XX:+HeapDumpOnOutOfMemoryErrorと-XX:HeapDumpPathを追加する予定です。今回はOOMの瞬間のヒープダンプが残っておらず、どのオブジェクトが領域を占めていたのかまでは追えませんでした。次に同じことが起きたときに何も残らないのは避けたいところです。ダンプ出力先のディレクトリは、設定変更の前に作成しておきます。

現時点ではどの案にするかを決めておらず、本番適用は保留のままです。検証環境で改善したからといって、本番でも同じ容量を入れればよいとは限りません。今回の検証で得られたのは、「変更手順が安全に実行できること」と「本番容量が妥当かどうか」は別問題だと切り分けられたことでした。

ヒープ上限を増やしてもメモリ使用量が同じだけ増えるとは限らない

今回いちばん意外だったのは、「最大ヒープを1GBから2GBへ増やす」ことと、「OS上で実際に1GB多くメモリを消費する」ことが別物だった点です。事前には最大値を1GB増やす分だけサーバー全体のメモリ使用率も上昇すると考え、約85%まで達すると予測していました。実測の使用率は74.1%で、空きメモリも4.1GB残りました。

この差は、Initial memory poolとMaximum memory poolを分けて考えると説明がつきます。Maximum memory poolは、Javaヒープが必要に応じて拡張できる「上限」です。今回の設定では、ジョブマネージャーが常時2GBを使うようにしたわけではありません。Initialを1GBのまま維持し、処理中に必要になった場合のみ2GBまで拡張できる余地を作っています。

実際、変更後のaw-job-manager64の実使用量は0.60GBでした。この数字だけを見ても、最大値2GBと実際の使用量が一致していないことが分かります。Javaのヒープ拡張を検討する場合は、「-Xmxを何GBにしたか」だけでサーバーの消費メモリを決めつけず、変更後にOSとプロセスの実測値を取る。今回はこれが効きました。

ただし、上限を大きくすれば何でも解決するわけでもありません。本番では4GB案を検討したものの、SQL Serverとのメモリ配分で引っかかりました。Java側だけを見れば余裕を増やしたいところですが、サーバー全体ではOS、データベース、Web・アプリケーション関連サービスにもメモリが要ります。ヒープサイズは単独の設定値ではなく、同居するサービスを含めたリソース設計の一部として決めるものだと考えています。

同じGC overhead limit exceededが出たときの確認順序

今回の対応を振り返ると、同じようにAgileWorksのジョブマネージャーでGC overhead limit exceededやOutOfMemoryErrorが発生した場合、次の順番で確認すると状況を整理しやすいと感じました。最初から設定変更へ進まず、ログ、現在値、ヒープ内部の状態を順番に見ていきます。

1. err.logでGC overhead limit exceededやOutOfMemoryErrorが出ているか確認する。[ABORT]で自らサービスを停止している場合は、その記録もログにしか残らない。
2. info.logで当日のジョブの開始・終了時刻を並べ、どのジョブの実行中にエラーが出たか、前段のジョブに押し出されていないかを確認する。
3. そのジョブの過去の実行時間を月別に拾い、タイムアウト値にどこまで近づいているかを見る。
4. jcmd <PID> VM.flagsを実行し、現在のMaxHeapSizeを確認する。
5. jcmd <PID> GC.heap_infoを実行し、特にParOldGenの使用率を確認する。
6. 最大ヒープに余裕がなく、老年世代の使用率も高い場合はヒープ拡張を検討する。あわせて、サーバーに未割り当てのメモリが残っていないかを確認する。
7. 変更前にreg exportでProcrunのレジストリ設定を退避し、切り戻し手段を確保する。
8. //ES//でサービス設定画面を開き、必要な項目だけを変更する。今回の場合はMaximum memory poolのみを1024MBから2048MBへ変更した。
9. サービス再起動後にVM.flagsで反映を確認し、続いてOS全体のメモリ使用率、プロセス別使用量、関連サービス、err.logを確認する。
10. 実際に負荷が掛かる夜間ジョブを通過させ、翌朝にもう一度GC.heap_infoを確認する。

今回はこの手順で確認したことで、最大ヒープ1GBに対して処理対象が5,700万行規模まで増えていたこと、#DELEGATIONの実行時間が6年で0分から60分に伸びてタイムアウト値に達していたこと、そして検証環境で2GBへ変更した後の夜間ジョブ通過後はParOldGenが6%にとどまることを確認できました。事前に85%と予測していたサーバー全体のメモリ使用率も、実測では74.1%です。どれも設定画面を見ているだけでは分かりません。

本番環境については、Javaヒープを増やせば終わりではなく、SQL Serverを含むメモリ配分の再検討と、ヒープダンプを残す設定の追加が残っています。#DELEGATIONの実行時間そのものを短くする方法も、まだ手をつけられていません。検証がうまくいったことをそのまま本番適用の根拠にはせず、現在も適用は保留中です。今回の検証では、そのために必要な設定変更手順、切り戻し方法、確認すべき指標まで整理できたことが収穫でした。