Webサービスエンジニアが教えるサーバサイドのログ分析　情報を可視化して負荷状況を見よ

サーバ情報を可視化して負荷状況を見る

続いて、サーバの負荷状況を見るところですね。リソースの情報をコマンドで取得してサーバ情報を可視化しましょうというところです。

よく使うのは、1つ目はhtopですね。htopでプロセスごとにどれくらいのメモリやCPUを使っているかを取っていくのがあります。リクエストが多いときにこれを取っていって、どこが重たくなっているかを見るというのがいいかなと思っています。

例えばアプリケーションサーバと同梱されているものだったりとかすると、アプリケーションサーバの負荷がいきなり高くなっていたりとかということがわかるかもしれないです。

続いてdstatですね。htopだけだとわかりにくい情報もあるので、それをdstatを使って取っていきましょう。この場合だと例えばディスクのread/writeを見たりとかですね。

ディスクのread/writeを見ると、例えばioがやたら多いものだと、このディスクのread/writeが増えていくので、ioに起因する部分の処理がなにかしら問題があるんじゃないかがわかったりします。

もちろんdstatとかhtopとかは一例なので、topやvmstatとか、普段使っているもので取ってもまったく問題ありません。あとはMackerelとかDatadogとか、メトリックを取るツールというのも対応できます。

ただ、dstatの場合だと1秒ごとに取れたりとかするんですけれども、Mackerel、Datadogとかだと取るタイミングが、例えば最短で1分単位とか、取得間隔があります。その取得間隔を意識して使う必要があるかなと思ってます。

あともう1つの注意点が、いろんな情報を取りたいがために、多数のコマンドを並列実行すると、コマンド自体が負荷を生む原因になります。やたらvmstatとかdstatとかいろんなオプションを付けて裏で流すのはやめたほうがいいと思います。

サーバの負荷状況を組み合わせて考える

サーバの負荷情報と状況を組み合わせて考えてみます。先ほどLTSVとalpを使ったものの話をしました。例えばdstat -taの結果から特定のタイミングでdisk readが高くなっている場合があったときには、dstat -ta --top-ioでioが最も高いプロセス情報を確認できます。

そのときにNginxが表示されてたら、Nginxの処理でなにかしら時間がかかっていることになります。じゃあNginxのほうで調べてみようってなると、先ほどのLTSV＋alpで復元したもののうち、処理がかかっているリクエストですね。

これがディスクioの処理速度に影響している可能性があるとなった場合、ディスクioがいきなり頻繁的に使われるもの、例えばやたらローカルのファイルを参照していたり。キャッシュが消えてなかったりとかがあると思います。そういったもののアプリケーション側の内部処理を確認して、そこをチューニングしていくことが必要になるのかなと思っています。

そこに改修を加えたあと、また同じ方法で再度計測して、そのボトルネックになっている部分が改善されたときには、それはアプリケーションチューニングが適切に実施されたと言えるかなと思っています。もちろんレスポンスがちゃんと返せていることが前提としてですね。

アプリケーションとデータベースのログを確認

あとはアプリケーションとデータベースのログを確認する。まずアプリケーションサーバ側からクエリが流れるデータベース側を確認しなければいけないんですけれども、クエリの実行回数と頻度を確認しましょうということです。

MySQLの場合は類に漏れず、スロークエリを取っていきます。スロークエリの場合にはlong_query_timeの値を、例えば3にすると3秒以上かかったもの、2にすると2秒以上とできますけれども。0にするとすべてを記録することが可能になります。

いきなりSQLのmy.cnfを書いて、mysqld再起動なんてできない場合もあると思うので、そのときにはMySQLのコンソールからset globalで渡してあげると、スロークエリのログが吐き出されます。

あとポスグレの場合は、log_min_duration_statementとか、Oracleの場合はv$SQLを見たりすることで、処理時間の遅いSQLをソート表示可能になるかなと思っています。

取ったスロークエリのログですね。これはMySQLの場合ですけれども、mysqldumpslowで統計を取ることができます。これで遅いものを引っ張って確認できます。

long_query_timeを0にすると、すべてのクエリログが表示されます。その場合1回の処理時間は短いんですけれども、回数が多いクエリとかがあった場合には、それをキャッシュさせる方法も検討できるかなぁと思っています。積み重ねで遅くなったりとかもするので、そういうときには使えるかなと思います。

レスポンスタイムが悪いクエリから順番に対策を

クエリの傾向と処理時間から改善対象を絞る部分ですが、先ほどのスロークエリのログをコマンドで、mysqldumpslowで確認した結果からレスポンスタイムが悪いクエリを順番に対策を行っていきましょうと。

アプリケーションのSQLを確認しますとか。SQLが悪かったらそのまま遅くなるよねとか。あとMySQLの実行計画を確認します。これで、どれくらいMySQLにクエリが流れて、そのあとにどういうプロセスを経て実際にクエリが消化されるのかまで見ることができます。

あとはレスポンスは悪くないですけども、回数が多いクエリの対策をしていきましょうということですね。アプリケーションそもそものデータの参照回数を減らしましょうとか。キャッシュを活用してMySQLへのクエリ回数を抑えるということですね。

インメモリデータベースを使えば圧倒的にioは速くなるし、SQLに直接参照するよりもはやくなるのでそういったものを活用していきましょう。繰り返しですけども、long_query_time = 0を使うと、レスポンスは悪くないですけれども、回数が多いクエリの対策を行うことができます。

一応簡単なところですと、以上になります。もっと情報の取り方はいろいろあると思うんですけれども。みなさんそれぞれ、調査の仕方は人それぞれやり方があると思うので、こういうかたちで分析したほうがいいよというのがあれば、ツイートしてぜひ教えてもらえると助かります。

全プログラマーが知るべきレイテンシー

おまけです。これも有名なもので、全プログラマーが知るべきレイテンシーです。例えばパケットのラウンドトリップが一番時間がかかりますよというのがあります。あとディスクシークは10ミリセックかかりますよとか。

どこにどれくらいボトルネックがあって、改善するとどういうレイテンシーを削減できるのかを見極めてパフォーマンスチューニングをしていかないと、レイテンシーが短いところをやたらめったらパフォーマンスチューニングしても効果は低いです。適切に効果が出るところをちゃんとチューニングしていきましょう。それを意識して、ログとかを参照するのが重要かなと思っています。

繰り返しですけれども、計測を行ってパフォーマンスが出ない原因を特定して、改善を適応して計測して、再度改善効果を確認する。これを繰り返すことがパフォーマンスチューニングだと思っています。そのために使えるログがいろいろあるので、みなさんも試してもらえればと思います。

最後まとめです。Web 3Tierアーキテクチャのサービスにおいてのパフォーマンスチューニングに必要なログと捉え方を説明しました。

業務だとAmazon X-RayとかNewRelicとかAPM、Application Performance Monitoringのツールを使うことも一般的かもしれません。こういったものを使うとより深くどこにボトルネックがあるのかっていうのを見ることができます。

あとはレイテンシーが大きい箇所から現状を調査して改善を加えることで効率的になるかなというところです。

大事なところなんですけれども、調査で使ったコマンドとか手順というのはけっこう忘れがちなので、どこかにメモっておいて必要なときにすぐ実行できるように準備しておくといいかなと思ってます。

なかなか調査を日常で多用することっていうのはあんまりなくて、なにか問題があったときに行うことが多いので、ちゃんと記録しておくことが必要なのかなと思っています。私からの話は以上になります。ありがとうございました。