Webサービスのパフォーマンスと ログ分析(入門編) ログ分析勉強会 オンライン

自己紹介 氏名：山口 正徳(@kinunori) - AWS資格をいくつか - PMP、認定スクラムマスター - CISSP 2019 APN AWS Top Engineers 昔ログ分析ツールの製品担当など やってました 現在はAWS上で構成された Webサービスの開発・構築を行っています

■話すこと ・Webサービスのパフォーマンスチューニングの為に必要と考えるログと その分析 ■話さないこと ・Webサービスのパフォーマンスチューニング方法 ※ここで表現するログとはシステムの動作を記録する情報として、 デバッグツールの情報、継続するコマンドの実行結果も含みます

http://isucon.net/ ISUCON公式サイト Webサービスのパフォーマンスチューニングといえば

日々の業務やISUCON7〜9で実践したことをまとめて、 “Webサービスのパフォーマンスチューニングを行う為に 必要と考えるログとその分析方法” として、話させていただきます。

本資料に記載されている内容は 負荷を上げる原因になる可能性があるため テスト環境で確認することを推奨します。 いきなり本番環境で実行はやめましょう。 注意事項

一定の条件(※)を満たした上で、 処理できるHTTPリクエスト数を多くする。 一定の条件(※)を満たした上で HTTPレスポンスを返す速度を短くする。 パフォーマンスチューニングの定義 ※ 一定の条件： 画像は今以上の最適化・サイズ縮小は認められない、 HTML、CSSなどは書き換えられない、 レスポンスまでの時間が定められている など

「推測するな 計測せよ」 ルール1: プログラムがどこで時間を消費することになるか知ることはできない。 ボトルネックは驚くべき箇所で起こるものである。したがって、どこがボトル ネックなのかをはっきりさせるまでは、推測を行ったり、スピードハックをし てはならない。 ルール2: 計測すべし。計測するまでは速度のための調整をしてはならない。 コードの一部が残りを圧倒しないのであれば、なおさらである。 出典：Wikipedia - Unix哲学 https://ja.wikipedia.org/wiki/UNIX%E5%93%B2%E5%AD%A6

１．計測を行う ２．パフォーマンスが出ない原因を特定する ３．改善を適用する ４．計測にて改善効果を確認する を繰り返す。

１．計測を行う ２．パフォーマンスが出ない原因を特定する ３．改善を適用する ４．計測にて改善効果を確認する を繰り返す。 繰り返しとなりますが、 今回は↑の話をします。

対象とする構成イメージ Apache, Nginx, h2o など Node, Python, PHP, Java, Perl, Ruby など MySQL, PostgreSQL, SQL Server など (キャッシュやNoSQLもある) クライアント HTTP/ HTTPS

クライアントから見たログを確認する Apache, Nginx, h2o など Node, Python, PHP, Java, Perl, Ruby など MySQL, PostgreSQL, SQL Server など (キャッシュやNoSQLもある) クライアント HTTP/ HTTPS

Chrome DevTools HTTPステータス リクエストから 受信にかかった時間

Web、アプリケーションのログを確認する Apache, Nginx, h2o など Node, Python, PHP, Java, Perl, Ruby など MySQL, PostgreSQL, SQL Server など (キャッシュやNoSQLもある) クライアント HTTP/ HTTPS

Webサーバのログ 192.168.16.3 - - [27/Feb/2020:05:56:35 +0000] "GET / HTTP/1.1" 200 3441 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:73.0) Gecko/20100101 Firefox/73.0" "-” 192.168.16.3 - - [27/Feb/2020:05:56:47 +0000] "GET / HTTP/1.1" 304 0 "https://login.microsoftonline.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:73.0) Gecko/20100101 Firefox/73.0" "-" 192.168.16.5 - - [27/Feb/2020:05:58:17 +0000] "GET / HTTP/1.1" 200 3442 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.100 Safari/537.36" "-" Nginx(1.16.xx デフォルト)アクセスログ Apache(2.2.xx デフォルト)アクセスログ 192.168.1.5 - - [26/Apr/2020:08:27:54 +0000] "GET / HTTP/1.1" 304 - "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36" 192.168.1.5 - - [26/Apr/2020:08:28:07 +0000] "GET / HTTP/1.1" 304 - "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36"

