はじめに

Progaku Advent Calendar 2024の2日目の記事です！
isucon素振りでpt-query-digestを使用してスロークエリを分析する際に、毎回ログファイルを削除して実行という流れが面倒だったこと、実行毎に結果を記録したかったので、それらを行うスクリプトを作ったので簡単にまとめたいと思います。

pt-query-digestの概要、インストール方法は下記の記事が参考になります。

今回はMySQLで行いますので、別のRDBMSを使用している方はログファイルの場所など適宜読み替えていただけたらと思います！

シェルスクリプト作成

スクリプトの設置場所

binディレクトリに直接配置することも考えましたが、以下の理由から別の場所に配置しました

binはGitの管理対象外とすることが一般的なため
誤って他のバイナリを削除するリスクを避けるため

そのため、アプリケーションのソースコードが置かれている箇所にscriptsディレクトリを作成し、スクリプトを配置することにしました。bin直下には、そのスクリプトを参照するシンボリックリンクを配置します。

シンボリックリンクって何？
という方は下記を参照していただけたらと思います。

スクリプトファイルの作成

以下の手順でスクリプトを作成します

$ mkdir -p /home/isucon/scripts
$ touch /home/isucon/scripts/analyze-slow-query-log.sh
$ vim /home/isucon/scripts/analyze-slow-query-log.sh

スクリプト内容

analyze-slow-query-log.shの内容は以下の通りです

#!/bin/bash

# エラー発生時にスクリプトを終了
set -e

# ログ保存用ディレクトリを作成
mkdir -p ~/log

# スロークエリログを解析して結果を保存
echo "Analyzing slow query log and saving the result..."
sudo pt-query-digest /var/log/mysql/mysql-slow.log > ~/log/$(date +mysql-slow.log-%m-%d-%H-%M -d "+9 hours")

# 古いスロークエリログを削除
echo "Removing old slow query log..."
sudo rm /var/log/mysql/mysql-slow.log

# MySQLを再起動して新しいログを生成
echo "Restarting MySQL service to regenerate the slow query log..."
sudo systemctl restart mysql

# 完了メッセージ
echo "Script execution completed successfully."

補足説明

set -e
- スクリプト内でエラーが発生した場合にスクリプトを終了します。エラーが発生した時に気づくことができるように念の為入れておきます
mkdir -p ~/log
- -pオプションをつければ、指定したディレクトリが既に存在している場合でもエラーにならず、正常終了するようになります。また、中間ディレクトリがない場合は自動的に作成してくれます。初回実行時、以降も正常に動作するよう設定しました
date +mysql-slow.log-%m-%d-%H-%M -d "+9 hours"
- 現在時刻をフォーマットしてファイル名に含めるようにしました。-d "+9 hours"は日本時間（UTC+9）で表示できるようにするために設定しています。これで後から見た時に時間毎の結果を確認することができるようになります。ファイル名も衝突しなくなります
sudo pt-query-digest
- MySQLのスロークエリログを解析し、その結果を標準出力に表示します。この出力をリダイレクトしてファイルに保存するようにしてます
sudo systemctl restart mysql
- MySQLのサービスを再起動し、新しいスロークエリログを生成します

後は、正常に実行できたか、視覚的に判断できるように各工程で内容をechoで表示するようにしてます

実行権限の付与

スクリプトを実行可能にするためには実行権限が必要なので以下のコマンドを実行します

$ chmod +x /home/isucon/scripts/analyze-slow-query-log.sh

実行権限については下記の記事にまとめておりますので良かったら見てください

シンボリックリンクの作成

binディレクトリにシンボリックリンクを作成します：

$ ln -s /home/isucon/scripts/analyze-slow-query-log.sh /bin/analyze-slow-query-log

確認

$ ls -l /bin | grep analyze-slow-query-log
lrwxrwxrwx 1 root root 46 Nov 24 11:08 analyze-slow-query-log -> /home/isucon/scripts/analyze-slow-query-log.sh

正常にできていそうです。

bin直下は元々$PATH の参照に含まれているので、これだけでコマンド実行できるようになります。

実行テスト

作成したスクリプトを実行し、期待通り動作するか確認します

