皆さんはスロークエリログを活用していますでしょうか。今回はこの連載でも第7回 スロークエリーログを使って遅いクエリを収集するや第113回 anemoeaterを使ってスローログを可視化してみるで紹介させていただいた、
今回は、
検証環境
今回の検証環境は、
git cloneしてきたディレクトリに入り、
$ docker-compose build $ docker-compose up -d $ docker-compose exec mysql /bin/sh # mysql -uroot -ppassword mysql>
mysqlクライアントが使用できる環境が簡単に立ち上がると思います。
今回はスロークエリログを有効にしたいので、
mysql> set global slow_query_log=1; mysql> set global long_query_time=0; mysql> set global log_queries_not_using_indexes=1;
スロークエリログの出力先はSHOWコマンドで確認できます。
mysql> show variables like 'slow_query_log_file'; +---------------------+--------------------------------------+ | Variable_name | Value | +---------------------+--------------------------------------+ | slow_query_log_file | /var/lib/mysql/84d4fcc06879-slow.log | +---------------------+--------------------------------------+ 1 row in set (0.01 sec)
実際に出力がされているか確認してみましょう。今回は、
mysql> use zipcode mysql> select * from zipcode limit 1; +-------+-------------+----------+-----------------------+--------------------------------------+-----------------------------------------------+------------+--------------------+--------------------------------+ | code | old_zipcode | zip_code | prefecture_kana | city_kana | town_kana | prefecture | city | town | +-------+-------------+----------+-----------------------+--------------------------------------+-----------------------------------------------+------------+--------------------+--------------------------------+ | 01101 | 060 | 0600000 | ﾎｯｶｲﾄﾞｳ | ｻｯﾎﾟﾛｼﾁｭｳｵｳｸ | ｲｶﾆｹｲｻｲｶﾞﾅｲﾊﾞｱｲ | 北海道 | 札幌市中央区 | 以下に掲載がない場合 | +-------+-------------+----------+-----------------------+--------------------------------------+-----------------------------------------------+------------+--------------------+--------------------------------+ 1 row in set (0.00 sec)
それでは、
# cat /var/lib/mysql/84d4fcc06879-slow.log # Time: 2020-09-25T00:13:42.385612Z # User@Host: root[root] @ localhost [] Id: 9 # Query_time: 0.000214 Lock_time: 0.000111 Rows_sent: 1 Rows_examined: 1 SET timestamp=1600992822; select * from zipcode limit 1;
先ほどのクエリが出力されていることがわかりました。
mysqlslowdumpを使ってみる
mysqlslowdumpは、
また、
使い方は簡単で、
# mysqldumpslow /var/lib/mysql/84d4fcc06879-slow.log Reading mysql slow query log from /var/lib/mysql/84d4fcc06879-slow.log Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode limit N
このような結果になりました。1行ずつ簡単に説明していくと、
もう少し件数を増やしてみましょう。mysqlクライアントで以下のクエリを実行しましょう。
mysql> select * from zipcode where prefecture = '北海道'; mysql> select * from zipcode where prefecture = '北海道'; mysql> select * from zipcode where prefecture = '北海道' limit 1;
上記を実行した後で、
/# mysqldumpslow /var/lib/mysql/84d4fcc06879-slow.log Reading mysql slow query log from /var/lib/mysql/84d4fcc06879-slow.log Count: 2 Time=0.07s (0s) Lock=0.00s (0s) Rows=8248.0 (16496), root[root]@localhost select * from zipcode where prefecture = 'S' Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode where prefecture = 'S' limit N Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode limit N
文字はSへ、
mysql > select * from zipcode where prefecture = '北海道' AND city = '札幌市中央区'; # このクエリを流すと # mysqldumpslow /var/lib/mysql/84d4fcc06879-slow.log # 以下の結果が増えます Count: 1 Time=0.07s (0s) Lock=0.00s (0s) Rows=89.0 (89), root[root]@localhost select * from zipcode where prefecture = 'S' AND city = 'S'
逆に匿名化されたくない場合は、-aオプションを利用することで生のデータを見ることができます。どうしてこのオプションが必要なのか？ というのを体感してもらうために、
mysql> select * from zipcode where prefecture = '北海道' limit 2000;
この場合に-aオプションを付けずに実行した場合の結果で見てもらいたい部分だけ抽出すると、
# mysqldumpslow /var/lib/mysql/84d4fcc06879-slow.log Count: 2 Time=0.00s (0s) Lock=0.00s (0s) Rows=1000.5 (2001), root[root]@localhost select * from zipcode where prefecture = 'S' limit N
このようにデータの偏りが大きい場合などには、-aオプションを利用すると、
# mysqldumpslow -a /var/lib/mysql/84d4fcc06879-slow.log Reading mysql slow query log from /var/lib/mysql/a79e29ca7752-slow.log Count: 2 Time=0.09s (0s) Lock=0.00s (0s) Rows=8248.0 (16496), root[root]@localhost select * from zipcode where prefecture = '北海道' Count: 1 Time=0.06s (0s) Lock=0.00s (0s) Rows=89.0 (89), root[root]@localhost select * from zipcode where prefecture = '北海道' AND city = '札幌市中央区' Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=2000.0 (2000), root[root]@localhost select * from zipcode where prefecture = '北海道' limit 2000 Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode limit 1 Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode where prefecture = '北海道' limit 1
ただし、
その他の便利なオプションとしては、-sオプションと-tオプションがあります。-sオプションはソートオプションで多い順に出力を並べ替えをすることができます。詳細は以下の表にまとめておきます。
| オプションの引数 | 並べ替えができる項目 |
|---|---|
| t, at | Time |
| l, al | Lock |
| r, ar | Rows |
| c | Count |
使い方は以下のようになります。以下では引数にrを渡しているので、
# mysqldumpslow -s r /var/lib/mysql/84d4fcc06879-slow.log Reading mysql slow query log from /var/lib/mysql/a79e29ca7752-slow.log Count: 2 Time=0.09s (0s) Lock=0.00s (0s) Rows=8248.0 (16496), root[root]@localhost select * from zipcode where prefecture = 'S' Count: 2 Time=0.00s (0s) Lock=0.00s (0s) Rows=1000.5 (2001), root[root]@localhost select * from zipcode where prefecture = 'S' limit N Count: 1 Time=0.06s (0s) Lock=0.00s (0s) Rows=89.0 (89), root[root]@localhost select * from zipcode where prefecture = 'S' AND city = 'S' Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost select * from zipcode limit N
続いて-tオプションですが、
# mysqldumpslow -s r -t 1 /var/lib/mysql/84d4fcc06879-slow.log Reading mysql slow query log from /var/lib/mysql/a79e29ca7752-slow.log Count: 2 Time=0.09s (0s) Lock=0.00s (0s) Rows=8248.0 (16496), root[root]@localhost select * from zipcode where prefecture = 'S' #
あまりに件数が多い場合などに、-sオプションと組み合わせて見れる件数だけに絞るという使い方が考えられます。スロークエリログに引っかかっている件数が多いクエリであれば、
まとめ
今回はmysqldumpslowというコマンドについて紹介しました。このコマンドはログファイルがあれば非常に簡単に使えるので、
スロークエリログを出してはいるものの活用があまりできていない場合は、