webアプリケーションの高負荷原因調査の手順を自分なりにまとめてみた(3層アーキテクチャの場合)
はじめに
「レスポンスが遅い」という問い合わせに幾度か出くわしたものの、実対応は したことがほぼなく、先輩の対応を横目で見ていたもののいざ自分でうまく対処が できるかというとできない状態だったので整理してみました。
ざっくりとした手順が自分の中に確立できていれば、いざ実対応となったときに 対応できるはず！
原因調査手順
基本方針は「マクロからミクロへ」。
闇雲に過去の自分が目の当たりにした負荷原因をもとに五月雨にログをあたる...というのは妙に時間が食うだけになってしまいます。
なので、大雑把な原因箇所の特定から始まって、徐々に調査範囲を狭めていくように徹底することが必要になると思います。
今回は自身が慣れ親しんでいる、javaアプリケーション/3層アーキテクチャを想定して手順を記載していきます。
それでは始めます！
1. 外部起因か、アプリ起因かを確認する
- 必要なもの(見るもの) : webサーバのアクセスログ
クライアントからリクエストがあって、クライアントに戻るまでのシーケンス図は下のようになります。「マクロからミクロへ」ということで、まずはサーバ起因か、クライアントとサーバの間のNWの遅延起因かを確認します。下図の赤矢印部分が長いか、短いかを確認することになります。 直接NWのが重いかどうかはクライアントのNW環境に依存するのでわかりません。ですが、アプリケーションの応答時間が短いか長いかはアクセスログから確認することができます。 応答が長ければアプリケーションが悪さをしていることがほぼ確定です。原因調査を進めましょう。反対に短ければアプリのせいではなく、クライアントからサーバまでのNWのせいなことが濃厚になります。
apacheの場合、デフォルトだとたしかaccess_logという名前でアクセスログがあるので、ログの中の応答時間の箇所をみつけ3~10秒ほどかかってるところを抽出するようにします。(私の場合less access_log | grep -v [画像読み込みなどいらないログはひっかからないように] | awk '$6 > 3 {print}'とかそんなんでやっています)
2. どのアーキテクチャが重いのか(次の手順への判断材料集め)
1.でアプリ起因が確定したら、今度はどのアーキテクチャが重たそうなのかをざっくり見つけます。下図の赤矢印部分を各アーキテクチャのログから読み取ります。
具体的には、一番左のwebサーバのアクセスログから応答時間が一番最初に重たくなった時間を見つけ出し、一番右にあるDBのスロークエリログから同じ時間帯でスロークエリが投げられていないかを確認します。
あればログにそのSQL処理にかかった時間が記載されているのでそれを読み、明らかに時間がかかっている場合はそのSQLの処理が重たい原因の可能性が高くなります。逆にそうでなければ、DBサーバの処理が原因ではなく、web appサーバが原因か、webサーバが原因の可能性が高くなります。 DBサーバの処理が原因出ない場合は同じようにwebサーバとweb appサーバのログを見ていきます。
この図だと、赤い矢印が長いのがweb appサーバのため、プログラムのどこかが悪さをしているんだなーとなります。
3. どのリクエスト(処理)が重たかったのか
2.の工程でどこの処理が原因かがわかったと思うので、それがじゃあプログラムのどの処理に起因するのか、を特定する作業に入ります。この作業のキモはやはりアプリの仕様理解(クライアントに返すデータを作るためにどの処理をして、どのデータをDBからとっているのか)が必要になります。スロークエリで重たいSQL文が出力されていて、それがどの処理で呼び出されるSQLなのかというアタリはアプリの仕様理解にかかっているのではと思います。 また、スロークエリが原因でない場合はアプリの実装が悪いのかどうかはもちろんプログラムを見ないとわかりません。 自分で究明するか、チーム開発であれば仕様をしっている人に聞くということになると思います。
その処理を行うとサーバにどのような負荷が起こるのか
- 必要なもの(見るもの) : topログ, vmstatログ, jstatログ(javaの場合)など
応答時間の重さから重くなった箇所は上までで把握できますが、その処理によってサーバのリソースがどうなるから重くなるのかはサーバの監視ログから見る必要があります。 linuxのリソース監視に関してはどのようにやるのかはメモ程度ですが以下に書きました。
まとめ
ここまでの調査でどの処理でサーバリソースのどこがネックになって処理遅延が発生しているかがだいたい分かると思います。 「マクロからミクロへ」を念頭に効率よく調査する一歩として上記を念頭に入れて、いざというときに調査できるようにしたいと思います。
【メモ】vmstatの読み方、負荷状況を読み解く復習【初心者】
業務で負荷テストの検証結果まとめ資料の作成作業を依頼されたものの、サーバ負荷状況に関しての知識が曖昧だったばかりに
久しぶりにvmstatの出力を見てちんぷんかんぷんになってしまっていたのでvmstatの復習と本日見た負荷テスト結果の照らし合わせの復習。
これを読んだら、ざっくりCPU-DISKI/Oどっちがボトルネックで遅くなっているかがパッと理解できるようになる。
今回メモリは私がまだ理解していないので...割愛する。
以下からvmstat実行例を拝借。
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 92 6608 6796 192804 0 0 126 23 548 569 9 1 89 2 0 0 0 92 5764 6828 192836 0 0 0 8 1090 1576 2 0 98 0 0
それぞれの意味は上の記事に書いてあるので割愛するとして、私がいつまでも読めない問題は「正常値がわからないから異常値かわからない」ってところだと感じる。
今日の業務で先輩方の読み方の流れはおおまかに言えば「異常かどうかすぐにわかる→正常が覚えやすい箇所から攻めていく」というのをしてらしたので、おそらくこの流れで読んでいくと素早くサーバ状況がわかるのだと思う。
- プロセスの待ち時間/DiskI/O待ちプロセスがあるかどうか
- CPUの使用量割合(ユーザus/システムsy/空きid/I/O待ちwa)
- ディスクI/Oが異常に増えていないか(0近くから数万に変化)
1.は一番左のproc。平常時は0(=待ちプロセスがない→プロセスを瞬時に捌ききれている)になることと、一番左にあるのですぐに把握ができる。
- は逆に一番右のcpu。平常時はidは80~90と高め(=忙しくないので暇(idle)している)、その他は10未満のことが多いはず。 これも真ん中とかでなく、一番右だからすぐに把握しやすい。(空き(id)だけはひとまず覚えていたらなんとかあとはググれば解にたどり着けるだろう)
最後3.は真ん中あたりにあるのでどこがディスクから受け取っているデータ量bi、ディスクに書きこんだデータ量bo。これは上に比べれば正常時が分かりづらいが、負荷が起きているであろう時間の前後をざっと見渡すと急に値が大きくなるのでぱっとわかりやすい。
この3つをまず押さえれば、数分、早くなれば数秒で状況がわかるようになる。
メモリに関しては...まとめきれていないので割愛とする。
まずは上を数秒でぱっとわかるように明日も読んでいく。
