シーマークすずきです．

久々にタイ古式マッサージをしてもらってきました．肩コリがとっても楽になりました．

さて，今回は性能診断分析サービス事例の第二段です．

■CPU稼働率が100%に暴走

お客様は大手のコンシューマ向けWebサイトを運営しています．複数のWebサイトを実施している中，２週間後にそのうちの１つをリニューアルしたことを大々的に告知するテレビコマーシャル(以下TVCM)が開始される予定でした．実はWebアプリケーションのリニューアル開発は既に完了し，本番稼働できる状態でしたが困った問題を抱えていました．それは，ステージング環境では発生しないのに，本番環境では稼動中に突然CPU稼働率が100％に張り付く，というものでした．

Tomcatを起動し，公開用のロードバランサーに参加し実際のリクエストを当て始めると数分で暴走することもあれば，数時間サービスした後に暴走を開始するケースもあった．数日間サービスを順調にしていたと思ったら，暴走してしまう，ということも．一度暴走するとTomcatプロセスを強制停止しなければならず，正常サービスを維持できなくなってしまうのです．

■問題事象の定義

TVCMが始まると非常にたくさんのアクセスが来ることが予想されていますが今の状況だと，せっかくリニューアルサイトに集客できてたとしても，サービスを提供できない可能性があるわけです．これは広告効果の問題以前に，会社の信用にかかわります．現状CPU暴走がなぜ発生するのか原因が分からないため，マシン台数をいくら足しても無駄な投資となってしまうため，どうしても早急に根本原因を突き止めたいという状況です．お客様からの我々への依頼内容は，TVCM開始までに対策を講じたいので，できるだけ早期に原因を突き止めてほしい，という内容でした．

今回の問題事象は，

CPU稼働率100%に張り付きっぱなしになる．

ということ．

掴みどころがない，非常に問題切り分けが難しい，ヘンな話しですが，個人的に好きなタイプの案件です．私は難しい仕事の依頼が来ると，ワクワクしてしまいます．

■性能診断分析サービス：計測アプローチ

私たちの性能診断分析サービスの基本アプローチは”数値”で計測し，評価することです．まず，問題事象を捕えることにしました．お客様のこれまで実施した感覚だと十中八九，リニューアル版を本番サービス投入すれば３時間以内に問題事象は１回は発生するだろう，との情報がありました．しかし，実際には，本番機は複数台存在しているが事象が何号機で発生するかは不明なのです．複数台同時に発生することもあります．

我々としては，全部のマシンに性能計測を仕込むのは時間も手間もかかるため，２台だけにモニターの網を張ることにしました．まず，問題事象が発生したことを確認するため，CPU稼働率をモニターすることにしました．同時に，アクセスしてきたリクエストのタイミングを記録することにしました．問題事象を引き起こした直前に実際にどんなリクエストが来たのかを限定し，問題事象を再現するための手懸りをえるためです（容疑者を狭めるため）．

■尻尾を掴むヒントは詳細な分析

２台に仕掛けた網にかかったのはモニター開始後の約１時間後でした．これで以下が分かってきました．

• 問題事象が発生すると確かにCPU稼働率が100%になった．
• 細かく分析すると，実際には，100%に振り切る前に50%で推移している段階を経ていた．
• 暴走開始後，しばらく経っても問題事象は解消しない．
• 問題事象発生後，Tomcatプロセスを終了すると問題事象は解消される．
• 直前のリクエストが１００個のURLに限定した．犯人はこの中にいる．

捕獲した100個の容疑者リクエストURLを順番に叩いていけばステージング環境でも発生できるのではないか，と推定しました．それよりも興味深いのは，問題事象に到達する前にCPU稼働率50%でしばらく維持する点でした．グラフで見れば不思議な形状が一目瞭然です．普通，ジグザグした絵を見せるCPU稼働率のグラフが，平らな２段の階段上になっているのです．

マシン構成を調べてみると本番機は全てデュアルコアのマシンでした．性能診断分析チームで検討した結果，コアが１つづつＣＰＵ稼働率１００％に振り切っている，という説．恐らく，クワッドコアのマシンならば４段の階段上にグラフが見える様になるのではないか，という意味です．何かの原因でTomcatのワーカースレッドが一つづつ無限ループにハマり，コアが１つづつ死んでいく，という説が分析の結果有力となった仮説でした．

■原因箇所の特定のための仕込み

現象からすると我々の仮説は正しそう．それでは原因となるクラスのメソッドを特定するためにはどうすればよいのでしょうか？性能診断分析チームで検討した結果，CPU稼働率が９０%以上に張り付く事象を検知したら，スレッドダンプを自動採取する仕掛けを組むことにしました．

