シーマークすずきです．
今回は，性能診断サービスの過去の事例をご紹介します． もちろん，障害内容の事例ですので，実際のお客様の社名は伏せてのご紹介です．
■原因不明のスローダウン
お客様は非常に人気のある携帯端末向けのサービスを提供していました． 当時，そのサービスは急成長し，ＰＶ数と供にビジネスも好調に推移していました． システムも順調に稼動し，性能問題も特になく，非常に健康的に日々運用していました． しかし，ある日突然，応答がタイムアウトするリクエストがいくつか発生したのです． 上流システム側の監視によりタイムアウトを検知し，「何か障害が発生したのか？」との上流システム側の担当者から問い合わせを受けて，初めてお客様側のシステム担当者がその事を知ることになりました． これはまるで，本人は自覚症状がないけど，友人から「一瞬，意識が遠くなってたようだけど，言葉も詰まってたし，大丈夫？」と云われたような状況です． しかし，その症状自体はしばらくすると消えてしまったのです． つまり，元の快適なシステムの状態に戻っていたのです． お客様のサービス担当者は「自社側は最近はプログラムの変更も一切していないし，マシンも故障がない状態なので，実際には，タイムアウトの原因は上流側なのでは？」と思い，「既に症状が発生していない」こともあり，この時点で特に対応しませんでした． 原因不明のスローダウンです． しかし，これは数日後に発生する性能障害の予兆でした．
■頻繁に症状発生
数日後，上流システム側の管理者から，「一日に何度も，大量にタイムアウトが発生して正常にサービス提供できない」という通達（苦情？）がお客様のサービス担当者にありました． この段階で，お客様の経営層も事態を知りしました． いきなりの事業リスクです． 一刻も早く対応し，元の健康なシステムの状態に戻す必要があります． お客様側の事業責任者は，サービス担当者と協議しましたが，原因が分かりません． 事業収支的には利益も成長も見込める状況だったようで，「取り合えず，ハードを増強しよう」となり，DB機はCPU稼働率30％程度で問題なさそうと考え，アプリサーバ機を現状の２台から４台追加し，計６台にする対策を講じた．
しかし，症状は改善しなかった． 実際には，問題事象の発生頻度が増し，全体としては，症状は更に悪化した．
■性能診断サービス：計測アプローチ
このような状態の中，私たちが呼ばれました． まず，問題事象を確認するために，アプリケーションのモニタリングをスピーディに実施しました． これにより，アプリケーションの応答回数，応答時間，リクエスト分布やマシンのリソース状況を可視化します． 他にも例えば，個々のSQLの発行タイミング，回数及びSQLの応答時間も同時に記録されます． 平行して，診断対象の環境やアプリケーションについてシステム担当者にヒアリング（問診）を行いました． 初回モニターとヒアリングにより，以下の状況が分かってきました．
- 問題事象は，上流システム側でタイムアウトを引き起すこと．
- 上流システム側は，応答が３０秒を超えると，タイムアウトし，再接続を試みる動きになっている．
- 通常の応答は平均１秒程度で応答していること．
- 性能障害発生前からアプリケーションプログラムは一切変更していない．
- アプリケーションサーバ機を2台から６台に増強したら，更に症状が悪化した．
- Javaアプリケーションサーバ上で動作し，メインは３つのServletで対応している．
- 携帯端末毎にセッションを発行するアプリケーションである．
- DBへのアクセス(SQL)は非常に速い．
- JVMのヒープは比較的大きなサイズを割り当てていた．
- マシンのリソース監視は，ロードアベレージを5分毎に記録している．
しばらく，モニターしている間に何度か問題事象を観測しました． それで以下の状況がハッキリしました．
- 問題事象の発生は，一定時間間隔や定期的ではない．
- 問題事象が発生している間はCPU稼働率が100%に張り付く．
- 問題事象が発生している時間はいつも28秒間程度
- 問題事象後はJavaの使用ヒープ量が減る．
短時間のCPU稼働率の急上昇と急降下をグラフ表示したときの絵柄から「スパイクする」と私たちは呼んでいます．まさに，CPU稼働率はスパイクし，その後，Javaの使用ヒープサイズが”ガクン”と落ちているグラフを見れば，一目瞭然です．この観測結果から，タイムアウトを引き起こす直接的な原因はJavaVMのガベージコレクター（以下GC)であることが明確になったのです． 典型的なFullGC問題です． この原因到達まではに要した時間は，モニター開始から数時間でした．なぜ，通常のマシン監視では観測できなかったのでしょうか．それは，「5分毎のロードアベレージの監視」では観測間隔が粗いのとロードアベレージ値自身が平均値のためなのです．短時間のマシンの挙動の変化，つまり，「スパイク」した様子は記録できないからなのです．我々の計測方法は，通常，5～１０秒間隔で細密にCPU稼働率やその他計測値を記録をします．従って，様々なメトリック（計測項目の値）のスパイクした状況を見逃しません．
しかし，なぜ突然FullGCによる影響が発生したのでしょうか？また，一体どのように対処すればよいのでしょうか？
■対策案の検討
直接的な原因が分かれば，対策はほぼほぼ見えてきます． これは，病名がハッキリすれば，治療法がある程度決まってくるのと似ています． 今回のFullGC問題の場合，要するに，FullGCを発生させないようにするか，又は，FullGC時間を短く抑えればよいのです． 最適な対処策を選択するためには，もう少し問題事象の発生経緯について詳しく分析する必要があります．FullGCを誘発しているのは誰か？正に犯人を知りたいところです．
つまり，
- ヒープ上のどんなクラスのオブジェクトによって占められているのか？
- そのオブジェクトの数はどのような処理に関連して増えていくのか？
我々はアプリケーションの挙動を更に細かくモニターし，可視化することにより，上記を明らかにする方針にしました．
まず，仮説を立てます．このお客様のWEBサイトは，携帯端末毎に固有の応答を返します． そのため携帯端末毎に発行するHTTPSessionオブジェクトが臭い訳です． このオブジェクトはどれくらいのサイズなのか，また，一日のアクセス状況に対し，HTTPSessionオブジェクトのヒープ上の数はどのように推移しているのかをモニターしたいということをお客様にお伝えしたところ，その場で，新たな事実が発覚しました． 実は，セッションタイムアウト時間をこれまでの設定値より2倍に増やした，ということでした． 実は，アプリケーションのコード自体は一切変更していないことは確かに正しかったのですが，セッションタイムアウトの値がJavaVMのヒープにどのような影響を与えるかを深く検討せずに，気軽に別のサービス担当者が良かれと思って値を変更していたことが発覚したのです． 実際にHTTPSessionのモニターをしたところ，JavaVM上のセッションオブジェクトの数はもの凄い数になっていました．我々の仮説はビンゴでした．さすがに人気の携帯端末向けサービスです．想像以上に端末ユニーク数が大きいのです．一般にセッションオブジェクトは「ログアウトを押す」などの明示的な無効化がされるまで，通常設定したセッション時間分，ヒープに存在し続けます． 仮にセッションタイムアウト時間を2倍の生存時間にしたら，それらセッションオブジェクトが占める領域も当然必要になります．アクセス数やユニークユーザ数が少ないサイトであれば，その設定変更は全く問題なかったのでしょうが，大規模/高負荷サイトのシステムでは命取りになりえます．
■対策後の効果測定
セッションタイムアウト値を元に戻しました．その結果，セッションオブジェクトは順次回収され，ヒープを圧迫することはなくなりました．この状況を計測し確認したところ，今後の携帯端末の利用者の増加を見込み，更に，セッションタイムアウト値をアプリケーションの許容する最短値にすることを推奨しました．これにより，当案件の問題事象に対する原因究明作業，対策案の提示及び対策後の効果測定を終えました．お客様の安心した笑顔を見るのは大変嬉しいことです．
■残った疑問点に対する答え
この案件で，問題事象に対して解決することができましたが，1つ疑問が残ったままでした．
なぜ，アプリケーションサーバ機を2台から6台に増強したら問題事象が悪化したのか？
と云う疑問です．普通，アプリケーションサーバ機の台数を追加すれば，1台辺りの処理すべき担当リクエストが減るので，応答時間が改善され，システム全体では，スループットも向上するのが一般的です．今回の場合も３倍のスループットにスケールアップすることが期待されていました．しかし，この案件の場合は違いました．実は，このアプリケーションは，DBアクセスした結果得られた値を元に生成したデータをセッションオブジェクトに保管していたのです．アプリケーション独自のキャッシュ機構を持っていたのです．一方，お客様のインフラ担当者はその仕組みは知らずに，全てのリクエストをラウンドロビンでバランシング（均等化）する設定をしていました．アクセス都度，アプリケーションサーバ機を順繰りにバラつかせるために，このキャッシュ効果が逆に1/3に減ってしまったのです．これは2台時と６台時のアプリケーションの計測結果の数値グラフの比較分析により確認できました．DBへのSQL発行数は3倍に膨れ上がっていました．もともとDB機はCPU稼働率30％ぐらいだったのですが，アプリケーションサーバ増加のために，接続プール数も3倍になり，単純にDB負荷は3倍に増えました．CPU稼働率が90%を超える状況になっていたのです．疑問に対し，解せました．
■事例その１のまとめ
この事例では，本番アプリケーションの振舞いを数値で観測し，アプリケーションの特性をきちんと理解し，アプリケーションの設定内容を熟慮するための材料を導き出すことができました．お客様自身も知らなかったアプリケーションの挙動を数値とグラフで可視化することができました．その結果，問題事象の原因と対策に対する効果測定も行い，システムの安定稼働に寄与することができました．また，我々のレポート結果をお客様にご報告後，お客様のインフラ担当者の方も，stickyなバランシングに変更し直したことで，マシン増強による投資対効果を確実に得ることができました．