SREチームの中原です。
今回は Aurora MySQL のスロークエリーのログを BigQuery に取り込む方法について書いてみます。

TL;DR

Aurora からスローログを取得するには CloudWatch Logs から awslogs コマンドでもってくるのが楽だよ
スローログをパースさせるなら信頼と実績の Percona Toolkit pt-query-digest が楽だよ

経緯

弊社の本番DBは Aurora MySQL 2.x で運用しています。

これまでスロークエリーの分析は pt-query-digest + Anemometer + Aurora Serverless v1 で行っていましたが、 Anemometer の更新は止まったままだし、蓄積されたデータが増えるにつれて Aurora Serverless v1 ではパフォーマンス的にも厳しくなってきてました。

そこで、

蓄積されたデータがでかくなっても力技でなんとかできて定額料金使ってる BigQuery にログを貯めて、可視化するのは既存の redash でいいかな
こちらのブログ「Aurora MySQL スロークエリログの解析」を拝見して、Kinesis と Lambda でシンプルにスローログ取り込めるやん！今なら EventBride から直接 lambda 叩いて S3 に JSONL とかで吐き出せば BigQuery DataTransfer で簡単にインポートできるやん！とか思う
弊社のスロークエリーでかすぎて CloudWatch Logs のメッセージサイズ 256kb 制限にかかって分割されてしまってメッセージ単位での処理はうまくいかなそう…

とか考えた結果、あきらめて地道にログを落としてきて pt-query-digest にパースさせた結果を BigQuery に取り込むことにしました。
また、BigQuery の定額料金あるので、 pt-query-digest のサマライズを回避してスロークエリー１個単位で取り込むことにします。
pt-query-digest の --review, --history オプションで出力されるサマリーテーブルは Aurora Serverless v1 に変わって v2 に取り込むことにしますが、標準の機能なので本記事では説明しません。

フロー

こんなフローでアワリーでスローログを取り込んでいます。

Amazon CloudWatch Logs へのデータベースログの発行 - Amazon Aurora で DB インスタンス上にあるスロークエリーのログファイルを CloudWatch Logs に転送
アワリーで取り込み用の bash スクリプトを実行
稼働中の writer/reader インスタンス単位で以下の処理を実行します
1. awslogs コマンドで CloudWatch Logs の Log Group から対象時間のログを分単位でダウンロード
2. pt-query-digest コマンドを使ってログを json 形式に変換
3. pt-query-digest コマンドにスローログをパースさせて、サマる前の個別のスロークエリーをそのまま出力
4. bq load コマンドで BigQuery のスローログ詳細テーブルに取り込み
5. pt-query-digest コマンドの機能でスローログサマリーテーブルに取り込み

実際の処理

スローログのダウンロード

Aurora のログ取得方法として以下を検討しました。

aws logs get-log-events コマンドで取得
aws rds download-db-log-file-portion コマンドで取得
awslogs コマンドで取得
downloadCompleteDBLogFile API で取得

aws logs get-log-events コマンドで取得

最初このコマンドで実装しようとしましたが、1回あたりのサイズ・件数制限のせいでループ処理を実装しないといけないのがめんどくさくなってあきらめました…

aws rds download-db-log-file-portion コマンドで取得

次にこのコマンドをつかって実装し、一見うまく動いてるように見えたのですが、1行あたりのサイズ制限がありあきらめました…
ログに記録されている件数と pt-query-digest で取り込んだ件数を比較したところ、スロークエリーのサイズが大きいと 1行 128KB あたりでバッサリ切られて [Your log message was truncated] とかいうエラーメッセージが出力され、 SQL の途中でぶった切られて pt-query-digest が正常にパースできないことがありました…

awslogs コマンドで取得

結局 Jorge Bastida 氏作成の awslogs コマンドを利用して、以下のようなかんじでログを取得することにしました。
ただ、API のレートリミットにかかることがあったのと、 awslogs コマンドでウェイトをかけるオプションはみあたらなかったので、実際にはログの取得期間や sleep で調整して実行しています。