Webサーバのログ 183.76.169.39 - - [26/Apr/2020:09:42:29 +0000] "GET /image.png HTTP/1.1" 200 127284 ”-” Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36" "-" どのクライアントから、いつ、何のメソッドで、どのコンテンツに対し、リクエストがあり、 処理をしたのかは分かるが、レスポンスまでにかかった処理時間が分からない。 log_formatに “$request_time” を追加することで処理時間を確認できる。 (Apacheの場合は、LogFormatに %D もしくは %Tを追加) http { log_format main '$remote_addr - $remote_user [$time_local] "$request" ' '$status $body_bytes_sent "$http_referer" ' '"$http_user_agent" "$request_time" "$http_x_forwarded_for"'; access_log /var/log/nginx/access.log main; nginx.conf Nginx(1.16.xx デフォルト)アクセスログ

Webサーバのログ 183.76.169.39 - - [26/Apr/2020:09:42:29 +0000] "GET /image.png HTTP/1.1" 200 127284 ”-” Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36" "0.131" "-" 赤字の部分が追加した “$request_time” で出力されたログ。 上記サンプルでは、該当リクエストの処理に対し、0.131 秒かかっていることが分かる。 “$request_time”を追加することでリクエストにかかっている時間はわかるものの、 ・分析するには parse に労力が必要(※) ・分析を行う際にフィールド追加の影響を受けやすい など、調査のための課題が残る。 ※ 独自カスタマイズしていなければ、fluentdなどで手間をかけずにparseすることは可能 Nginxアクセスログ

Webサーバのログ LTSV Labeled Tab Separated Values (LTSV) というのは、はてなで使っているログフォーマットのことで、 広く使われているTSV(Tab Separated Value)フォーマットにラベルを付けて扱い易くしたものです。 https://blog.stanaka.org/entry/2013/02/05/214833 引用元：stanaka‘s blog Labeled Tab Separated Values (LTSV) ノススメ 可読性は低いものの、値に名前がついていること、タブで列が区切られており、 かつ：（コロン）で名前と値が分けられているため、Parseしやすく集計などを取りやすい。 NginxのアクセスログをLTSVにした例 time:18/Sep/2016:11:52:52 +0900 host:192.168.50.11 forwardedfor:- req:GET /img/star.gif HTTP/1.1 status:200 method:GET uri:/img/star.gif size:93 referer:- ua:isu6q- benchmarker/1.0.0 reqtime:0.145 cache:- runtime:- apptime:0.132 vhost:172.30.20.4

Webサーバのログ nginx.conf http { log_format ltsv "time:$time_local" "¥thost:$remote_addr" "¥tforwardedfor:$http_x_forwarded_for" "¥treq:$request" "¥tstatus:$status" "¥tmethod:$request_method" "¥turi:$request_uri" "¥tsize:$body_bytes_sent" "¥treferer:$http_referer" "¥tua:$http_user_agent" "¥treqtime:$request_time" "¥tcache:$upstream_http_x_cache" "¥truntime:$upstream_http_x_runtime" "¥tapptime:$upstream_response_time" "¥tvhost:$host"; access_log /var/log/nginx/access.log main;

Webサーバのログ LTSV + alp で処理時間がかかっているリクエストを調べる Access Log Parser https://github.com/tkuchiki/alp ・css、jsなどの静的ファイルの配信は処理時間がかかっていない → ngxinでキャッシュしても効果は少なそう ・/icons、/channel配下へのアクセス処理に時間がかかっている → ここを改善することでパフォーマンス向上に繋げることができそう 基本は「レスポンス処理に時間がかかっているリクエスト x リクエスト回数」 で対象を決める。

htop サーバの負荷状況を見る リソース情報をコマンドにより取得し、サーバの負荷情報を確認する

サーバの負荷状況を見る リソース情報をコマンドにより取得し、サーバの負荷情報を確認する dstat -ta (--output オプションを使うことでCSV形式でログ出力が可能) ・top や vmstat など使いなれたものでも問題ない ・Mackerel、Datadogなどもツールでも対応可能だが、取得間隔を意識する必要あり ・いろいろな情報を取りたいが為に、多数のコマンドを並列実行すると、 コマンド自体が負荷を生む原因になるため注意が必要

サーバの負荷状況と組み合わせて考える 例えば、 ・dstat -ta の結果から特定タイミングで disk read が高くなっている 場合を想定。 1) dstat -ta --top-io でioが最も高いプロセス情報を確認する 2) nginxが表示された 3) LTSV + alp で確認した処理時間が掛かっているリクエストは ディスクioが処理速度に影響している可能性がある など、計測情報を組み合わせ、アプリケーションより該当箇所を調査し、 改修を加える。改修を加えた後、再度計測し、改善有無を確認する。