$ analyze-slow-query-log
Analyzing slow query log and saving the result...
/var/log/mysql/mysql-slow.log:  75% 00:09 remain
Restarting MySQL service to regenerate the slow query log...
Script execution completed successfully.

保存されたファイルを確認(説明用に3回ほど実行したので3つファイルができてます笑)
下記のように実行した日時毎に分析結果を残すことができます。

$ ls ~/log
mysql-slow.log-11-24-20-30  mysql-slow.log-11-24-20-31  mysql-slow.log-11-24-20-50

これで、スクリプトは完成です！

ファイルを見てみる

せっかくなので、分析結果を見てみます

# 11.6s user time, 30ms system time, 36.47M rss, 42.96M vsz
# Current date: Sun Nov 24 12:35:52 2024
# Hostname: ip-192-168-1-246
# Files: /var/log/mysql/mysql-slow.log
# Overall: 161.68k total, 94 unique, 759.08 QPS, 2.95x concurrency _______
# Time range: 2024-11-24T12:31:56 to 2024-11-24T12:35:29
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           627s     1us   859ms     4ms    16ms    11ms   925us
# Lock time          888ms       0    74ms     5us     1us   318us     1us
# Rows sent        167.71k       0   7.32k    1.06    0.99   30.37    0.99
# Rows examine      66.12M       0  14.02k  428.84   1.33k  926.75    1.96
# Query size        29.38M       5   1.94M  190.51  346.17   5.49k   54.21

# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0x84B457C910C4A79FC9EBECB8... 102.1298 16.3% 10875 0.0094  0.01 SELECT icons
#    2 0x4ADE2DC90689F1C4891749AF...  66.5847 10.6% 26883 0.0025  0.00 DELETE SELECT livecomments
#    3 0x42EF7D7D98FBCC9723BF896E...  66.1044 10.5%  3421 0.0193  0.01 SELECT records
#    4 0x38BC86A45F31C6B1EE324671...  63.1442 10.1%  9033 0.0070  0.00 SELECT themes
#    5 0x3D83BC87F3B3A00D571FFC81...  38.4090  6.1%  2651 0.0145  0.01 SELECT records
#    6 0xF1B8EF06D6CA63B24BFF433E...  34.4488  5.5%  2607 0.0132  0.04 SELECT users livestreams livecomments
#    7 0xDB74D52D39A7090F224C4DEE...  33.3438  5.3%  2609 0.0128  0.04 SELECT users livestreams reactions
#    8 0x64CC8A4E8E4B390203375597...  28.5551  4.6%   221 0.1292  0.01 SELECT ng_words
#    9 0xFBC5564AE716EAE82F20BFB4...  28.2169  4.5% 20329 0.0014  0.00 SELECT tags
#   10 0x59F1B6DD8D9FEC059E55B3BF...  24.2572  3.9%   407 0.0596  0.01 SELECT reservation_slots
#   11 0xEA1E6309EEEFF9A6831AD2FB...  13.2996  2.1%  8897 0.0015  0.00 SELECT users
#   12 0xFFFCA4D67EA0A788813031B8...  10.9758  1.7%  1734 0.0063  0.00 COMMIT
#   13 0xF7144185D9A142A426A36DC5...  10.7225  1.7%  5904 0.0018  0.00 SELECT livestream_tags
#   14 0x8F7679D452333ED3C7D60D22...  10.4510  1.7% 11479 0.0009  0.00 ADMIN RESET STMT
#   15 0x22279D81D51006139E0C7640...   8.9071  1.4%  3956 0.0023  0.00 SELECT domains domainmetadata
#   16 0x9EAD6C0CE525E3693EE27FFC...   8.5085  1.4%    69 0.1233  0.03 SELECT livestreams
#   17 0xD6032FE08E1FE706A928B8B7...   7.1180  1.1%  4724 0.0015  0.00 SELECT livestreams
#   18 0xD2A0864774622BA36F655749...   5.9126  0.9%  1131 0.0052  0.00 INSERT themes
#   19 0xA3401CA3ABCC04C3AB221DB8...   5.7727  0.9%    60 0.0962  0.07 UPDATE reservation_slots
#   20 0xDFFCC1D78939C4D781C7C583...   5.6549  0.9%  1000 0.0057  0.00 INSERT users
# MISC 0xMISC                         54.9624  8.8% 43694 0.0013   0.0 <74 ITEMS>

