性能診断分析サービス事例 その3

シーマークすずきです.

最近,つけ麺にハマっています.自分的には約7年周期でつけ麺がマイブームになる,という事実...

さて,性能診断分析サービスの事例,第3段となります.今回は,性能向上です.

■サイト利用者から「ページが遅い」の声

あるコンシューマ向けWebサイトを運営しているお客様の事例です.その会社の事業部の責任者は,「ページが遅い」というサイト利用者からの意見が多くなってきていることを課題の一つとして認識していました.実際に,自分でブラウザで試してみても,時々詰まったような遅いページがあったり,特定のページが極端に遅い,という経験を実際に体感していたのです.サービス責任者としては,お客様のニーズに応えることが最も重要です.Webサイトとしてニーズに応えることに加えて,リーズナブルな応答時間内に,という性能観点の目標もあるのです.そこで,サービス責任者は「ページが遅い」というサイト利用者からの声に対して何らかの改善策を具体的に検討することになりました.

 

■暗中模索

まず,開発パートナー会社さんとインフラを提供しているインフラ会社さんに現行システムの性能向上のための施策案を検討してもらいました.しかし,開発パートナー会社さんからは,簡単に云えば「マシンが遅いからだと思う」や「DBが遅いから仕方ない」とか「デザインが重いから」という様なポイントが出てきて,インフラ会社さんからは,「アプリが遅いからどうしようもない」とか「DB側は遅いSQLが無いので問題ではない」という指摘が出てきてしまい,お客様のサービス責任者の方も困ってしまいました.「取り合えず,自分たちじゃない」という反応だったからです.現行システムを請け負っている会社としては,仕事を増やしたくないとか責任範囲外なので,ということをお客様に伝えたい気持ちがあるのでしょう.一種の自己防衛本能です.

サービス担当者は,暗闇の中で何かを探すような感じで,手がかりが分からないままに「手探り」状態でなんとかして問題を解決しなければなりません.そんな文字通り暗中模索の頃にお客様からご連絡を頂きました.

 

■まずは現状把握

まずは状況を正確に把握しなければ,対策案もでてきません.そこで性能診断分析サービスのアプリケーションの挙動を数値で計測する技術が活きてきます.本番環境で数値で計測した結果は何よりも説得力があります.仮に改善内容の方法にアプリの改修が絡んだ場合でも,開発パートナー会社さんも計測した数値で説明すると,「なるほど,これは改修の効果が期待できますね」ということでご納得してタスク化してもらえます.逆に,開発会社様からは,「本番サービス環境下では,このメソッドがこんなに時間がかかっているのですね.意外だなぁ.」と新たな発見をしてもらえることもあります.ともかく,本番サービス環境のアプリケーションの挙動を数値で計測することから作業を開始しました.

 

■課題は何か?

次は,課題は何か?です.お客様のWebサイトにはたくさんのメニューやコーナーがあります.まずは,そのメニューやコーナー事に時間毎応答回数や平均応答時間をまとめました.予めお客様から頂いていた,このWebサイト内のビジネス上の重要度が高いメニューやコーナー,重要シナリオ(ページ遷移)と見比べてみると,課題が明確になってきました.どうやら,以下の2つが優先的に対処すべき課題でした.

  • 検索メニューの応答性能が10秒以上になることが多々ある.
  • お申し込みメニューの平均応答時間が遅い.

サイト全体のプログラムを分析するのはそれはそれで時間と手間がかかりますが,ある程度絞って注力することで,深い診断と分析が可能となり,結果としてスピーディに成果を得ることができます.

お客様と相談し,改めて今回の課題に対する目標は,

  • 検索メニューの応答性能が悪化する原因を特定し,対策案を検討し,提案する.目標は平均処理時間30%短縮.
  • お申し込みメニューの平均応答時間を20%短縮.

となりました.

■処理内容の詳細分析

本番サービス環境で実際に稼動しているアプリーケーションの稼動状況を映し出すことにより,様々なことがわかってきます.

