ALB のログで URL パスごとに分析したい
Web アプリケーションのパフォーマンス問題に遭遇することがあります。その際に、闇雲にパフォーマンスチューニング行うのは、あまり良い方法とは言えないです。お金でリソースを購入するスケールアウト/アップの対応は考えられますが、エンジニアとしてはお金以外の解決策も持っておきたいです。通常、まずはボトルネックを特定したうえで、その後の対策を行います。
ざっくりどこの URL パスにボトルネックがありそうかを把握したくなります。そこで、ALB のアクセスログを基に Athena を利用して検索することで、URL パスごとのレイテンシーやアクセス回数などを把握する方法を紹介します。
S3 バケットポリシー
ALB のアクセスログは、S3 に出力する機能があります。これを利用するため、S3 バケットポリシーを編集します。
東京リージョンの場合は、次のようなポリシーを入れます。ALB を動かしているリージョンごとに許可する Account ID が異なるので、こちらのドキュメントを基に指定します。
{
"Version": "2012-10-17",
"Statement": [
{
"Effect": "Allow",
"Principal": {
"AWS": "arn:aws:iam::582318560864:root"
},
"Action": "s3:PutObject",
"Resource": "arn:aws:s3:::alb-cognito-nginx01-logs/*"
}
]
}
ALB でログ設定
ALB 側でログを S3 に出力する設定をします。Attributes タブから Edit を押します。
Monitoring の欄で、出力先の S3 バケットを指定します。
S3 ログ確認
その後、ALB にアクセスすると、実際にログが出力されている様子が確認できます。
こんな感じで、リージョンや日付ごとにディレクトリが切られて、5 分ごと、ALB の Node ごとに gz ファイルが出力されています。
Athena のテーブル作成
Athena の操作方法は省略しますが、ALB のログ出力の形式に合わせた Table の Create 文が公式で提供されています。 これの Create 文を利用して、Athena 上で SQL クエリーを発行できるように準備を進めます。
Tips : 公式の Create 文ではパーティションが定義されておらず、大規模になってくると料金やパフォーマンス面で気になってきます。また、ALB は 5 分ごとに gz ファイルを出力するため、細かいファイルが多く出来上がります。大規模な環境では、パーティショニングや定期的に Parquet 形式にまとめる方法を検討してもいいかもしれません。
CREATE EXTERNAL TABLE IF NOT EXISTS alb_access_logs (
type string,
time string,
elb string,
client_ip string,
client_port int,
target_ip string,
target_port int,
request_processing_time double,
target_processing_time double,
response_processing_time double,
elb_status_code int,
target_status_code string,
received_bytes bigint,
sent_bytes bigint,
request_verb string,
request_url string,
request_proto string,
user_agent string,
ssl_cipher string,
ssl_protocol string,
target_group_arn string,
trace_id string,
domain_name string,
chosen_cert_arn string,
matched_rule_priority string,
request_creation_time string,
actions_executed string,
redirect_url string,
lambda_error_reason string,
target_port_list string,
target_status_code_list string,
classification string,
classification_reason string,
conn_trace_id string
)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
'serialization.format' = '1',
'input.regex' =
'([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*):([0-9]*) ([^ ]*)[:-]([0-9]*) ([-.0-9]*) ([-.0-9]*) ([-.0-9]*) (|[-0-9]*) (-|[-0-9]*) ([-0-9]*) ([-0-9]*) \"([^ ]*) (.*) (- |[^ ]*)\" \"([^\"]*)\" ([A-Z0-9-_]+) ([A-Za-z0-9.-]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^\"]*)\" ([-.0-9]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^ ]*)\" \"([^\\s]+?)\" \"([^\\s]+)\" \"([^ ]*)\" \"([^ ]*)\" ?([^ ]*)?'
)
LOCATION 's3://alb-cognito-nginx01-logs/accesslogs/'
ALB のログフォーマット
ALB が出力するログのフォーマットが、こちらの Document で整理されています。
重要な列をピックアップします。
- target_processing_time : ロードバランサーがターゲットにリクエストを送信した時点から、そのターゲットが応答ヘッダーの送信を開始した時点までの合計経過時間。つまり、EC2 などの Web アプリケーション側の処理にかかるレイテンシー。
- request : URI パスを含めたアクセス先の表示
上記の 2 列のデータをコアに分析することで、どの Path にどれくらいの時間がかかっていそうなのか、パフォーマンス概要を把握できます。特に遅い Path や、アクセス回数が多い Path を発見できたら、そこでより深くボトルネックを確認する動きに活かせます。
Athena でクエリーを行う
いくつか Athena で分析してみましょう。
- 直近 1 週間以内
- 最も Web アプリ側の処理時間 (target_processing_time) が長い URL Path を Top 10 まで表示
SELECT
time,
request_url,
request_processing_time,
target_processing_time,
response_processing_time,
elb_status_code,
client_ip
FROM alb_access_logs
WHERE target_processing_time > 0
AND time >= date_format(current_timestamp - interval '7' day, '%Y-%m-%dT%H:%i:%s.000Z')
ORDER BY target_processing_time DESC
LIMIT 10;
実行例
-
直近 1 週間以内
-
url_extract_path を利用して、URL パラメーターが付与されているものでも同じ Path をまとめる。以下のように同じ Path で異なる Parameter である場合でも、同じ Path として Group By を行い集計する。
- /sample?testkey1=testvalue1
- /sample?testkey2=testvalue2
- /sample?testkey3=testvalue3
-
最も Web アプリ側の処理時間 (target_processing_time) が長い順に Path を表示
-
アクセス数を表示
-
アクセス数と平均レイテンシーを掛け算を行い、処理に費やしている時間の合計を
SELECT
domain_name,
url_extract_path(request_url) as path,
COUNT(*) as access_count,
ROUND(AVG(target_processing_time), 3) as avg_target_processing_time,
MAX(target_processing_time) as max_target_processing_time,
MIN(target_processing_time) as min_target_processing_time,
ROUND(COUNT(*) * AVG(target_processing_time), 3) as total_processing_time
FROM alb_access_logs
WHERE target_processing_time > 0
AND time >= date_format(current_timestamp - interval '7' day, '%Y-%m-%dT%H:%i:%s.000Z')
AND domain_name = 'cognito-nginx01.sugiaws.tokyo'
GROUP BY
domain_name,
url_extract_path(request_url)
ORDER BY avg_target_processing_time DESC;
実行例
- アクセス元 IP の多い順
SELECT distinct client_ip, count() as count
FROM alb_access_logs
GROUP BY client_ip
ORDER BY count() DESC
その他 Tips
- S3 に格納される日付は、UTC 時間で格納がされているので、日本時間でフィルターをしたい場合は時差に気を付ける。
参考 URL
[初心者向け]Application Load Balancerのアクセスログを、Amazon Athenaで色々なクエリを実行し分析してみた
https://dev.classmethod.jp/articles/application-load-balancer-athena-202306/