RDSやAuroraなどでMySQLを使用しているとスロークエリログをCloudWatch Logsで管理することが多いと思います。

今回はそのMySQLのスロークエリログを、CloudWatch Logs Insightsで整形して有用な情報を得るクエリを書いてみました。

概要

RDSやAurora、はたまたEC2内のMySQLのスロークエリログ(slow query log)を、CloudWatch Logs Insightsでうまくパースして、見やすく・フィルタリングしやすくします。

前提

スロークエリログがCloudWatch Logsに吐き出されるように設定されていること
- RDSやAuroraを使用しているときは簡単に設定できます

監査ログ(Audit Log)

RDSやAuroraなどのMySQLの監査ログ(Audit Log)をCloudWatch Logs Insightsで整形する方法に関しては、以下の記事に記載しています。

go-to-k.hatenablog.com

CloudWatch Logs Insightsでスロークエリログを整形する

よく使う絞りパターンのクエリをいくつか載せてみます。

Timestampでソート

実行された順番

fields @timestamp, @message
| parse @message /^# Time:[\s]*(?<Time>.*?)\n# User@Host: (?<User>[^\[]*?)\[[^\]]*?\]\s*@\s*(?<Host>.*?)\s*?Id.*\n# Query_time: (?<QueryTime>[^\s]*?)[\s]*Lock_time: (?<LockTime>[^\s]*?)[\s]*Rows_sent: (?<RowsSent>[^\s]*?)[\s]*Rows_examined: (?<RowsExamined>[^\s]*?)\n(?<Query>.*?)$/
| filter User != 'rdsadmin'
| display @timestamp, User, Host, QueryTime, LockTime, RowsSent, RowsExamined, Query
| sort @timestamp desc
| limit 100

QueryTimeでソート

クエリ実行に時間がかかった順番

fields @timestamp, @message
| parse @message /^# Time:[\s]*(?<Time>.*?)\n# User@Host: (?<User>[^\[]*?)\[[^\]]*?\]\s*@\s*(?<Host>.*?)\s*?Id.*\n# Query_time: (?<QueryTime>[^\s]*?)[\s]*Lock_time: (?<LockTime>[^\s]*?)[\s]*Rows_sent: (?<RowsSent>[^\s]*?)[\s]*Rows_examined: (?<RowsExamined>[^\s]*?)\n(?<Query>.*?)$/
| filter User != 'rdsadmin'
| display @timestamp, User, Host, QueryTime, LockTime, RowsSent, RowsExamined, Query
| sort QueryTime desc
| limit 100

LockTimeでソート

ロック待ちになっている時間が長い順番
- 更新クエリによる行ロックとは限らないので注意
- MySQLにはいろいろなロックがあって、このLockTimeはテーブルアクセスするときのメタデータロックなども含んでいる

fields @timestamp, @message
| parse @message /^# Time:[\s]*(?<Time>.*?)\n# User@Host: (?<User>[^\[]*?)\[[^\]]*?\]\s*@\s*(?<Host>.*?)\s*?Id.*\n# Query_time: (?<QueryTime>[^\s]*?)[\s]*Lock_time: (?<LockTime>[^\s]*?)[\s]*Rows_sent: (?<RowsSent>[^\s]*?)[\s]*Rows_examined: (?<RowsExamined>[^\s]*?)\n(?<Query>.*?)$/
| filter User != 'rdsadmin'
| display @timestamp, User, Host, QueryTime, LockTime, RowsSent, RowsExamined, Query
| sort LockTime desc
| limit 100

RowsSent / RowsExaminedでソート

クエリのアクセス効率が悪い順番
- = インデックスで適切に絞り込めていない

fields @timestamp, @message
| parse @message /^# Time:[\s]*(?<Time>.*?)\n# User@Host: (?<User>[^\[]*?)\[[^\]]*?\]\s*@\s*(?<Host>.*?)\s*?Id.*\n# Query_time: (?<QueryTime>[^\s]*?)[\s]*Lock_time: (?<LockTime>[^\s]*?)[\s]*Rows_sent: (?<RowsSent>[^\s]*?)[\s]*Rows_examined: (?<RowsExamined>[^\s]*?)\n(?<Query>.*?)$/
| filter User != 'rdsadmin'
| fields RowsSent/RowsExamined as SentPerExamined
| filter SentPerExamined > 0
| display @timestamp, User, Host, QueryTime, LockTime, SentPerExamined, RowsSent, RowsExamined, Query
| sort SentPerExamined
| limit 100

RowsSentでソート

返す行数が多い順番

fields @timestamp, @message
| parse @message /^# Time:[\s]*(?<Time>.*?)\n# User@Host: (?<User>[^\[]*?)\[[^\]]*?\]\s*@\s*(?<Host>.*?)\s*?Id.*\n# Query_time: (?<QueryTime>[^\s]*?)[\s]*Lock_time: (?<LockTime>[^\s]*?)[\s]*Rows_sent: (?<RowsSent>[^\s]*?)[\s]*Rows_examined: (?<RowsExamined>[^\s]*?)\n(?<Query>.*?)$/
| filter User != 'rdsadmin'
| display @timestamp, User, Host, QueryTime, LockTime, RowsSent, RowsExamined, Query
| sort RowsSent desc
| limit 100

最後に

小ネタというか、よく使うフィルタパターンをコピペで使えるよう載せてみました。

365歩のテック

MySQLのスロークエリログをCloudWatch Logs Insightsで整形する

概要

前提