まずは,「検索メニュー」の方のリクエスト状況の分析です.特に,平均応答時間だけで見ているとスパイクして遅い応答リクエストが見えにくくなります.つまり,リクエスト回数が多いサイトでは,リクエスト数である分母が非常に大きいため,平均することで,時々発生している遅いリクエストが見えなくなってしまいます.性能診断分析チームが分析する際には,「平均値とは丸められた値である」ということを強く意識し,その計測区間の最大値(その計測区間内で一番遅かったリクエスト応答時間)も一緒にプロットするようにします(下図).こうすることで,実態が見えてきます.実際には10秒以上の応答時間だったリクエストは多発していることがハッキリしました.

 

更に,一回の検索リクエストの処理内容の内訳を以下の様に横軸が時間の図化することで,どのような処理に時間がかかっているのかが分かります.

この見える化は強力です.ここの事例とは別のお客様の例では,Webの1ページの画面を処理するために,アプリケーションから同等SQLが300回実行されている実態がこの図化によって明らかになったこともありました.一回のSQLが50ミリ秒だとしても,300回×50ミリ秒で15000ミリ秒,つまり,15秒です.しかも,よくよく分析してみると実は,1回のSQLで十分だったいうことがありました.既存のDAOコンポーネントを部品化した開発を行い,ループ中からDAOを呼出す作りだったのです.SQLは”表”で結果が取れるにもかかわらず...インフラ側のDB管理者は遅いSQLはチェックしていることが多いですが,流石に1アクセスの処理で大量にSQLを発行しているのか,複数リクエストにより1発づつ発行されているかは意識していません.

さて,話を戻します.図中のsearch()が横に細い時は全く問題ありません.しかし,横に長くなるケース,要は,処理時間が延びてくる現象が確認されました.塵も積もれば山となります.図から推察するに,search()はループ中で必要な処理回数呼ばれる様です.図では80回前後呼び出されている絵です.search()メソッドが10ミリ秒なのか20ミリ秒なのかは,高々10ミリ秒の差ですが,比率では2倍の差になります.つまり,大量に発行されている場合は,全体が3秒だった処理が2倍の6秒になる訳です.しかもその呼出回数が多数であるならば,さらに時間がかかります.遅くなっている原因は,カットオーバー後,取り扱いデータ量が増え,search()メソッドが順次遅くなってきているためでした.開発側と相談し,該当ソース箇所をレビューした結果「四重ループ」が確認されました.

 

■多重ループに注意

プログラムでループ処理を書くことは簡単です.もちろん,ループ処理の中でループを書くこともできます.更に,一番内側の処理で別のメソッドを呼出し,呼出したメソッドの中で別のループを実装する.簡略化すると以下の様なコードでした.

※実際のコードはもちろん,もっと処理内容があります.

このsomeMethod()メソッドのコードは四重ループです.二重ループの内側で二重ループを持つメソッドを呼び出しているのです.性能的に危険なループです.経験豊富なプログラムならば臭うことでしょう.

上の簡略ソースの変数outer,innerのいずれも10ならば1ミリ秒以下.あっという間です.

outer,innerいずれも100として,私の作業PC上でsomeMethod()メソッドの応答時間は50ミリ秒程度でした.これも問題ないです.

outer=100,inner=1000ならば,6秒程度.ちょっと遅い.

outer,innerいずれも1000になれば,10分は返ってきません.しかも,その間ハードウェア的に1コアはCPU100%になります.

そもそも変数outerやinnerが10000になる可能性があるならば,設計段階で実現不能なロジックとして除外しなければなりません.ブラウザーで検索ボタンを押してから,10分待っている利用者はいないでしょうから,outer/innerが1000でもWebアプリケーションとしては既に現実的とは云えないでしょう.

少し脱線しますが,forループやwhileループとして見えないループもあります.再帰呼出です.再帰呼出で有名なフィボナッチ数列を例にします.

フィボナッチ数列のJavaプログラムは,以下の様な再帰呼出が典型的な実装コードです.

さて,質問です.Nがいくつぐらいまでが現実的でしょうか?最近の高速なCPUを搭載したマシンでもN=50でfibonacci()関数は現実的な時間で終了しません.高々N=50です.forループは1個しか見えないのに.

話しを戻します.多重ループは指数的に処理時間が延びることを理解しなければなりません.事例では,四重ループの内側の処理効率を見直して改善することで劇的に応答時間が改善しました.

■チューニングの鉄則

