こうしてシステムのボトルネック問題を解決した　～NW、HW、MWとアプリの切り分け～

はじめに

私はあるお客様のWebアプリケーション(SSOの認証システム等)の保守を担当しています。
ここ数年このシステムは安定稼働をしており、今までトラブルらしいトラブルは発生していませんでした。
しかしシステムリリースから5年近く経過し、次期システム更新の話が出始めた頃、突然今回のトラブルが発生しました。
全く予想していなかった所にトラブルの原因がありこの原因を除去したところ、今度は、今まで隠れていた別の問題が表面化しました。
この時の問題解決に至るまでの経緯・経験をこの場にて共有することにより、私と同じような立場の方々が問題に直面した時に、解決に向けたヒントとなれば幸いです。

不具合(その1)と顛末

既述のように、このシステムでは過去5年間にわたり大きな問題は発生していませんでした。
ある時、新規アプリケーションがこの認証システムを利用することになりました。
日中時間帯に従来通り順調に稼働していましたが、利用者が多くなる月末と月初の朝晩に、約1時間ほど認証処理の遅延が発生するようになりました。しかも、一定の割合で時間切れとなり認証処理自体ができないアクセスが多発しました。
すると、その先のアプリケーションを使えないために出勤/退勤時刻の登録ができません。 当然、利用者からの問い合わせが殺到しました。

最初は、単にサーバのリソース不足が原因と思っていました。しかし、以下のようにリソース系が原因ではありませんでした。

• SSOサーバ、アプリケーションサーバなど関係するサーバのCPU、メモリ等のリソースを確認しましたが、かなり余裕があり全く問題ありません。
• アクセス経路中のNW系機器（FW、SW、LB等)の処理能力不足を疑い、アクセス数を確認しました。しかし、機器の最大処理数に対しては十分な余裕がありました。

本システムに関係するメンバー5、6人が原因究明に努めました。しかし、本番環境を運用しながらの調査である上に以後の再発も無いので、原因不明のまま月末を迎えました。
この時も同様な遅延が発生しました。この時、メンバーの1人がFWに対するpingコマンドの応答が無いことに気づきました。

ここが怪しいとのことで、翌月末の不具合発生予想日にパケットキャプチャを用意した上で、FWへのアクセス数を計測しました。
すると結果的にFWの性能劣化が原因であることが判明しました。
アクセスが多くなると正常にログすら書き出せないほどの半ば故障状態だったようです。
これではFWのログを見ても分からないはずです。

ちょうどNW系機器の交換時期だったため、10倍以上高性能な機器に交換することで不具合は解消しました。
これで問題解決と思っていたら、後日別の不具合に見舞われました。

不具合(その2)と顛末

その後の数ヶ月は問題無く安定稼働していました。
しかし、ある日突然に今度は平日の日中時間帯に似たような認証遅延現象が発生しました。なぜか24時間経過すると自然に解消しました。

NW機器系は交換したばかりだし、関係各サーバ系のリソースも問題ありません。前回の担当メンバーが再度調査に当たり、以下のことが分かりました。

• SSOサーバ上のTomcat処理時間が長くなると遅延が発生する。
• ApacheとTomcatのサービスを再起動すると遅延は解消する。
• SSOサーバに関係するミドルウェアのログを調査しても問題点は見つからない。
• 一部Apacheのスレッド数が上限に達することを確認した。パラメータを変更したが、効果は無かった。

更に調査を続けたところ、SSOサーバの参照先であるADサーバからの応答時間が長く（数10秒）かかるケースが見つかりました。
このためADサーバ側に問題があると考えましたが、後日この応答時間は認証遅延とは関係無いことが判明しました。
このようにトライ＆エラーで可能性がある部分を徹底的に調査しましたが、原因にはたどりつけませんでした。

程無く類似システムの開発経験があるメンバーが調査チームに加わりました。
本システムの構築には関係していないので、先入観無しであらゆる角度からの調査を開始しました。
先ずはシステム構築以降見直しが無かったアプリケーション側のパラメータ一式とシステムの挙動を確認しました。
すると数日でJavaのヒープメモリ不足が原因らしいと気づきました。

Javaのメモリを構築当時の2GBから、4GB、6GBと順位増加することで問題は解消しました。

教訓(次の問題発生に備えて）

最後までお読みいただき、ありがとうございました。