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

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>[^\[]*?)\[[^\]]*\] @ (?<Host>[^\s\[]*?) \[.*\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>[^\[]*?)\[[^\]]*\] @ (?<Host>[^\s\[]*?) \[.*\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>[^\[]*?)\[[^\]]*\] @ (?<Host>[^\s\[]*?) \[.*\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>[^\[]*?)\[[^\]]*\] @ (?<Host>[^\s\[]*?) \[.*\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>[^\[]*?)\[[^\]]*\] @ (?<Host>[^\s\[]*?) \[.*\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


最後に

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



Twitter始めました!

良かったらぜひ。

Twitter ID → @365_step_tech