DB_CLUSTER="prod-cluster"
DB_INSTANCE="prod-instance"
DB_ROLE="writer"
HOUR_OFFSET=2
DATE=$(TZ=UTC /bin/date +"%Y-%m-%d" --date "${HOUR_OFFSET} hour ago")
HOUR=$(TZ=UTC /bin/date +"%H" --date "${HOUR_OFFSET} hour ago")
START_HOUR=$(TZ=UTC /bin/date +"%Y-%m-%dT%H" --date "${DATE}T${HOUR}:00")
END_HOUR=$(TZ=UTC /bin/date +"%Y-%m-%dT%H" --date "${START_HOUR}:00 1 hour")
LOG_GROUP="/aws/rds/cluster/${DB_CLUSTER}/slowquery"

TZ=UTC awslogs get ${LOG_GROUP} ${DB_INSTANCE} -G -S --start="${START_HOUR}"  --end="${END_HOUR}" > ${DB_INSTANCE}.${START_HOUR}.log

downloadCompleteDBLogFile API で取得

こちらは実際には試せてませんが downloadCompleteDBLogFile API なら aws rds download-db-log-file-portion と違って欠損なくログを落とせるはずってのを AWS の方に教えていただきました。普段からシェルスクリプトなんか使わず python とかで直接 API 叩くよって方はこちらのほうが楽かもしれません。

スローログのパース

スローログの用意ができたら pt-query-digest でログを解析していきます。
しかし pt-query-digest の標準の機能ではサマった結果しか出力できません。(json で出力させて sample カラムからクエリー単位で再構成する手もなくはない)

せっかく BigQuery にいれるなら生のスローログを入れたかったので --filter オプションの中で強引にスロークエリーを１個単位で JSON 形式出力してます。
また、Aurora の DB インスタンスや Writer/Reader などの情報も記録しときたかったので対応するカラムを追加してます。
あと、--filter オプションはあくまで評価式を入れる前提になっているようなので perl の記法としてはちょっと変な感じになってます。

pt-query-digest --no-report \
 --filter="( \$event->{aurora_role}=\"null\" && \$event->{aurora_role}=\"${DB_ROLE}\") \
 && (\$event->{aurora_instance}=\"null\" && \$event->{aurora_instance}=\"${DB_INSTANCE}\") \
 && print JSON::encode_json(\$event),\"\n\"" \
 ./${DB_INSTANCE}.${START_HOUR}.log > ${DB_INSTANCE}.${START_HOUR}.json

JSONファイルの分割と Google Cloud Storage へのアップロード

BigQuery は 4GB までの gzip 圧縮された JSON ファイルを受け付けてくれるのですが、めんどくさいので圧縮前のサイズで判定してファイルを分割してしまって圧縮し Google Cloud Storage のインポート用バケットにアップロードします。

JSONSIZE=$(stat -c %s ${DB_INSTANCE}.${START_HOUR}.json)
JSONMAXSIZE=$(( 4 * 1024 * 1024 * 1024 ))
JSONSPLIT=$(( ( JSONSIZE / JSONMAXSIZE ) + 1 ))
JSONSPLIT=$(( JSONSPLIT + 1))

if [[ "${JSONSIZE}" -ge "${JSONMAXSIZE}" ]]; then
  split -d -n "l/${JSONSPLIT}" "${DB_INSTANCE}.${START_HOUR}.json" "${DB_INSTANCE}.${START_HOUR}.json."
  pigz ${DB_INSTANCE}.${START_HOUR}.json.*
else
  pigz ${DB_INSTANCE}.${START_HOUR}.json
fi

gsutil cp *.gz  "gs://gcs-import-bucket/${START_HOUR}/"

BigQuery のテーブル作成

初回実行時はスローログ用のテーブルを作成しておきます。

