Go to Qiita Advent Calendar 2024 Top
LoginSignup
3
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

MySQLAdvent Calendar 2024

Day 10
@TomoProgin株式会社ネオジニア

【MySQL】mysqldumpslowでスロークエリログを解析する

Last updated at Posted at 2024-12-09

この記事は MySQL Advent Calendar 2024 10日目の記事です。

はじめに

MySQLにはスロークエリログを解析するためにmysqldumpslowというコマンドラインツールがあります。
この記事ではそのツールの使い方を解説します。

動作環境

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.35    |
+-----------+
1 row in set (0.00 sec)

MySQL公式のDockerイメージを使っています。
実際に使用したDockerfileはこちら

ちなみに8.4.3のDockerイメージではmysqldumpslowは付属していませんでした。
もしかしてもうオワコン？

mysqldumpslowって何？

mysqldumpslowというのはMySQLで出力されるスロークエリログを解析し、要約してくれるツールです。
スロークエリログを直接lessのようなページャを使って確認することも可能ですが、mysqldumpslowを使うとクエリを抽象化してまとめてくれたり、時間がかかっているクエリ順にソートするといったことができたりします。

基本的な使い方

mysqldumpslow [options] [log_file ...]

実際に試すと以下のような出力になります。

mysqldumpslow /var/lib/mysql/slow.log