アプリケーション、DBのログを確認する Apache, Nginx, h2o など Node, Python, PHP, Java, Perl, Ruby など MySQL, PostgreSQL, SQL Server など (キャッシュやNoSQLもある) クライアント HTTP/ HTTPS

クエリの実行回数と頻度を確認する > set global slow_query_log = 1; > set global slow_query_time = 3; > set global slow_query_log_file = /tmp/mysql-slow.sql; MySQLの場合、my.cnfに以下の記載し、mysqldを再起動する [mysqld] slow_query_log=ON long_query_time = 0 ← スロークエリとして記録する秒数(0にすると全て出力) slow_query_log_file = /tmp/mysql-slow.sql 動的に変更したい場合、mysqlコンソールから postgreSQLの場合は” log_min_duration_statement” で実行時間とログ記録を行うこと、 Oracleの場合はv$SQLを参照し処理時間の遅いSQLをソート表示するのと同様 ※ long_query_time = 0 は、サーバ負荷がかかるので一時的な利用にした方が良い

クエリの実行回数と頻度を確認する shell> mysqldumpslow Reading mysql slow query log from /tmp/mysql-slow.sql Count: 103 Time=4.40s (445s) Lock=0.00s (0s) Rows=5.0 (465), myapp[myapp]@localhost SELECT * FROM users WHERE first_name like 'A%’ Count: 12 Time=3.76s (39s) Lock=0.00s (0s) Rows=0.4 (34), myapp[myapp]@localhost insert into t1 select * from t1 mysqldumpslowで統計を出力する long_query_time = 0 の場合、全てのクエリログが記録されるため、１回の実行時間は短いが 回数が多いクエリを特定し、キャッシュさせるなどの方法を検討することができる。

クエリの傾向と処理時間から改善対象を絞る slow queryログをもとに、 ・レスポンスタイムが悪いクエリから順番に対策を行う ・アプリケーションのSQLを確認する ・MySQLの実行計画を確認する ・レスポンスは悪くないが、回数が多いクエリの対策を行う(※) ・アプリケーションのデータ参照回数を減らす ・キャッシュを活用し、MySQLへのクエリ回数を抑える など、改善対象の絞り込みを行うことが可能。 ※ long_query_time = 0 の場合、全てのクエリログが記録されるため、１回の実行時間は短いが 回数が多いクエリを特定し、キャッシュさせるなどの方法を検討することができる。

おまけ Apache, Nginx, h2o など Node, Python, PHP, Java, Perl, Ruby など MySQL, PostgreSQL, SQL Server など (キャッシュやNoSQLもある) クライアント HTTP/ HTTPS

http://yuroyoro.net/latency.html 参考：Remix: Latency Numbers Every Programmer Should Know(2014) 全プログラマーが知るべきレイテンシー

１．計測を行う ２．パフォーマンスが出ない原因を特定する ３．改善を適用する ４．計測にて改善効果を確認する を繰り返す。

まとめ Web 3Tier アーキテクチャのサービスにおいて、 パフォーマンスチューニングに必要なログと捉え方を説明しました。 業務ではAmazon X-RayやNewRelicなどのAPMを軸に 調査をはじめることが一般的かも知れません。 ログをもとに、レイテンシが大きい箇所から現状を調査し、 改善を加えることで効率的なチューニングとなる可能性が高くなります。 調査で使ったコマンドや手順は記録しておき、 必要な時にすぐに実行できるように準備しておくことをお勧めします。 (日常で多用することも無いと思うもうので)