概要
こんにちは。スタメンで開発者をしている津田です。今回は、Amazon Athenaを利用しアプリケーションのリクエスト処理時間をセグメント別に計測することで、パフォーマンスの低下を検知しやすくしたことについて紹介します。
動機
Webアプリケーションのパフォーマンスについて、以前は主に、ロードバランサーの平均処理時間を参照していました。しかし、平均処理時間はサーバー全体の負荷状況の手がかりにはなるものの、それ以上の詳細については読み取れません。また、ポーリングや、その他、応答に要する時間の短いリクエストが多数送られてくる状況だと、平均の処理時間としては下がることになり、アプリケーションパフォーマンス改善の目安としても利用しにくいです。
特別、処理に長い時間のかかったリクエストに関しては、bugsnagへ通知、New Relic等のAPMを使用して対象のリクエストを調査、というようなこともしていました。これは、極端に遅いリクエストが発生するケースを発見、改善するのに有用でしたが、閾値を下げすぎると調査しきれないほどの量が通知されてしまうため、あまり閾値を下げることができません。
上記では検出できない、「特定の状況にあるユーザーのみ、じわじわとパフォーマンスが低下している」ような状況をより早く発見するために、「ユーザーのセグメント」 x 「リクエストの種類」で分類した平均応答時間を算出し、継続的にチェックできるようにしました。
流れ
全体の流れは以下のようになります。
- Ruby on Railsアプリケーションからのjson形式ログ出力
- Amazon Kinesisによるファイル転送
- AWS Glueのクロール
- Amazon Athenaによる分析
1. Ruby on Railsアプリケーションからのjson形式ログ出力
アプリケーションは、Ruby on Railsで作成しています。まずはリクエスト毎に集計のもととなるログを出力する必要があるため、controllerのbefore_actionで処理開始時の時間を記録、after_actionで所要処理時間、ユーザーの分類に必要な情報、controller、actionに関わる情報をjson形式でログ出力しています。
この時点で、分析や調査に必要と無いと思われるリクエストではskipして、対象から外しておきます。
2. Amazon Kinesisによるファイル転送
Amazon Kinesis Data Firehoseを利用して、ログファイルを各アプリケーションサーバーから、Amazon S3のバケットに集約します。
Amazon S3 destinationのPrefixに
access/YEAR=!{timestamp:yyyy}/MONTH=!{timestamp:MM}/DAY=!{timestamp:dd}/
と設定し、パスに年月日を入れておきます。これは、Amazon Athenaで分析する際に、パーティションとして利用するためです。Amazon Athenaでは読み込んだファイルサイズの総量で課金されるため、日次で分析することが多いのであれば、日付単位でパーティション(Amazon S3におけるディレクトリ)を分割しておくほうがコストを抑えられます。
パーティションについては、Amazon Athena > ユーザーガイド > データのパーティション分割を参照してください。
3. AWS Glueのクロール
S3にファイルを置いただけではAmazon AthenaからDatabaseとして認識されないため、AWS Glueのクローラの定義を行い、S3をクロールしてデータソースとして登録します。クローラはjsonの中身を読み取ってテーブルの定義を作成してくれます。
クロールは基本一度行えば良いのですが、パーティションが増えたことを検知するために日次で動かしています。データの形式(jsonのフォーマット)が変わらないのであれば、ALTER TABLE ADD PARTITIONの方が良いのかも知れません。
ちなみに、上記の設定だとGMT零時でディレクトリが切り替わるため、日本時間では朝九時過ぎにクローラーを動かすと良いようです。
4. Amazon Athenaによる分析
ここまででAmazon AthenaのクエリエディターでSQLを利用してログが分析できるようになっているのですが、前述の通り、Amazon Athenaでは読み込んだファイルの総容量によって課金されます。試行錯誤したり、いろいろな種類のクエリを実行するのであれば、あらかじめセグメント別に集計したテーブルを作っておいたほうが、時間の節約にもなります。
create table
テーブルを作成するため、以下のような感じのSQLを一度実行しました。SELECTの結果を使ってCREATE TABLE ASしています。普通にCREATE TABLEを書いてもいいと思いますが、集計したいSQLで直接テーブルを作れるため、こちらのほうが楽でした。項目としてはセグメント別に平均値や総所要時間等を算出しています。
集計のもととなっているaccessテーブルは上記のjsonファイルからなるテーブルなので、各カラムはjsonファイルに含まれるオブジェクトのキーにあたります。
CREATE TABLE "access-log".aggregated_access WITH ( format='PARQUET', external_location='s3://xxx-log/aggregated_access/', partitioned_by=ARRAY['YEAR', 'MONTH', 'DAY'] ) AS SELECT tenant_id, controller_name, action_name, COUNT(*) AS total_count, FLOOR(SUM(processing_time)) AS total_time, ROUND(AVG(processing_time), 2) AS average_time, MAX(processing_time) AS max_time, MIN(processing_time) AS min_time, APPROX_PERCENTILE(processing_time, 0.9) AS ninety_percentile, YEAR, MONTH, DAY FROM access WHERE YEAR = '2020' AND MONTH = '06' AND DAY = '17' -- ここの日付はデータがあれば何でも良い GROUP BY tenant_id, controller_name, action_name, YEAR, MONTH, DAY ORDER BY total_time desc
insert
日次では、以下のようなSQLで集計を追加します。INSERT文を実行すると、対象のS3ディレクトリにファイルが生成されます。現状自動化できておらず、間違えて二度実行すると同じデータが2回作られてしまいますが、そうなったらS3から該当のファイルを消せば大丈夫です。
INSERT INTO aggregated_access SELECT tenant_id, controller_name, action_name, COUNT(*) AS total_count, FLOOR(SUM(processing_time)) AS total_time, ROUND(AVG(processing_time), 2) AS average_time, MAX(processing_time) AS max_time, MIN(processing_time) AS min_time, APPROX_PERCENTILE(processing_time, 0.9) AS ninety_percentile, YEAR, MONTH, DAY FROM access WHERE YEAR = '2020' AND MONTH = '06' AND DAY IN ('17') -- ここの日付を変える GROUP BY tenant_id, controller_name, action_name, YEAR, MONTH, DAY
select
気になる情報をselectします。aggregated_accessはファイルサイズとして非常に小さくなっているはずなので、PARTITIONもあまり気にせずクエリできます。
上記のSQLでも使用していますが、関数などはPrestoのドキュメントを参照できます。
まとめ
完全な自動化はできていないのですが、日々、各アクションのセグメント別パフォーマンスチェックを行うことができるようになり、いくつか問題点も事前に発見できました。
また、集計したテーブルは、元のデータに比べて圧倒的にサイズが小さくなっています。元のログは、サイズが大きいため、パーティションを横断するようなSELECT(日付をまたぐような検索)は若干躊躇するようなところがあったのですが、集計後のテーブルであれば全期間検索しても大した読み取りサイズにはなりません。特定のアクションを改善した際など、経時で処理時間を抽出し、改善の成果を確認することができるため、改善のモチベーションも発生しやすくなったのが良かったと思います。