プログラムをチューニングする際の鉄則は,チューニング効果の高い箇所から手を入れる,ことです.例えば,全体が10秒のリクエストであれば,その処理時間の内訳が大きい箇所をチューニングするのが効果を得やすい訳です.元々1秒しかかかっていないメソッドを一生懸命チューニングして処理時間を半分にしても,0.5秒しか短縮できませんが,元々8秒かかっている場所を半分にできれば,4秒の短縮なのです.

性能診断分析サービスの性能向上を目的とした現場の場合は,「もっとも少ない工数で,もっとも高い効果」が得られる対策案を提案しなければなりません.そのためには,どうしても本番サービス環境でアプリケーションの挙動を数値で計測する必要があったのです.

 

■もうひとつの課題

「お申込みメニューの20%短縮」の方です.Webサイトの場合,検索して,購入する,又は,申し込みをする,ことが一般的です.利用者に検索してもらうのは,次のアクションとして購入や申し込みをしてもらうためです.一般にWebサイトの最重要機能は「申し込み」と云っても過言ではないでしょう.注文も申し込みの一種です.最近だと「申し込み」の後に「共有」することも大切な機能になってきているようです.つまり,SNSなどに購入した事をツブヤき,お友達と買った事実を共有するという機能です.このサイトは共有はありませんでしたが,「申し込み」機能は重要な機能でした.直接,売上に影響するトランザクションです.この画面遷移を詳細にモニターしました.

申し込みの一連のリクエストの前後で大量のXMLファイルのI/OとXMLパース処理が見つかりました.開発会社様に確認すると,マーケティングデータの収集のための処理でした.それにしても,ファイルから都度読みだしているし,しかも,XMLパースを毎度行っています.その後,更にバックエンドにXML電文を作成し,http通信でそのXMLを数回投げています.応答もXML形式で返ってきて,その返信をパースして解釈後,ログ記録用XMLを作成してログ出力していました.

ディスクからの読みだしはOSキャッシュに載れば性能はある程度確保できますが,ディスクへの出力は極力避けたい訳です.詳しく出力ファイルの場所を確認すると,悪い事に,NFS上への出力でした.高負荷でないWebサイトなら特に問題ではありません.しかし,高負荷サイトの場合は気にしなければなりません.複数台のWEBアプリケーションサーバが水平分散できないからです.また,NFSサーバの障害で,全てのWEBアプリケーションサーバに影響をおよぶことも問題なのです.言い換えれば,ビジネスの停止になってしまうリスクがあるからです.

以下に挙げる2つの主な対策案を提示しました.

1)WEBアプリのファイル出力はローカルファイルへ.

開発会社とインフラ会社が別々だと,インフラ会社さんの運用の手間が楽な方の設定にされてしまうことがあります.設定ファイルの変更で入力パスを変更可能な場合,多くの場合は,一か所の変更で反映できる,という理由からNFS上に置かれる事が多々あります.性能的な観点は全く考慮されません.入力ファイルはNFS上に置き,出力ファイルはローカルディスクに設定変更を提案しました.

2)キャッシュの利用

バックエンドに数回投げているXMLのうち,数回は履歴を紹介する電文でした.これは「履歴」ですから,過去の記録です.後から追加はありますが,変更される内容ではありません.従って,キャッシュが効果的に機能します.memcacheやredisなどのKVSを利用し,オブジェクトをキャッシュする仕組みをご提案しました.キャッシュ機能は機能的には単純です.後から機能を追加することは比較的容易です.効果は非常に高いです.

■目標達成.更にもっと.

ご提案した内容を対策後,後日,本番環境で効果測定を行いました.2つの課題箇所の両方とも目標を達成していました.お客様も喜んでいました.喜んでいるのも束の間,応答時間が速くなることを知ってしまったため欲が出たのでしょう.「更にもっと速くしたいのですが,どうすればよいでしょうか?」と相談を受けました.文章が長くなってしまったので,今回はここまでとします.次回は高負荷,高性能を実現するためのサーバ側の対策案についていくつかご紹介していきたいと思います.

性能診断分析サービス事例 その2

シーマークすずきです.

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

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

■CPU稼働率が100%に暴走

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

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

 

■問題事象の定義

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

今回の問題事象は,

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

ということ.

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

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

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

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

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

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

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

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

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

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

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

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

