■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放映開始日を迎えることができて，本当に嬉しそうでした．原因は本当に些細なことでした．しかし，その些細な原因がはっきりしないと，とてつもない恐怖に感じたとサービス責任者が笑顔で御礼の言葉を私達に伝えてくれました．

Seamark Engineers' Blog

タグ: 診断

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