見出し画像
Photo by toyokawashinun

Aurora MySQL スロークエリログの解析

Takahiro Yamada

Aurora MySQL スロークエリログの可視化について試してみたので共有したいと思います。

Aurora MySQL とは AWS が提供しているMySQL と互換性のあるリレーショナルデータベースサービスです (PostgreSQL 互換エディションもあります)。
Aurora ではスロークエリログを出力することができますが、出力先として CloudWatch Logs を選択することができます [1]。

画像2

※ Aurora MySQL スロークエリログを CloudWatch Logs で表示させた例

CloudWatch Logs ではコンソール上でログデータの検索を実施できますが、スロークエリの実行時間の統計値などを確認することは難しいです。
そこで、下記 2 つの方法にてスロークエリログの可視化を実施してみました。

・CloudWatch Logs Insights を利用する
・Athena を利用する

上記 2 つの方法以外にも Elasticsearch を利用する方法もあります。Elasticsearch を利用する方法については、インターネット上に紹介されている記事もあるのでそちらを参考にしてください。

CloudWatch Logs Insights を利用する

CloudWatch Logs には CloudWatch Logs Insights という機能があります。
CloudWatch Logs Insights を利用すると CloudWatch Logs に保存されているテキストデータを解析し、タイムスタンプや特定の数値などを抽出することができます（抽出した各値はフィールドと呼ばれます）。
また、抽出したそれぞれのフィールドに対してフィルタリングやソート処理を実行したりと、ログ内容の解析ができます。


画像2

※ CloudWatch Logs での表示例

CloudWatch Logs Insights では、CloudWatch Logs Insights 専用のクエリを用いてテキストデータからフィールドを抽出したり、各フィールドにソートなどを実行します。

まず、parse クエリを用いて Aurora MySQL のスロークエリログからタイムスタンプやクエリ実行時間といった値を抽出してみましょう。
parse クエリでは正規表現を用いて、ログテキストデータから抽出したいフィールドを指定することができます。

Aurora MySQL のスロークエリログの例と利用する parse クエリは次のようになります。

​# Time: 2021-01-01T00:00:00.000000Z
# User@Host: user[user] @ [10.0.0.1] Id: 12345
# Query_time: 10.000156 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
select sleep(10);

※ Aurora MySQL のスロークエリログの例

parse @message /^#? Time: (?<timestamp>.*?)\s#? User\@Host:\s+(?<user>\S+)\[.*?\]\s+\@\s+(?<host>\S+)(\s+Id:\s+\d+)?\s# Query_time: (?<query_time>[0-9.]+)\s+Lock_time: (?<lock_time>[0-9.]+)\s+Rows_sent: (?<rows_sent>[0-9.]+)\s+Rows_examined: (?<rows_examined>[0-9.]+)\s+(?<query>.*)/

※ 利用する parse クエリ (視認性のため引用にしています)

正規表現の算出には [2] を利用しました。
正規表現中の (?<name>.*) のような形式の箇所が抽出されるフィールドを表し、下記のようなデータをフィールドとして抽出できます。

・タイムスタンプ
・クエリ実行ユーザー
・クエリ実行ホスト
・クエリ実行時間
・ロック取得までの時間
・クライアントへ送信した行数
・(ストレージエンジンでの処理は除いた) 探索された行数
・実行したクエリ

また、sort クエリを用いて下記のようなクエリを組み立てることでクエリ実行時間が長い順にソートすることができます。

parse @message /^#? Time: (?<timestamp>.*?)\s#? User\@Host:\s+(?<user>\S+)\[.*?\]\s+\@\s+(?<host>\S+)(\s+Id:\s+\d+)?\s# Query_time: (?<query_time>[0-9.]+)\s+Lock_time: (?<lock_time>[0-9.]+)\s+Rows_sent: (?<rows_sent>[0-9.]+)\s+Rows_examined: (?<rows_examined>[0-9.]+)\s+(?<query>.*)/
| sort query_time desc

※ クエリ実行時間が長い順のスロークエリを表示するクエリ

更に、CloudWatch Logs Insights ではクエリ結果を折れ線グラフを用いて可視化できます。
例えば下記のようなクエリを実行すると、次のような 30 秒間の解像度におけるクエリ時間の最大値を表したグラフが得られます。

parse @message /^#? Time: (?<timestamp>.*?)\s#? User\@Host:\s+(?<user>\S+)\[.*?\]\s+\@\s+(?<host>\S+)(\s+Id:\s+\d+)?\s# Query_time: (?<query_time>[0-9.]+)\s+Lock_time: (?<lock_time>[0-9.]+)\s+Rows_sent: (?<rows_sent>[0-9.]+)\s+Rows_examined: (?<rows_examined>[0-9.]+)\s+(?<query>.*)/
| stats max(query_time) by bin(30s)

※ 30 秒間の解像度におけるクエリ時間の最大値を表示するクエリ

画像3

※ 30 秒間の解像度におけるクエリ時間を表すグラフ

Athena を利用する方法

次に紹介する方法は、Athena を利用して SQL を用いて Aurora MySQL のスロークエリログを解析する方法です。