こんな感じで、処理に時間をかかっているクエリをランキング形式で良い感じに分析して可視化してくれます

3位の分析結果の詳細を見てみる

# Query 3: 34.56 QPS, 0.67x concurrency, ID 0x42EF7D7D98FBCC9723BF896EBFC51D24 at byte 24226196
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2024-11-24T12:33:50 to 2024-11-24T12:35:29
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2    3421
# Exec time     10     66s   717us   107ms    19ms    36ms    13ms    21ms
# Lock time      1    17ms       0     2ms     5us     1us    56us     1us
# Rows sent      0   1.02k       0       1    0.30    0.99    0.46       0
# Rows examine   6   4.41M   1.25k   1.38k   1.32k   1.33k   38.87   1.26k
# Query size     1 475.79k     131     209  142.42  158.58   10.31  136.99
# String:
# Databases    isudns
# Hosts        localhost
# Users        isudns
# Query_time distribution
#   1us
#  10us
# 100us  ###
#   1ms  #####################
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isudns` LIKE 'records'\G
#    SHOW CREATE TABLE `isudns`.`records`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='pipe.u.isucon.local' and domain_id=1\G

ざっくりとみる

特に重要になりそうな箇所だけ抜粋してみていきます

# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Exec time     10     66s   717us   107ms    19ms    36ms    13ms    21ms
# Rows sent      0   1.02k       0       1    0.30    0.99    0.46       0
# Rows examine   6   4.41M   1.25k   1.38k   1.32k   1.33k   38.87   1.26k

Exec time

このクエリ全体で処理にかかった合計時間は 66秒（3421回分の合計）です
1回あたりの平均実行時間は 19ms（0.019秒）で、最長で 107ms（0.107秒）になります

Rows sent

クエリ全体で返された行数の合計は1020件
1回あたりの平均は 0.3行なので、ほとんどのクエリは1行以下の結果しか返してないことがわかります

Rows examine

このクエリで読み込んだ行数の合計は 441万行です
1回あたりの平均は 1320行になります

たった1020の行しか返さないクエリで441万行も読み込んでいることから適切なインデックスが効いていない、無駄なデータ読み込みがある可能性がありそうです。

実行計画を見る

分析結果を下部に該当のクエリも掲載されているので実行計画を見ていきます

EXPLAIN SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='pipe.u.isucon.local' and domain_id=1

id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
1	SIMPLE	records	null	ALL	domain_id	null	null	null	1280	1	Using where

typeがALLとなっていて、フルスキャンになっていることがわかりました。
keyもnullなのでindexが貼られていないことがわかります。

WHEREで条件に指定されているnameとdisabledとdomain_idの３つです。
recordsテーブルを見るとdisabledは0、domain_idは1のレコードしか存在しなかったため、そもそもdisabledとdomain_idの条件が不要な可能性がありそうです。

WHERE disabled=0 and name='pipe.u.isucon.local' and domain_id=1

とりあえずnameのみindexを付与

ALTER TABLE records ADD INDEX name_idx (name);

フルスキャンは改善されています。
ただtypeがrefなのでまだ改善の余地がありそうです。(不要な条件をソースから消すとか)

id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered	Extra
1	SIMPLE	records	null	ref	domain_id,name_idx	name_idx	258	const	1	10	Using where

作ったスクリプト実行して、再度分析結果を見ると

after
#   17 0x3D83BC87F3B3A00D571FFC81...   9.0606  1.7% 10003 0.0009  0.00 SELECT records

before
#    3 0x42EF7D7D98FBCC9723BF896E...  66.1044 10.5%  3421 0.0193  0.01 SELECT records

トータル66秒かかってたクエリが9秒まで短縮されました
とりあえず、スクリプト作成の趣旨から脱線しそうなのでここまにします笑

まとめ

ということで後半かなり話が逸れましたが、無事、スロークエリ分析のスクリプト作成を行うことができました。
これで

スロークエリログの解析と結果の保存
古いスロークエリログの削除
MySQLの再起動による新しいログの生成
と手動で行う煩わしさから解放されそうです！