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

この記事は [MySQL Advent Calendar 2024](https://qiita.com/advent-calendar/2024/mysql) 10日目の記事です。

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

## 動作環境
```
mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.35    |
+-----------+
1 row in set (0.00 sec)
```
MySQL公式のDockerイメージを使っています。
実際に使用したDockerfileは[こちら](https://github.com/TomoProg/try-mysqldumpslow/blob/main/mysql/Dockerfile)

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

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

## 基本的な使い方
```
mysqldumpslow [options] [log_file ...]
```

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

```bash
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|出力のソート方法<br>`at` または `t`: クエリにかかった平均時間 または 合計時間<br>`al` または `l`: ロックにより待機していた平均時間 または 合計時間<br>`ar` または `r`: 読み込んだ平均行数 または 合計行数<br>`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

## 参考

https://dev.mysql.com/doc/refman/8.0/ja/mysqldumpslow.html

https://gihyo.jp/dev/serial/01/mysql-road-construction-news/0131