はじめに
現在のWebシステム開発・運用で踏まえるべき新しい技術的な取り組みについて、日立Cosminexusの製品群を題材として取り上げながら解説する本連載の前回では、トラブルシューティング実践編の第1回としてシステムスローダウンとDB周りのトラブルシューティングを解説しました。
最終回の今回は、トラブルシューティング実践編②として、具体的な事例をベースに、メモリ周りのトラブルシューティングの流れを説明します。
ログイン数の多さによるGC多発
あるWebシステムでは、通常であれば数秒以内で応答が返ってきます。ところが、業務処理の締めである月末を迎えると、応答時間が数十秒から数分かかるようになりました。業務がスムーズに行われなくなり、会社全体の作業効率が低下してしまいます。数百人から数千人のユーザが接続すると、スローダウンが発生します（図1）。
図1 ログイン数増加でスローダウンが発生するケース
原因の特定から解決まで
システムへのアクセスが集中するとリクエストの応答時間が大幅に遅くなっている現象からWeb/APサーバ内部でメモリが圧迫されていることが考えられるため、まずはWeb/APサーバの実行基盤であるJava VMのメモリ管理領域（Javaヒープ）の使用状況を見ます。このケースでは同時ログイン数が増えると、HTTPセッションの総量も増加しています。JavaヒープにはHTTPセッションが存在し、これに圧迫されてFull GC（ガベージコレクション）が発生し、業務効率性能に影響していました。
続いて、Javaヒープの使用量を詳細に見ます（図2）。
図2 Javaヒープ領域の使用量
ログイン数増加に伴いHTTPセッションの総量が増えていき、Javaヒープの閾値（いきち）を超える9時半以降に、Full GCが多発しています。なお、この閾値はFull GCの発生条件の一つである「New領域の使用サイズ＞Old領域の空きサイズ」の条件が満たされるラインです。-Xmxは最大ヒープサイズ、-XX:NewRatio、New世代とOld世代領域を示すものとすると、ラインは図2中の①の計算式で求められます。例えば-Xmx指定値が768m、-XX:NewRatio指定値が2の場合は、768×2÷（2＋1）＝512Mバイトとなります。
GC処理時間の散布グラフ（図3）を見ると、Copy GCの処理時間が0.5秒未満なのに対して、Full GCでは4秒以上かかっていて、しかも発生頻度も多くなっていることがわかります。
図3 GC処理時間
1分間あたりの発生頻度を比較したところ、Copy GCは最大で6回／分、Full GCは同7回／分でした。Copy CGは処理時間が小さいためパフォーマンスにはほとんど影響しませんが、Full GCは処理時間が長いため、多発するとパフォーマンスが劣化してしまいます。GC処理によって業務処理にCPUが割り当てられない時間の割合をGCの占有率といいます。1分ごとのCopy GCとFull GCの占有率をグラフ化したところ、Copy GCの占有率はほとんど確認できませんが、Full GCの占有率は30～60％とかなり大きくなっています（図4）。図4のGCの占有率は、経験から2％以下は安全、5％超えは要注意、15％を超えるとユーザからのクレームが増えます。GCの占有率とスループットとは大きく関係します。
図4 GC処理占有率
GCの多発はアプリケーション全体の性能に影響しますが、特定の業務処理に起因する問題ではないため、PRFトレース[1]
ではボトルネックを見つけることができません。その場合には、メモリやCPUなどリソース面でネックになっていないかを調査する必要があります。
CosminexusではGCログをCSV形式で出力可能であり、MS Excelなどを使えば簡単にグラフ化できるため、Javaヒープ使用量やGCの発生頻度を視覚的に分析することで、通常は半日かかる原因究明も数時間程度で終了しました。
今回のケースでは、通常は閾値を超えないようログイン数を制限する設定が適切にされていないため、トラブルが発生しました。
対策として、マシンの台数を増やすことでシステムの負荷を分散させて、無事解決に至りました。
同時処理実行数の多さによるGC多発
次の事例は、先ほどの事例と同様のシステムです。現象も同じように、システムの応答に時間がかかるようになってスローダウンが発生していますが、原因が異なっています。
原因の特定から解決まで
リクエストの同時実行処理数をグラフ化すると、上限値が256に設定されていて、それを超えている時間帯があります（図5）。上限値は通常40～50が適切な範囲であり、あまりに大きいとCPUやメモリがパンクしてしまうのです。
図5 リクエスト同時実行処理数
Javaヒープ領域の使用量を見ると、Full GCの閾値は超えないものの、頻繁に達していることがわかります（図6）。そこで、GC処理時間の占有率をグラフ化したところ、Copy GCの占有率が異常に高く、危険レベルを大きく超えてしまっていました（図7）。
図6 Javaヒープ領域の使用量
図7 GC処理実行時間の占める割合
システムへの負荷が低いはずのCopy GCでも、頻発すればスローダウン発生を招くことになってしまいます。
このケースでは同時実行数を通常範囲にまで減らしましたが、それだけでは不十分であったため、マシン台数を増やして対処しました。
一般的に、同時処理実行数が増えてトランザクション数が多くなるとFull GCが多発し、パフォーマンスが劣化します。同時処理実行数が大きいと使用中メモリの合計サイズも増大し、Javaヒープ内のNew領域に入り切らなくなってしまうため、短命なオブジェクトにもかかわらずOld領域に移動され、Full GCの発生頻度が高くなるからです（図8）。
図8 同時処理実行数が増えてトランザクション数が多くなるとFull GCが多発する
「同時実行処理数を増やせば処理が速くなる」と思い込みがちですが、これは間違いで、適切な設定が必要なのです。
システムトラブルにおいて、さまざまな解析手段を駆使して状況を正確に把握し、設定が不適切でないかも含めて調査・検討することが、トラブルの解決には不可欠といえます。