■再現しないのはなぜ?

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

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

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

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

■無事TVCM放映

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

 

性能分析診断サービス事例 その1

シーマークすずきです.

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

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

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

■頻繁に症状発生

数日後,上流システム側の管理者から,「一日に何度も,大量にタイムアウトが発生して正常にサービス提供できない」という通達(苦情?)がお客様のサービス担当者にありました. この段階で,お客様の経営層も事態を知りしました. いきなりの事業リスクです. 一刻も早く対応し,元の健康なシステムの状態に戻す必要があります. お客様側の事業責任者は,サービス担当者と協議しましたが,原因が分かりません. 事業収支的には利益も成長も見込める状況だったようで,「取り合えず,ハードを増強しよう」となり,DB機はCPU稼働率30%程度で問題なさそうと考え,アプリサーバ機を現状の2台から4台追加し,計6台にする対策を講じた.

しかし,症状は改善しなかった. 実際には,問題事象の発生頻度が増し,全体としては,症状は更に悪化した.

■性能診断サービス:計測アプローチ

このような状態の中,私たちが呼ばれました. まず,問題事象を確認するために,アプリケーションのモニタリングをスピーディに実施しました. これにより,アプリケーションの応答回数,応答時間,リクエスト分布やマシンのリソース状況を可視化します. 他にも例えば,個々のSQLの発行タイミング,回数及びSQLの応答時間も同時に記録されます. 平行して,診断対象の環境やアプリケーションについてシステム担当者にヒアリング(問診)を行いました. 初回モニターとヒアリングにより,以下の状況が分かってきました.

  • 問題事象は,上流システム側でタイムアウトを引き起すこと.
  • 上流システム側は,応答が30秒を超えると,タイムアウトし,再接続を試みる動きになっている.
  • 通常の応答は平均1秒程度で応答していること.
  • 性能障害発生前からアプリケーションプログラムは一切変更していない.
  • アプリケーションサーバ機を2台から6台に増強したら,更に症状が悪化した.
  • Javaアプリケーションサーバ上で動作し,メインは3つのServletで対応している.
  • 携帯端末毎にセッションを発行するアプリケーションである.
  • DBへのアクセス(SQL)は非常に速い.
  • JVMのヒープは比較的大きなサイズを割り当てていた.
  • マシンのリソース監視は,ロードアベレージを5分毎に記録している.

しばらく,モニターしている間に何度か問題事象を観測しました. それで以下の状況がハッキリしました.

  • 問題事象の発生は,一定時間間隔や定期的ではない.
  • 問題事象が発生している間はCPU稼働率が100%に張り付く.
  • 問題事象が発生している時間はいつも28秒間程度
  • 問題事象後はJavaの使用ヒープ量が減る.

短時間のCPU稼働率の急上昇と急降下をグラフ表示したときの絵柄から「スパイクする」と私たちは呼んでいます.まさに,CPU稼働率はスパイクし,その後,Javaの使用ヒープサイズが”ガクン”と落ちているグラフを見れば,一目瞭然です.この観測結果から,タイムアウトを引き起こす直接的な原因はJavaVMのガベージコレクター(以下GC)であることが明確になったのです. 典型的なFullGC問題です. この原因到達まではに要した時間は,モニター開始から数時間でした.なぜ,通常のマシン監視では観測できなかったのでしょうか.それは,「5分毎のロードアベレージの監視」では観測間隔が粗いのとロードアベレージ値自身が平均値のためなのです.短時間のマシンの挙動の変化,つまり,「スパイク」した様子は記録できないからなのです.我々の計測方法は,通常,5~10秒間隔で細密にCPU稼働率やその他計測値を記録をします.従って,様々なメトリック(計測項目の値)のスパイクした状況を見逃しません.

しかし,なぜ突然FullGCによる影響が発生したのでしょうか?また,一体どのように対処すればよいのでしょうか?

■対策案の検討

直接的な原因が分かれば,対策はほぼほぼ見えてきます. これは,病名がハッキリすれば,治療法がある程度決まってくるのと似ています. 今回のFullGC問題の場合,要するに,FullGCを発生させないようにするか,又は,FullGC時間を短く抑えればよいのです. 最適な対処策を選択するためには,もう少し問題事象の発生経緯について詳しく分析する必要があります.FullGCを誘発しているのは誰か?正に犯人を知りたいところです.

