Athenaを使ってALBのアクセスログからリクエスト毎のパフォーマンスを計測する

Athenaを使うとS3上のデータを分析することが可能です。
今回はS3上に出力されるALBのアクセスログをAthenaを使って分析してみました。
パフォーマンスを計測する用途です。
ALBのアクセスログは結構なデータ量になることが想定されるので、パーティションを適用してクエリの実行時間、コストに気を配ります。

事前準備

ALBの設定でS3上にアクセスログを出力できます。

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

Athenaの利用方法

S3のデータに対応したテーブルを作成して、そのテーブルにクエリを実行するという流れになります。

テーブルを作成する

Athenaでテーブルを作成するクエリを実行します。
公式ドキュメントに大体の説明があります。
Application Load Balancer ログのクエリ - Amazon Athena

ほぼ公式ドキュメントの内容通りですが、異なる点は、パーティションを作成しているところです。

CREATE EXTERNAL TABLE IF NOT EXISTS alb_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 string,
  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,
  new_field 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' = '([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*):([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://your-alb-logs-directory/AWSLogs/<ACCOUNT-ID>/elasticloadbalancing/<REGION>/';

PARTITIONED BYでパーティションを定義します。
ALBのアクセスログでは、年月日毎にS3の階層が分かれているので、それに合わせてパーティションを設定しています。
LOCATIONでアクセスログのS3のPathを指定します。

パーティションを作成する

ALBのアクセスログのデータに対してパーティションを作成する場合には、データがパーティション分割されていないので、日付毎に手動でパーティションを作成する必要があります。

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

パーティション作成を自動化するために、Lambda関数を使ってパーティションを作成します。
日次で実行されることを想定して現在日時のパーティションを作成するNode.jsのLambda関数を用意しました。

index.js

const partition = require('./partition');

exports.handler = async (event) => {
  try {
    const body = await partition.execute();
    return {
      statusCode: 200,
      body,
    };
  } catch (err) {
    return {
      statusCode: 500,
      body: err,
    };
  }
};

partition.js

const util = require('util');
const AWS = require('aws-sdk');
const athena = new AWS.Athena({
  region: 'ap-northeast-1',
});
const startQueryExecution = util.promisify(athena.startQueryExecution).bind(athena);
const getQueryExecution = util.promisify(athena.getQueryExecution).bind(athena);

const sleep = (msec) => new Promise((resolve) => setTimeout(resolve, msec));

async function createQueryExecutionId() {
  const date = new Date();
  const params = {
    QueryString: `ALTER TABLE alb_logs ADD IF NOT EXISTS PARTITION (year=${date.getFullYear()},month=${date.getMonth() + 1},day=${date.getDate()})
    location 's3://hi1280-log/AWSLogs/012345678901/elasticloadbalancing/ap-northeast-1/${date.getFullYear()}/${(String(date.getMonth() + 1)).padStart(2, 0)}/${String(date.getDate()).padStart(2, 0)}/'`,
    ResultConfiguration: {
      OutputLocation: `s3://aws-athena-query-results-012345678901-ap-northeast-1/`,
    },
  };
  return await startQueryExecution(params);
}

async function getQueryExecutionState(id) {
  const params = {
    QueryExecutionId: id,
  };

  const data = await getQueryExecution(params);

  return data.QueryExecution.Status.State;
}

async function execute() {
  const data = await createQueryExecutionId();
  let state = false;
  for (let i = 0; i < 5; i++) {
    await sleep(1000);
    state = await getQueryExecutionState(data.QueryExecutionId);
    if (state === 'SUCCEEDED') {
      break;
    }
  }
  return `${data.QueryExecutionId} ${state}`;
}

module.exports = {
  execute,
};

Lambda関数の設定では、Athenaにアクセス可能なIAMポリシーを忘れないように設定します。

あとはこのLambda関数をEventBrideで毎日0時に実行するようにcron式でスケジュール実行します。
こちらUTCの時間なので、日本時間だと9時に実行されます。

諸々設定すると、Lambdaは下記のようになります。

クエリを実行する

パフォーマンスを計測するためのSQLを書きます。

select  
  count(*) as count,
  count(if(try_cast(target_status_code as integer) >= 100 and try_cast(target_status_code as integer) <= 199,1,NULL)) AS count_1XX,
  count(if(try_cast(target_status_code as integer) >= 200 and try_cast(target_status_code as integer) <= 299,1,NULL)) AS count_2XX,
  count(if(try_cast(target_status_code as integer) >= 300 and try_cast(target_status_code as integer) <= 399,1,NULL)) AS count_3XX,
  count(if(try_cast(target_status_code as integer) >= 400 and try_cast(target_status_code as integer) <= 499,1,NULL)) AS count_4XX,
  count(if(try_cast(target_status_code as integer) >= 500 and try_cast(target_status_code as integer) <= 599,1,NULL)) AS count_5XX,
  request_verb,
  request_url, 
  min(target_processing_time) as min,
  max(target_processing_time) as max,
  sum(target_processing_time) as sum,
  avg(target_processing_time) as avg,
  approx_percentile(target_processing_time, 0.01) as percentile_1,
  approx_percentile(target_processing_time, 0.50) as percentile_50,
  approx_percentile(target_processing_time, 0.99) as percentile_99
from alb_logs
where year = <year> and month = <month> and day = <day> # 日付を指定する
group by request_url, request_verb
order by sum desc;

レスポンスタイムの合計値で改善の効果が高いリクエストやパーセンタイルで定常的にレスポンスが悪いリクエストを確認できます。
また、リクエスト毎のステータスコードの割合も確認できるようにしています。

出力結果はログを可視化する下記ツールの出力を参考にしています。
GitHub - tkuchiki/alp: Access Log Profiler
ISUCONでお世話になっています。

そのほか、Athenaのクエリで利用可能な関数は以下に記載があります。

Amazon Athena の Presto 関数 - Amazon Athena

まとめ

今回の仕組みを使えば、ある程度実用的にALBのアクセスログを分析できるのではないかと思います。
手動でパーティションを作るのは面倒なのですが、今回のように自動化することもできます。