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

はじめに

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

題材

• isucon-privatea
• OS
  • Ububtu22系
• DB
  • Mysql8系

スロークエリとは

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

設定

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

[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

• スロークエリログを集計していい感じに各クエリを計測
• インストール

調査

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

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

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

# 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番時間がかかっているクエリ

# 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
  • 読み込んだテーブル行数

出力された項目については本家を参照

pt-query-digestを用いたスロークエリ調査の観点

• 1つのSQLが何回実行されたか
• SQLの実行時間
  • SQLのかかる時間 -> インデックスで解決できるか？
  • 1回は高速だが、何回も呼び出されているSQL -> N+1問題？

その後

遅いクエリを特定できたら、クエリの実行計画を確認して、さらに詳細に調査する。
実行計画の見方はDBMSと実行計画
を参照