Count: 1  Time=15.00s (15s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  select sleep(N) from comments

Count: 2  Time=3.00s (6s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(N), comments.* from comments limit N

Count: 1  Time=0.13s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into comments values
  (N, N,  'S'),
  (N, N,  'S'),
  (N, N,  'S'),
  (N, N,  'S'),
  (N, N, 'S')

...

読み方

出力される内容の読み方ですが、以下のようになります。

Count: 1  Time=15.00s (15s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  select sleep(N) from comments
項目 説明
1つめ（Count） クエリが現れた回数
2つめ（Time） クエリにかかった平均時間（括弧内は合計時間）
3つめ（Lock） ロックにより待機していた平均時間（括弧内は合計時間）
4つめ（Rows） 読み込んだ平均行数（括弧内は合計の読み込み行数）
5つめ 実行したユーザと実行したホスト

2行目以降には実際のクエリを抽象化（数値はN、文字列はS）したクエリが表示されます。

オプションについて

オプションは色々ありますが、よく使うと思われるものだけ記載しておきます。

オプション 説明
-a すべての数値、文字列を抽象化しない
-g パターンに一致するステートメントのみを考慮
-s 出力のソート方法
at または t: クエリにかかった平均時間 または 合計時間
al または l: ロックにより待機していた平均時間 または 合計時間
ar または r: 読み込んだ平均行数 または 合計行数
c: クエリの出現回数
-t 指定された数だけのクエリーのみ表示

aオプション

すべての数値、文字列を抽象化せずに出力します。
mysqldumpslowでは数値はN、文字列はSで抽象化されて解析ますが、このオプションを使うと実際に実行したクエリのまま解析が行われます。

  • オプションなし
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), dbuser[dbuser]@localhost
  select * from comments where user_id = N and contents = 'S'
  • オプションあり
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), dbuser[dbuser]@localhost
  select * from comments where user_id = 1 and contents = 'コメント2-1'

データに偏りがある場合、抽象化するとクエリがまとめられてしまうため、状況を正しく解析できていない場合が出てきます。
そういったケースが考えられる場合はこのオプションを使って解析した方が良いと思います。

gオプション

パターンに一致するステートメントのみを出力できます。
正規表現も使用可能です。

# "user_id"が含まれるクエリを検索
mysqldumpslow /var/lib/mysql/slow.log -g user_id

Count: 1  Time=0.05s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  create table comments (
  id integer primary key,
  user_id integer not null,
  contents varchar(N)
  )

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.5 (1), dbuser[dbuser]@localhost
  select * from comments where user_id = N and contents = 'S'

...

特定のクエリだけを調べたいという場合に使えるオプションだと思います。

sオプション

出力のソート方法を指定します。
それぞれaが前に付くと平均値(average)でのソートとなります。
何も指定しない場合はatを指定したのと同じになります。
ソートはすべて降順です。もし昇順にしたい場合はrオプションを併用してください。

at または t

クエリにかかった平均時間（Timeの値）または合計時間（Timeの括弧の値）でソートします。

mysqldumpslow /var/lib/mysql/slow.log -s at

Reading mysql slow query log from /var/lib/mysql/slow.log
Count: 1  Time=15.00s (15s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  select sleep(N) from comments

Count: 2  Time=3.00s (6s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(N), comments.* from comments limit N

Count: 3  Time=3.00s (9s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select sleep(N), comments.id from comments limit N for update

Count: 1  Time=1.20s (1s)  Lock=0.00s (0s)  Rows=1048576.0 (1048576), root[root]@localhost
  select * from sample for update

...

mysqldumpslow /var/lib/mysql/slow.log -s t

Count: 20  Time=0.94s (18s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into sample select * from sample

Count: 1  Time=15.00s (15s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  select sleep(N) from comments

Count: 3  Time=3.00s (9s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select sleep(N), comments.id from comments limit N for update

...

al または l

ロックにより待機していた平均時間（Lockの値）または合計時間（Lockの括弧の値）でソートします。

mysqldumpslow /var/lib/mysql/slow.log -s al

Count: 1  Time=0.01s (0s)  Lock=26.51s (26s)  Rows=0.0 (0), dbuser[dbuser]@localhost
  update sample2 set id = N limit N

Count: 2  Time=0.01s (0s)  Lock=4.32s (8s)  Rows=0.0 (0), 2users@localhost
  update sample set id = N limit N

Count: 6  Time=0.01s (0s)  Lock=1.63s (9s)  Rows=0.0 (0), 2users@localhost
  update comments set contents='S' where id = N
...

mysqldumpslow /var/lib/mysql/slow.log -s l

Count: 1  Time=0.01s (0s)  Lock=26.51s (26s)  Rows=0.0 (0), dbuser[dbuser]@localhost
  update sample2 set id = N limit N

Count: 6  Time=0.01s (0s)  Lock=1.63s (9s)  Rows=0.0 (0), 2users@localhost
  update comments set contents='S' where id = N

Count: 2  Time=0.01s (0s)  Lock=4.32s (8s)  Rows=0.0 (0), 2users@localhost
  update sample set id = N limit N
...

ar または r

読み込んだ平均行数（Rowsの値）または合計行数（Rowsの括弧の値）でソートします。

mysqldumpslow /var/lib/mysql/slow.log -s ar

Count: 2  Time=1.29s (2s)  Lock=0.00s (0s)  Rows=1048575.0 (2097150), root[root]@localhost
  select * from sample for update

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=501.0 (1002), 2users@[192.168.56.101]
  /* ApplicationName=RubyMine N.N.N */ select * from sample

Count: 4  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=286.0 (1144), 2users@[192.168.56.101]
  /* ApplicationName=RubyMine N.N.N */ select collation_name, character_set_name,
  is_default collate utf8_general_ci = 'S' as is_default
  from information_schema.collations
...

mysqldumpslow /var/lib/mysql/slow.log -s r

Count: 2  Time=1.29s (2s)  Lock=0.00s (0s)  Rows=1048575.0 (2097150), root[root]@localhost
  select * from sample for update

Count: 4  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=286.0 (1144), 2users@[192.168.56.101]
  /* ApplicationName=RubyMine N.N.N */ select collation_name, character_set_name,
  is_default collate utf8_general_ci = 'S' as is_default
  from information_schema.collations

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=501.0 (1002), 2users@[192.168.56.101]
  /* ApplicationName=RubyMine N.N.N */ select * from sample
...

c

クエリの出現回数（Countの値）でソートします。

mysqldumpslow /var/lib/mysql/slow.log -s c

Count: 1787  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  SET @time_zone_id= LAST_INSERT_ID()

Count: 156  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  INSERT INTO time_zone_transition_type (Time_zone_id, Transition_type_id, Offset, Is_DST, Abbreviation) VALUES
  (@time_zone_id, N, N, N, 'S')
  ,(@time_zone_id, N, N, N, 'S')
  ,(@time_zone_id, N, N, N, 'S')
  ,(@time_zone_id, N, N, N, 'S')

Count: 147  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  INSERT INTO time_zone_transition_type (Time_zone_id, Transition_type_id, Offset, Is_DST, Abbreviation) VALUES
  (@time_zone_id, N, -N, N, 'S')
  ,(@time_zone_id, N, -N, N, 'S')
  ,(@time_zone_id, N, -N, N, 'S')
  ,(@time_zone_id, N, -N, N, 'S')
  ,(@time_zone_id, N, -N, N, 'S')
  ,(@time_zone_id, N, -N, N, 'S')
...

tオプション

指定された数だけのクエリーのみ表示します。
上位のスロークエリのみ抽出したい場合とかに便利です。

mysqldumpslow /var/lib/mysql/slow.log -t 3

# 3件のみ表示される
Count: 1  Time=15.00s (15s)  Lock=0.00s (0s)  Rows=5.0 (5), root[root]@localhost
  select sleep(N) from comments

Count: 2  Time=3.00s (6s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(N), comments.* from comments limit N

Count: 3  Time=3.00s (9s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select sleep(N), comments.id from comments limit N for update

まとめ

MySQLのスロークエリログを解析するツールであるmysqldumpslowの使い方について解説しました。

それではまた。
TomoProg

参考

3
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
3
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?