kavo’s diary

備忘録

ISUCON練習 private-isu[2] スロークエリ解析、インデックス作成　～9315点

スロークエリログ設定

webapp\etc\my.cnfに追記

slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time = 0

出ないと思ったらパーミッション問題。

mysql: [Warning] World-writable config file '/etc/my.cnf' is ignored.

chmod 644 /etc/my.cnf ls -l /var/log/mysql/mysql-slow.log

これで出るようになった。ログをクリアしてベンチ。

初期状態のスロークエリ解析

pt-query-digestをdockerで実行。

docker run -it --rm -v $(pwd)/$mysql_log_dir/mysql-slow.log:/tmp/mysql-slow.log perconalab/percona-toolkit /bin/bash -c "pt-query-digest /tmp/mysql-slow.log --limit 20" > $mysql_log_dir/mysql-slow-analyze.log

# Profile
# Rank Query ID           Response time   Calls R/Call V/M   Item
# ==== ================== =============== ===== ====== ===== =============
#    1 0x16849282195BE09F 1214.9183 73.6%  1318 0.9218  0.46 SELECT comments
#    2 0x7539A5F45EB76A80  352.4430 21.4%  1346 0.2618  0.29 SELECT comments
#    3 0x839C127C71B69E75   37.5151  2.3%    61 0.6150  0.36 SELECT posts
#    6 0x3A976F5EBE87A97C    4.8459  0.3%    11 0.4405  0.36 SELECT comments
# MISC 0xMISC               40.9680  2.5% 21763 0.0019   0.0 <21 ITEMS>

上位SQLの実行計画取得。

インデックスを作ってみる

mysql -uroot -proot isuconp

ALTER TABLE comments ADD INDEX idx_post_created (post_id, created_at);

$  MSYS_NO_PATHCONV=1 docker run --network host -i private-isu-benchmarker /opt/go/bin/benchmarker -t http://host.docker.internal -u /opt/go/userdata
{"pass":true,"score":9659,"success":8170,"fail":0,"messages":[]}

スコアがプラスになった。

スロークエリ解析

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x839C127C71B69E75 30.2871 48.2%   765 0.0396  0.06 SELECT posts
#    2 0xB2ED5CF03D4E749F  5.7500  9.2%   242 0.0238  0.02 SELECT comments
#    3 0x99AA0165670CE848  5.7375  9.1% 88220 0.0001  0.00 ADMIN PREPARE
#    4 0xE070DA9421CA8C8D  4.0315  6.4% 43555 0.0001  0.00 SELECT users
#    5 0xB718D440CBBB5C55  3.5114  5.6%  3611 0.0010  0.01 SELECT posts
#    6 0x3027353C36CAB572  2.4114  3.8%    35 0.0689  0.11 SELECT posts
#    7 0x16849282195BE09F  2.0960  3.3% 18612 0.0001  0.00 SELECT comments
#    8 0x7539A5F45EB76A80  2.0318  3.2% 19310 0.0001  0.00 SELECT comments

元々の1,2位のクエリが7,8位まで下がった。

さらに追加

R/Callが比較的大きい以下を改善できそうなインデックスを追加。

  • 1 0x839C127C71B69E75 30.2871 48.2% 765 0.0396 0.06 SELECT posts
  • 2 0xB2ED5CF03D4E749F 5.7500 9.2% 242 0.0238 0.02 SELECT comments
  • 5 0xB718D440CBBB5C55 3.5114 5.6% 3611 0.0010 0.01 SELECT posts
  • 6 0x3027353C36CAB572 2.4114 3.8% 35 0.0689 0.11 SELECT posts
ALTER TABLE comments DROP INDEX idx_post_created;
CREATE INDEX idx_post_id_created_at ON comments (post_id, created_at DESC);
CREATE INDEX idx_posts_created_at ON posts (created_at DESC);
CREATE INDEX idx_comments_user_id ON comments (user_id);

{"pass":true,"score":9315,"success":7865,"fail":0,"messages":[]}

スコアあまり変化なし。

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x839C127C71B69E75 30.7378 52.8%   755 0.0407  0.06 SELECT posts
#    2 0x99AA0165670CE848  5.9871 10.3% 90271 0.0001  0.00 ADMIN PREPARE
#    3 0xE070DA9421CA8C8D  4.4016  7.6% 45531 0.0001  0.00 SELECT users
#    4 0xB718D440CBBB5C55  3.5164  6.0%  3528 0.0010  0.01 SELECT posts
#    5 0x7539A5F45EB76A80  2.1383  3.7% 19372 0.0001  0.00 SELECT comments
#    6 0x16849282195BE09F  2.1295  3.7% 18699 0.0001  0.00 SELECT comments
#    7 0x3027353C36CAB572  2.0670  3.6%    41 0.0504  0.04 SELECT posts
#    8 0x4097914B4DBD1C07  1.9715  3.4%    63 0.0313  0.06 INSERT posts
#    9 0xC67B1B05D2469241  1.4163  2.4%   248 0.0057  0.00 SELECT posts
#   10 0xAB05CA526E3FEDDC  1.3343  2.3%   214 0.0062  0.01 INSERT comments
#   11 0x80CA8067F971EA04  0.7754  1.3%   178 0.0044  0.00 INSERT users
#   12 0xE819735F00B6DBDF  0.5309  0.9%   248 0.0021  0.00 SELECT posts
#   13 0x111FD2D3F3B3B4EB  0.4868  0.8% 90271 0.0000  0.00 ADMIN CLOSE STMT
#   14 0x798DE77E477DF648  0.1663  0.3%     1 0.1663  0.00 DELETE posts
#   15 0x746D96521AE5B82C  0.1405  0.2%  2150 0.0001  0.00 SET
#   16 0x81F9D7F7FA80A53D  0.1245  0.2%   673 0.0002  0.00 SELECT comments
#   17 0xE5B367867F4BDDDD  0.0962  0.2%   554 0.0002  0.01 SELECT users
#   18 0x3A976F5EBE87A97C  0.0560  0.1%   248 0.0002  0.00 SELECT comments
#   19 0xB4BB2E774B30F1D4  0.0319  0.1%   248 0.0001  0.00 SELECT users
#   20 0xB2ED5CF03D4E749F  0.0316  0.1%   248 0.0001  0.00 SELECT comments

さっきの - 0xB2ED5CF03D4E749F 5.7500 9.2% 242 0.0238 0.02 SELECT comments が20位まで行ってる。

posts周りのインデックスは効いていないかも。

8以上なのでdescも有効のはず。

mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.34    |
+-----------+

mysql> select count(1) from posts;
+----------+
| count(1) |
+----------+
|    10063 |
+----------+

forceしたらようやく実行計画で有効になった。全行取ってくるクエリだから使わない方がマシ、という判断なのかな。

explain SELECT id, user_id, body, mime, created_at FROM posts FORCE INDEX (idx_posts_created_at) ORDER BY created_at DESC;