[
  { "name": "ts", "type": "TIMESTAMP" },
  { "name": "timestamp", "type": "INTEGER" },
  { "name": "cmd", "type": "STRING" },
  { "name": "arg", "type": "STRING" },
  { "name": "bytes", "type": "INTEGER" },
  { "name": "fingerprint", "type": "STRING" },
  { "name": "Query_time", "type": "FLOAT" },
  { "name": "Lock_time", "type": "FLOAT" },
  { "name": "Rows_examined", "type": "INTEGER" },
  { "name": "Rows_sent", "type": "INTEGER" },
  { "name": "aurora_instance", "type": "STRING" },
  { "name": "aurora_role", "type": "STRING" },
  { "name": "db", "type": "STRING" },
  { "name": "host", "type": "STRING" },
  { "name": "ip", "type": "STRING" },
  { "name": "user", "type": "STRING" },
  { "name": "Thread_id", "type": "INTEGER" },
  { "name": "pos_in_log", "type": "INTEGER" }
]

bq mk \
    -t \
    --time_partitioning_field ts \
    --time_partitioning_type HOUR \
    --table target_dataset.slowlog_events \
    ./slowlog_events.schema

BigQuery へのインポート

BigQuery のテーブルへインポートを行います。

bq load \
    --noreplace \
    --source_format=NEWLINE_DELIMITED_JSON \
    target_dataset.slowlog_events \
    gs://gcs-import-bucket/${START_HOUR}/*.gz \
    ./slowlog_events.schema

使ってみる

インポートした BigQuery のスローログテーブルにクエリーを投げてみます。

テーブルの内容は以下のようなかんじになってます。

カラム	内容	例
ts	クエリー終了時のタイムスタンプ	2023-03-29 23:10:02 UTC
timestamp	UNIX TIME 形式のタイムスタンプ	1680131402
cmd	クエリーの Cmmand 種別	Query
arg	実クエリー	SELECT col FROM tbl WHERE id=5
bytes	クエリーのサイズ	103
fingerprint	抽象化したクエリー	select col from tbl where id=?
Query_time	実行時間	0.033384
Lock_time	ロック時間	0
Rows_examined	検査された行数	0
Rows_sent	返信された行数	0
db	対象の論理DB	audience
host	接続元ホスト	localhost
ip	接続元IP	10.0.2.150
user	接続元ユーザ	dbuser
Thread_id	MySQL スレッド識別子	3567763897
pos_in_log	スローログ上の位置	0
aurora_instance	Aurora の Instance ID	prod-instance
aurora_role	Instance が writer か reader	writer

各カラムの詳細については Percona Toolkit のドキュメントも参照ください。

クエリーは調査したい内容にあわせてお好みでといったところですが、例えば一定時間以上 Lock_time がかかっているスロークエリーの推移を確認したいとかいった場合はこんなかんじで redash から実行したりしています。

SELECT
  TIMESTAMP_TRUNC(ts, MINUTE) AS ts_min,
  count(ts) AS cnt
FROM `target_dataset.slowlog_events`
WHERE
  ts BETWEEN timestamp('{{START_UTC}} UTC') AND timestamp('{{END_UTC}} UTC')
  AND aurora_role = '{{ROLE}}'
  AND Lock_time > {{LOCK_SEC}}
GROUP BY ts_min
ORDER BY ts_min

後書き

直近の情報であれば Performance Insights を見れば事足りることも多いですが、とりあえず BigQuery にぶっこんでおけば、Performance Insights の保存期間過ぎた過去の負荷を調べたいとか、統計的に長期傾向みたいとかで、しあわせになれるかもしれません。

Yappli Tech Blog

株式会社ヤプリの開発メンバーによるブログです。最新の技術情報からチーム・働き方に関するテーマまで、日々の熱い想いを持って発信していきます。

Aurora MySQL のスローログを BigQuery に取り込んでみた