画像4

※ CloudWatch Logs から Amazon Kinesis Data Firehose, S3 まで

CloudWatch Logs に保存されたデータは CloudWatch Logs サブスクリプションフィルターを利用して、Amazon Kinesis Data Firehose を経由して S3 に保存することができます。
また、Amazon Kinesis Data Firehose から S3 に保存する際に、Lambda を利用して Aurora MySQL のスロークエリログを JSON データへと構造化してから Amazon Kinesis Data Firehose 上にて Parquet 形式に保存することで、Athena から SQL を用いて効率的に Aurora MySQL のスロークエリログを解析することができます。

CloudWatch Logs サブスクリプションフィルターの作成と、Amazon Kinesis Data Firehose との連携についてはドキュメント [3] を参考にすることで実施できます。

Aurora MySQL のスロークエリログを解析してJSON データへと構造化する Lambda については下記のようなコードにて実施しました。

import json
import base64
import io
import gzip
import re

def lambda_handler(event, context):
   transformed_records = []
   for record in event['records']:
       record_id = record['recordId']
       payload = base64.b64decode(record['data'])
       iodata = io.BytesIO(payload)
       with gzip.GzipFile(fileobj=iodata, mode='r') as f:
           payload = json.loads(f.read())
       processed_data = ''
       for log_event in payload['logEvents']:
           processed_data += transform(log_event) + '\n'
       tmp = {
           'data': base64.b64encode(processed_data.encode('utf-8')),
           'result': 'Ok',
           'recordId': record_id
       }
       transformed_records.append(tmp)
   return {'records': transformed_records}

def transform(log_event):
   timestamp = log_event['timestamp']
   message = log_event['message']
   match = re.search(
       '^#? Time: (.*?)\s#? User\@Host:\s+(\S+)\[.*?\]\s+\@\s+\[(\S+)\]\s+Id:\s+\d+\s# Query_time: ([0-9.]+)\s+Lock_time: ([0-9.]+)\s+Rows_sent: ([0-9.]+)\s+Rows_examined: ([0-9.]+)\s+(.*)',
       message
   )
   if match:
       time, user, host, query_time, lock_time, rows_sent, rows_examined, query = match.groups()
       parsed_json = {
           'timestamp': timestamp,
           'message': message,
           'time': time,
           'user': user,
           'host': host,
           'query_time': float(query_time),
           'lock_time': float(lock_time),
           'rows_sent': int(rows_sent),
           'rows_examined': int(rows_examined),
           'query': query,
       }
   else:
       parsed_json = {}
   return json.dumps(parsed_json)


CloudWatch Logs Insights の時に利用した正規表現をほぼそのまま利用できます。

S3 に Parquet 形式で保存した後は Athena にてテーブルを作成して (自分は Glue クローラを利用しました) あげることで、下記のように SQL にて Aurora MySQL のスロークエリログを解析できます。

SELECT 
   time,
   user,
   host,
   query_time,
   lock_time,
   rows_sent,
   rows_examined,
   query
FROM aurora_slowquery_log_parquet
WHERE CONCAT(YEAR, MONTH, DAY) >= date_format(CURRENT_DATE - interval '1' DAY, '%Y%m%d')

画像5

※ Athena クエリの例

また、AWS サービスであれば QuickSight から Athena テーブルを参照することでグラフ化も可能です。
弊社では Re:dash が利用される事が多いため、今回は Re:dash を利用してクエリ時間の最大値を表したグラフを取得してみました。

画像6

※ Redash での可視化の例

まとめ

下記 2 つの方法にて Arurora MySQL スロークエリログの可視化を実施してみました。

・CloudWatch Logs Insights を利用する
・Athena を利用する

設定の容易さについては「CloudWatch Logs Insights を利用する」のほうが簡単に実施できることがわかりました。しかし、CloudWatch Logs Insights 専用のクエリを利用しなければならないことや、AWS Console を利用しなければならない点が欠点になると思いました。

「Athena を利用する」方法については設定が「CloudWatch Logs Insights を利用する」方法に比べ複雑ですが、SQL を利用できる（ただし、Presto SQL  Syntax に従う必要あり）点がメリットに感じられました。

終わりに

株式会社POLではエンジニア、デザイナー、プロダクトマネージャーを大募集してます！お話しだけでも構いませんのでお気軽にお声がけください！！！

https://herp.careers/v1/polinc

参考

[1] Amazon CloudWatch Logs への Amazon Aurora MySQL ログの発行 - Amazon Aurora
https://docs.aws.amazon.com/ja_jp/AmazonRDS/latest/AuroraUserGuide/AuroraMySQL.Integrating.CloudWatch.html

[2] mysql-server/mysqldumpslow.sh at 5.7 · mysql/mysql-server
https://github.com/mysql/mysql-server/blob/5.7/scripts/mysqldumpslow.sh

[3]CloudWatch Logs サブスクリプションフィルターの使用 - Amazon CloudWatch Logs
https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/SubscriptionFilters.html#FirehoseExample

この記事が気に入ったらサポートをしてみませんか？