MySQL道普請便り

第131回 mysqldumpslowを使ってスロークエリログを解析してみる

この記事を読むのに必要な時間:およそ 4.5 分

皆さんはスロークエリログを活用していますでしょうか。今回はこの連載でも第7回 スロークエリーログを使って遅いクエリを収集する第113回 anemoeaterを使ってスローログを可視化してみるで紹介させていただいた,スロークエリログ関連のお話となります。

今回は,mysqldumpslowという,スロークエリログをもっと便利にするコマンドラインツールについて紹介していきます。mysqldumpslowという字面を見ると,mysqldumpでじっくりと時間をかけてダンプファイルを取ってきてくれると思い浮かべるかもしれませんが,全くの別物なので注意しましょう。

検証環境

今回の検証環境は,第125回 phpMyAdminでDockerで建てたMySQLにアクセスするで記載したdocker-composeを利用して作成します。手元で簡単に試せるように,githubの筆者のレポジトリにサンプルコードとして置いてあるので,気軽に試したい方はgit cloneして試してみてください。試すにはdockerとdocker-composeが必要です。

git cloneしてきたディレクトリに入り,以下のコマンドを実行して見ましょう。

$ docker-compose build
$ docker-compose up -d
$ docker-compose exec mysql /bin/sh
# mysql -uroot -ppassword
mysql> 

mysqlクライアントが使用できる環境が簡単に立ち上がると思います。

今回はスロークエリログを有効にしたいので,第7回 スロークエリーログを使って遅いクエリを収集するで使用した以下のコマンドを実行して,スロークエリログが出力されることを確認しましょう。

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は,スロークエリログを解析してサマリーとして出力するコマンドラインツールです。第113回で紹介したanemoeaterと同様に,MySQLにログインする必要はなく,ログファイルだけを使用して解析をすることができます。

また,このツールを使うと,解析する過程で文字列や数字に関して自動で置き換えが行われるので,スロークエリログに個人情報や重要情報などが出力されてしまった場合にSQLを抽象化して出力でき,便利です。

使い方は簡単で,mysqldumpslowコマンドに引数としてログファイルを渡すだけで実行ができます。まずはオプションを付けずに実行してみましょう。

# 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行ずつ簡単に説明していくと,1行目はスロークエリログはどこのファイルから読んでいるかを書いています。2行目はこのクエリが現れた回数,クエリにかかった時間,ロックしていた時間,読み込んだ行数,実行したユーザとホストが書かれています。3行目には匿名化されたクエリが書かれています。

もう少し件数を増やしてみましょう。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へ,数字はNに置換されていることがわかりました。ちなみに文字列や数字が複数個ある場合でも, 文字列は全てS, 数字は全てNで置換されます。

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オプションを付けずに実行した場合の結果で見てもらいたい部分だけ抽出すると,以下のようになっていることがわかります。Rowsの部分を見てもらうとわぁるのですが,2000行と1行で1回あたり,平均1000.5行読まれていることになってしまっています。

# 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を渡しているので,Rowsの順に並んでいることがわかると思います。

# 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オプションですが,このオプションの引数に指定した個数だけ結果を返してくれるようになります。以下では1を指定しているので,結果が1件になりました。

# 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というコマンドについて紹介しました。このコマンドはログファイルがあれば非常に簡単に使えるので,たとえば1日に1回cronでmysqldumpslowを動かして,結果をwebhook等を利用してslack等のツールに通知として流し,常日頃からスロークエリログを確認する等の使い方ができます。

スロークエリログを出してはいるものの活用があまりできていない場合は,このツールを使ってスロークエリログを定期的に確認する仕組みを作ってみるところから始めてはいかがでしょうか。

著者プロフィール

木村浩一郎(きむらこういちろう)

株式会社オプティム 技術統括本部のエンジニア。最近はミドルウェア・インフラ周りのことも少しずつ学習しています。趣味は将棋。好きな戦法は四間飛車。

Twitter:@kk2170