つまり,

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

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

まず,仮説を立てます.このお客様のWEBサイトは,携帯端末毎に固有の応答を返します. そのため携帯端末毎に発行するHTTPSessionオブジェクトが臭い訳です. このオブジェクトはどれくらいのサイズなのか,また,一日のアクセス状況に対し,HTTPSessionオブジェクトのヒープ上の数はどのように推移しているのかをモニターしたいということをお客様にお伝えしたところ,その場で,新たな事実が発覚しました. 実は,セッションタイムアウト時間をこれまでの設定値より2倍に増やした,ということでした. 実は,アプリケーションのコード自体は一切変更していないことは確かに正しかったのですが,セッションタイムアウトの値がJavaVMのヒープにどのような影響を与えるかを深く検討せずに,気軽に別のサービス担当者が良かれと思って値を変更していたことが発覚したのです. 実際にHTTPSessionのモニターをしたところ,JavaVM上のセッションオブジェクトの数はもの凄い数になっていました.我々の仮説はビンゴでした.さすがに人気の携帯端末向けサービスです.想像以上に端末ユニーク数が大きいのです.一般にセッションオブジェクトは「ログアウトを押す」などの明示的な無効化がされるまで,通常設定したセッション時間分,ヒープに存在し続けます. 仮にセッションタイムアウト時間を2倍の生存時間にしたら,それらセッションオブジェクトが占める領域も当然必要になります.アクセス数やユニークユーザ数が少ないサイトであれば,その設定変更は全く問題なかったのでしょうが,大規模/高負荷サイトのシステムでは命取りになりえます.

 

■対策後の効果測定

セッションタイムアウト値を元に戻しました.その結果,セッションオブジェクトは順次回収され,ヒープを圧迫することはなくなりました.この状況を計測し確認したところ,今後の携帯端末の利用者の増加を見込み,更に,セッションタイムアウト値をアプリケーションの許容する最短値にすることを推奨しました.これにより,当案件の問題事象に対する原因究明作業,対策案の提示及び対策後の効果測定を終えました.お客様の安心した笑顔を見るのは大変嬉しいことです.

 

■残った疑問点に対する答え

この案件で,問題事象に対して解決することができましたが,1つ疑問が残ったままでした.

なぜ,アプリケーションサーバ機を2台から6台に増強したら問題事象が悪化したのか?

と云う疑問です.普通,アプリケーションサーバ機の台数を追加すれば,1台辺りの処理すべき担当リクエストが減るので,応答時間が改善され,システム全体では,スループットも向上するのが一般的です.今回の場合も3倍のスループットにスケールアップすることが期待されていました.しかし,この案件の場合は違いました.実は,このアプリケーションは,DBアクセスした結果得られた値を元に生成したデータをセッションオブジェクトに保管していたのです.アプリケーション独自のキャッシュ機構を持っていたのです.一方,お客様のインフラ担当者はその仕組みは知らずに,全てのリクエストをラウンドロビンでバランシング(均等化)する設定をしていました.アクセス都度,アプリケーションサーバ機を順繰りにバラつかせるために,このキャッシュ効果が逆に1/3に減ってしまったのです.これは2台時と6台時のアプリケーションの計測結果の数値グラフの比較分析により確認できました.DBへのSQL発行数は3倍に膨れ上がっていました.もともとDB機はCPU稼働率30%ぐらいだったのですが,アプリケーションサーバ増加のために,接続プール数も3倍になり,単純にDB負荷は3倍に増えました.CPU稼働率が90%を超える状況になっていたのです.疑問に対し,解せました.

 

■事例その1のまとめ

この事例では,本番アプリケーションの振舞いを数値で観測し,アプリケーションの特性をきちんと理解し,アプリケーションの設定内容を熟慮するための材料を導き出すことができました.お客様自身も知らなかったアプリケーションの挙動を数値とグラフで可視化することができました.その結果,問題事象の原因と対策に対する効果測定も行い,システムの安定稼働に寄与することができました.また,我々のレポート結果をお客様にご報告後,お客様のインフラ担当者の方も,stickyなバランシングに変更し直したことで,マシン増強による投資対効果を確実に得ることができました.