AthenaとRedashで遅いAPIのレスポンスタイムを可視化する

可視化までの流れは以下の通りです。

・ALBのログ出力オプションをonとしS3に出力する
・ALBのログをAthenaから参照できるようにする
・Redashでクエリを作り、Refresh Scheduleを利用して日時で実行する
・Redashの出力結果をSlackに通知する (ことで可視化を加速する)

それぞれを解説していきます。
（なお、各登場人物についての細かな説明、インストールや導入方法については省略します）

構成

ALBのログ出力オプションをonとしS3に出力する

AWS公式に詳しく書かれているのでこちらをご参照ください。デフォルトはoffになっているのでonにする必要があります。

Application Load Balancer のアクセスログ - Elastic Load Balancing

ALBのログをAthenaから参照できるようにする

ALBに関するテーブル作成についてはAWS公式ドキュメントにも記載がありますが、データ量が多い環境下だとパフォーマンスとスキャン量に応じて決まる従量課金の観点からテーブル作成に加えパーティショニングが必須となります。

データのパーティション分割 - Amazon Athena

Athenaのパーティショニングは CREATE TABLE 時に PARTITIONED BY を定義した上で定期的にパーティションを更新する必要があります。
パーティションの更新は、ログ出力されるディレクトリがHive形式(e.g.year=2020/month=6/day=28)となっている場合、

・ALTER TABLE ADD PARTITION, MSCK REPAIR TABLEコマンドを打つ
・Glueのクローラーを利用する

のいずれかで可能で、特にGlueのクローラーを利用する方法はスケジューラーも含めてノーコードで解決するので重宝している方も多いのではないかと思います。

ところが、ALBのログ出力は日付単位とはなるがHive形式となっていないためパーテションの定期更新に上記いずれの方法も選択できません。よって、ALTER TABLE ADD PARTITION を利用してマニュアルで対応する必要があります。
私の場合は、SDK(start_query_execution)を利用してcron経由で日時実行するようにしました。

参考までにCREATE TABLE文とALTER文は以下のとおりです。

■CREATE TABLE文

CREATE EXTERNAL TABLE IF NOT EXISTS alb_logs (
  type string,
  request_timestamp string,
  elb_name string,
  client_addrport string,
  client_ip string,
  client_port int,
  target_addrport string,
  target_ip string,
  target_port int,
  request_processing_time decimal(8,6),
  target_processing_time decimal(8,6),
  response_processing_time decimal(8,6),
  elb_status_code string,
  target_status_code string,
  received_bytes int,
  sent_bytes int,
  request 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)
PARTITIONED BY (year int, month int, day int)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
 'serialization.format' = '1',
 'input.regex'='([^ ]*) ([^ ]*) ([^ ]*) (([^ ]*):([^ ]*)|-) (([^ ]*):([^ ]*)|-) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) \"([^\\\"]*)\" \"([^\\\"]*)\" ([^ ]*) ([^ ]*) ([^ ]*) \"([^\\\"]*)[ ]*\" \"([^ ]*)\" \"([^ ]*)\" ([^ ]*) ([^ ]*) \"([^ ]*)\" \"([^\\\"]*)\".*$'
)
LOCATION 's3://your_elb_log_path/'
TBLPROPERTIES ('has_encrypted_data'='false');

■ALTER文

ALTER TABLE alb_logs
  add partition (year = 2020, month = 6, day = 28)
  location 's3://your_elb_log_path/2020/06/28/'

※SDK経由で日付部分は動的に変更し実行

Redashでクエリを作り、Refresh Scheduleを利用して日時で実行する

例として前日分のワースト50を出力するクエリを作ります。
(requestの条件は適宜読み替えてください)

SELECT 
  request,
  target_processing_time,
  parse_datetime(request_timestamp, 'yyyy-MM-dd''T''HH:mm:ss.SSSSSS''Z') as request_at
FROM alb_internal_logs
WHERE
  YEAR = year(date_add('hour', 9, date_add('day', -1, now())))
  AND MONTH = month(date_add('hour', 9, date_add('day', -1, now())))
  AND DAY = day(date_add('hour', 9, date_add('day', -1, now())))
  AND request LIKE '%/api%'
  ORDER BY target_processing_time DESC
LIMIT 50

次に、Refresh Scheduleを設定し上記クエリを1日1回実行するようにします。Refresh Scheduleについては以下をご参照ください。

How to schedule a query

これで日時で前日に実行されたAPIの中からレスポンスが遅いワースト50が可視化できました。パーティションが効いているのでスキャン量も最小限です。（※ここ大事）

Redashの出力結果をSlackに通知する (ことで可視化を加速する)

Redash見に行かずにSlackで結果を見れたら...そんな願いを叶えてくれるのがredashbotです。

hakobera/redashbot

本家は↑ですが、弊社では同僚がforkして色々いい感じにカスタマイズしたredashbotを利用しています。

operando/redashbot

使い方としては、Slackに常駐しているBotに結果を見たいRedashページのURLをメンションします。

そうすると以下のような結果を返してくれます。

さらにSlackのリマインダー経由でredashbotへメンションすることで自動でSlackに通知がされるようにします。
(余談ですがSlackのリマインダー、書式が記憶に定着しないのでコチラのツールにお世話になっています)

これで遅いAPIのレスポンスタイムをSlack上に可視化することができました。

以上です。