この仕掛けが機能すれば，クラスとメソッドレベルで暴走スレッドのスタックを採取できるため，犯人を特定できる，と考えました．そのため，この再現するであろう１００個のＵＲＬを順番に実行するJmeterのシナリオを作成し，ステージング環境で問題事象再現テストを行ないました．

■再現しないのはなぜ？

Jmeterのシナリオは30秒毎に１発づつじっくり実行していきました．しかし，１００個の容疑者ＵＲＬは全て正常に実行して終了してしまいました．ステージング環境の再現テスト機はCPU稼働率が５０％になることさえもなく，正常にＪｍｅｔｅｒシナリオが完了してしまったのです．どうして問題事象が再現しないでしょうか．性能診断分析チームはもう一度Jmeterシナリオを走らせたが結果は変わりませんでした．

本番環境とステージング環境の違いは何か？答えが１つ見つかりました．それは本番環境は，全ての本番機が共有するNFSサーバ上のディレクトリを見ていたのです．ステージング環境は，ステージング用のディレクトリを見ています．この設定を意図的に本番環境のディレクトリを見る様にして，先程のJmeterシナリオを実行すると，見事に２段階の階段上のグラフが現れました．

■原因はプログラムのバグ

きれいに問題事象をステージング環境で再現できました．併せて，スレッドダンプも採取することに成功しました．原因もハッキリし，お客様と開発ベンダー様同席でご説明したところ，分析チームが指摘した箇所のクラスのメソッドにバグを発見し修正することができました．特定のファイルがあることを期待したコーディングが原因でした．whileループのbraek条件がその特定ファイルを読むことだったのです．しかし，本番環境のNFSサーバ上のディレクトリには，そのファイルがありませんでした．ステージング環境のディレクトリからファイルをコピーしたところ，whileループから正しく抜けることも確認しました．そもそも，ファイルがなかった時の考慮をソース上修正してもらうことで根本原因を除去しました．

■無事TVCM放映

予定通りTVCMも放映されました．お客様も安心してCM放映開始日を迎えることができて，本当に嬉しそうでした．原因は本当に些細なことでした．しかし，その些細な原因がはっきりしないと，とてつもない恐怖に感じたとサービス責任者が笑顔で御礼の言葉を私達に伝えてくれました．

シーマークすずきです．

今回は，性能診断サービスの過去の事例をご紹介します． もちろん，障害内容の事例ですので，実際のお客様の社名は伏せてのご紹介です．

■原因不明のスローダウン

お客様は非常に人気のある携帯端末向けのサービスを提供していました． 当時，そのサービスは急成長し，ＰＶ数と供にビジネスも好調に推移していました． システムも順調に稼動し，性能問題も特になく，非常に健康的に日々運用していました． しかし，ある日突然，応答がタイムアウトするリクエストがいくつか発生したのです． 上流システム側の監視によりタイムアウトを検知し，「何か障害が発生したのか？」との上流システム側の担当者から問い合わせを受けて，初めてお客様側のシステム担当者がその事を知ることになりました． これはまるで，本人は自覚症状がないけど，友人から「一瞬，意識が遠くなってたようだけど，言葉も詰まってたし，大丈夫？」と云われたような状況です． しかし，その症状自体はしばらくすると消えてしまったのです． つまり，元の快適なシステムの状態に戻っていたのです． お客様のサービス担当者は「自社側は最近はプログラムの変更も一切していないし，マシンも故障がない状態なので，実際には，タイムアウトの原因は上流側なのでは？」と思い，「既に症状が発生していない」こともあり，この時点で特に対応しませんでした． 原因不明のスローダウンです． しかし，これは数日後に発生する性能障害の予兆でした．

■頻繁に症状発生

数日後，上流システム側の管理者から，「一日に何度も，大量にタイムアウトが発生して正常にサービス提供できない」という通達（苦情？）がお客様のサービス担当者にありました． この段階で，お客様の経営層も事態を知りしました． いきなりの事業リスクです． 一刻も早く対応し，元の健康なシステムの状態に戻す必要があります． お客様側の事業責任者は，サービス担当者と協議しましたが，原因が分かりません． 事業収支的には利益も成長も見込める状況だったようで，「取り合えず，ハードを増強しよう」となり，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を誘発しているのは誰か？正に犯人を知りたいところです．

つまり，

1. ヒープ上のどんなクラスのオブジェクトによって占められているのか？
2. そのオブジェクトの数はどのような処理に関連して増えていくのか？

我々はアプリケーションの挙動を更に細かくモニターし，可視化することにより，上記を明らかにする方針にしました．

まず，仮説を立てます．このお客様の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なバランシングに変更し直したことで，マシン増強による投資対効果を確実に得ることができました．