ログ解析に便利なawk
アクセスログやアプリケーションのエラーログなど、一定のフォーマットで出力されるテキストの解析には awk が便利です。今回は MySQL のスロークエリログを対象に解析した時の tips です。
MySQLのパフォーマンスチューニングにおいて、実行に時間が掛かる処理の特定にはスロークエリログが便利です。出力するための設定は 本家リファレンス を参照下さい。
スロークエリログは以下のような内容です。
# Time: 120227 0:00:27
# User@Host: ユーザー名 @ ホスト名 [IPアドレス]
# Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 15932
SELECT COUNT(*) AS `count` FROM ...
上記のフォーマットで場合によっては膨大な量のログが出力されます。これを目視でひとつひとつ確認するにはかなりの時間がかかるので、ツールを使って効率的に行ないたいと思います。そこで登場するのが awk です。
awk の基本形は以下の通り。
$ awk '条件文{実行文}' ファイル名
これを使って、スロークエリログ内の 「Query_time」値が高い順に出力し、その行番号と行内容を出力する awk ワンライナーは以下の通りです。
$ awk '/Query_time/ && $3 > 0 {print NR,$0}' slow.log | sort -k4 -n -r > sorted.txt
コマンド解説
- 条件文
- 行内の「Query_time」で正規表現マッチをかけ、かつ3列目( Query_time 値)が 0 以上のもの。
- 実行文
- NR とは、処理中の行数を示すもの。$0 とは行全体を指す。よって、行番号とその行を標準出力に表示する。
これで、以下のように標準出力に表示されます。
2342 # Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 15932
4854 # Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 7834
7848 # Query_time: 10 Lock_time: 0 Rows_sent: 1 Rows_examined: 15932
22475747 # Query_time: 5 Lock_time: 0 Rows_sent: 1 Rows_examined: 22146
これで Querytime が 0 以上のものが表示されましたが、さらに sort コマンドをパイプで連結して Querytime の降順で出力します。
- -k4
- ソートキーを指定します。スペース区切りで先頭から4列目( Query_time 値)を指定しています。
- -n
- 数値の前に付いている記号「+」や「-」なども数値とみなします。
- -r
- 逆順(降順)で出力すること。
これで最終的に sorted.txt に出力される内容は、以下の通り。
7848 # Query_time: 10 Lock_time: 0 Rows_sent: 1 Rows_examined: 15932
22475747 # Query_time: 5 Lock_time: 0 Rows_sent: 1 Rows_examined: 22146
2342 # Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 15932
4854 # Query_time: 2 Lock_time: 0 Rows_sent: 1 Rows_examined: 7834
これで効率良く時間がかかっているSQLを見つけることができます!!