スロークエリログについて調べてみた

# はじめに
今回はMysqlのスロークエリの調査についてまとめてみました

# 題材
* [isucon-privatea](https://github.com/catatsuy/private-isu)
* OS
  - Ububtu22系
* DB
  - Mysql8系

# スロークエリとは
DBへのクエリのうち、時間がかかっているクエリのこと。


# 設定
* スロークエリをログに出力させる必要がある
* 設定ファイル`/etc/mysql/mysql.conf.d/mysqld.cnf`にスロークエリログについて設定する
* Mysqlプロセスを再起動して設定を反映させる

```conf
[mysqld]
# 0=出力OFF、1=出力ON
slow_query_log=1

# 秒数を指定。3秒以上時間がかかったクエリを出力する
# 0=すべてのSQLを出力
long_query_time=3

# スロークエリを出力するログファイルを指定
slow_query_log_file=/var/log/mysql/slow_query.log
```

# スロークエリログ調査
## SQL調査ツール:pt-query-digest
- スロークエリログを集計していい感じに各クエリを計測
- [インストール](https://docs.percona.com/percona-toolkit/installation.html)

## 調査
スロークエリログを指定してコマンド実行

```sh
pt-query-digest /var/log/mysql/slow_query.log > query.log
```

時間がかかったクエリのランキングを出力してくれる

```sql
# 22.1s user time, 200ms system time, 28.83M rss, 35.64M vsz
# Current date: Sat May 27 11:57:18 2023
# Hostname: app-go
# Files: /var/log/mysql/slow_query.log
# Overall: 569.29k total, 24 unique, 8.63k QPS, 2.02x concurrency ________
# Time range: 2023-05-27T02:50:12 to 2023-05-27T02:51:18
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           133s     1us    84ms   233us   761us     1ms    44us
# Lock time          663ms       0    18ms     1us     1us    39us       0
# Rows sent        680.90k       0      22    1.22    2.90    2.55    0.99
# Rows examine      17.83M       0  10.23k   32.84   10.84  545.73       0
# Query size        35.37M      17     242   65.14   80.10   26.44   65.89

# Profile
# Rank Query ID                     Response time Calls  R/Call V/M   Item
# ==== ============================ ============= ====== ====== ===== ====
#    1 0x624863D30DAC59FA1684928... 37.5165 28.2% 178356 0.0002  0.00 SELECT comments
#    2 0x422390B42D4DD86C7539A5F... 32.4973 24.4% 183500 0.0002  0.00 SELECT comments
#    3 0x396201721CD58410E070DA9... 24.0708 18.1% 161136 0.0001  0.00 SELECT users
#    4 0x54F58DF8DE8C3F7CBAF1E54... 20.3102 15.2%    853 0.0238  0.01 SELECT posts users
#    5 0x551E806A701FB924943DAD0...  6.4726  4.9%   5144 0.0013  0.00 SELECT posts users
#    6 0xC9383ACA6FF14C29E819735...  4.1810  3.1%    853 0.0049  0.00 SELECT posts
#    7 0x7792B2201BBA6508D27427A...  2.5058  1.9%   7243 0.0003  0.00 SELECT posts users
# MISC 0xMISC                        5.6331  4.2%  32209 0.0002   0.0 <17 ITEMS>

```
* Response Time
  - 実行時間、全体のSQL実行時間に占める割合
* Calls
  - 実行回数
* R/Call
  - 1回のクエリの実行時間


1番時間がかかっているクエリ

```sql
# Query 1: 2.92k QPS, 0.62x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 139656811
# Scores: V/M = 0.00
# Time range: 2023-05-27T02:50:17 to 2023-05-27T02:51:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         31  178356
# Exec time     28     38s    29us    36ms   210us   839us   641us    49us
# Lock time     33   225ms       0    18ms     1us     1us    54us       0
# Rows sent     15 105.90k       0       3    0.61    2.90    1.16       0
# Rows examine   0 105.90k       0       3    0.61    2.90    1.16       0
# Query size    39  14.08M      79      83   82.79   80.10    0.08   80.10
# String:
# Databases    isuconp
# Hosts        localhost
# Users        isuconp
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  ########################
#   1ms  ###
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
#    SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `comments` WHERE `post_id` = 33176 ORDER BY `created_at` DESC LIMIT 3\G
```

* Count
  - SQL実行回数
* Exec time
  - SQL実行時間
* Rows examine
  - 読み込んだテーブル行数

出力された項目については本家を[参照](https://docs.percona.com/percona-toolkit/pt-query-digest.html)


## pt-query-digestを用いたスロークエリ調査の観点
- 1つのSQLが何回実行されたか
- SQLの実行時間
  - SQLのかかる時間 -> インデックスで解決できるか？ 
  - 1回は高速だが、何回も呼び出されているSQL -> N+1問題？

# その後
遅いクエリを特定できたら、クエリの実行計画を確認して、さらに詳細に調査する。
実行計画の見方は[DBMSと実行計画](https://qiita.com/hot_study_man/items/dd4beab6a2bed6f4f382)
を参照