【ハンズオン】MySQLでスロークエリを見つけて改善してみよう

本記事の目的

ネットではEXPLAIN句の使い方やslow.logなど、それぞれの情報が散っていて、スロークエリの分析&パフォーマンス改善は初学者にはとっつきにくい印象があります。

そこで、今回は自分自身の備忘録的な意味合いも含めてSQLのスロークエリ分析＆改善の一連の流れを理解できるような記事を書いてみようと思います。

本記事を読むことで以下を ”ざっくり” 理解することができます。

• MySQLのスロークエリログ出力設定
• シェルスクリプト, mysqldumpslowを使ったログデータの抽出＆分析方法
• EXPLAIN句を使ってスロークエリを改善する方法

また、対象となる読者は以下を想定しています。

対象読者

• クエリチューニングの一連の流れを把握してみたい方
• フロントエンド/バックエンドエンジニアでクエリチューニングに興味がある方
• スタートアップで機能開発に注力する中で徐々にパフォーマンス改善が必要なフェーズに差し掛かっている方

留意事項
タイトルにもある通り、本記事ではサクッと全体感を把握し後学に繋げることを目標としています。そのため、詳細については他記事を参照いただければと思います。

今後もハンズオン系の記事を沢山書いていこうと思うので"いいね"頂ける喜びます...!

環境構築編

手元で実際に動かせるように本記事で用いるプロジェクトは以下のRepositoryを用意しています。適宜、ご利用ください。

ディレクトリ階層

root/
　├ .docker/
　│　└ init/
　│　　　└ init.sql # コンテナ起動時に実行される初期化用のクエリ
　│　└ Dockerfile
　│　└ my.cnf
　├ .env.example
　├ copy_env.sh # .env.exampleをコピーするシェルスクリプト
　├ docker-compose.yml
　└ Makefile

上記リポジトリーからクローン後に初期セットアップを行います。ローカル開発環境はDockerを利用しています。

ここではMakefileを用いて事前に定義済のdocker-composeコマンドを実行しています。

Terminal

# リポジトリをクローン
git clone [e-mail]:WebEngrChild/sample-slow-query.git

# .env.exampleをコピーして.envを作成
make copy_env

# 初期セットアップ
make init

Makefile

copy_env:
	sh copy_env.sh
init:
	@make build
	@make up
mysql:
	docker-compose exec sample-mysql mysql -uroot -ppass

docker-compose.yml

version: "3" # composeファイルのバージョン

services:
  sample-mysql:
    # コンテナ名を明示的に指定
    container_name: sample-mysql
    # Dockerfileからビルドすることを示す
    build: ./.docker/
    # コンテナにマウント
    volumes:
      # 初期化クエリ
      - ./.docker/init:/docker-entrypoint-initdb.d
      # 設定ファイル
      - ./.docker/my.cnf:/etc/mysql/conf.d/my.cnf
      # ログファイル
      - ./.docker/log:/var/log/mysql
      # データ永続化を指定（必要であれば）
#      - ./.docker/data:/var/lib/mysql
    environment:
      - MYSQL_ROOT_PASSWORD=${DB_PASS}

.docker/init/init.sqlに起動時の初期化のためのクエリを用意しています。

dockerのMySQL　Imageでは/docker-entrypoint-initdb.d/というディレクトリ内に初期化用のSQLやスクリプトを置くことで、最初にimageを起動したときにデータの初期化を自動的に行う仕組みがあります。

サンプルデータ作成

今回のイメージとしては、管理画面など検索機能のSELECT句 がボトルネックとなっているケースを想定しています。

簡単のため、テーブル構成自体もitemテーブル１つとシンプルなものとしています。

sql：init.sql

-- データベース作成
CREATE DATABASE sample;
use sample;

-- テーブル作成
CREATE TABLE item (
  id INT PRIMARY KEY AUTO_INCREMENT,
  name VARCHAR(10),
  description VARCHAR(30),
  price INT UNSIGNED,
  created_at DATETIME
);

-- ①16,384（2^14）件分の空データを挿入
INSERT INTO item () VALUES ();
INSERT INTO item (id) SELECT 0 FROM item;　-- 2行になる
INSERT INTO item (id) SELECT 0 FROM item;　-- 4行になる
INSERT INTO item (id) SELECT 0 FROM item;　-- 8行になる
...省略

-- ②空データを型に合わせてランダムな値に更新
UPDATE item SET
  name = CONCAT('商品', id),
  description = SUBSTRING(MD5(RAND()), 1, 30),
  price = CEIL(RAND() * 10000),
  created_at = ADDTIME(CONCAT_WS(' ','2014-01-01' + INTERVAL RAND() * 180 DAY, '00:00:00'), SEC_TO_TIME(FLOOR(0 + (RAND() * 86401))));

①の解説：
・idがprimary keyでAUTO_INCREMENTである必要がある
・２番目以降からは２の行数乗分空データが挿入される

②の解説：
・nameフィールド: 「商品」とレコードの「id」を連結したもの
・descriptionフィールド: ランダムな文字列 (MD5ハッシュ値) の最初の30文字
・priceフィールド: 1から10000までのランダムな数字の小数点以下を切り上げた値
・created_atフィールド: 「2014-01-01」から180日間のランダムな日付と「00:00:00」を結合し、そこに0から86,401秒 (1日) のランダムな時間を加えた値

スロークエリログを見てみよう

ここからが本題です。基本的にMySQLがデフォルトで用意している”スロークエリを出力するログ”を分析することから全てが始まります。

ログ出力設定の確認

本ハンズオンではすでに環境構築の段階でスロークエリを出力できる状態にしていますが、改めて内容を確認しておきます。設定ファイルはmy.cnfというファイル名です。該当部分のみ転記しています。

my.cnf

# ...省略
# スロークエリのログ設定
slow_query_log=1 #①
slow_query_log_file=/var/log/mysql/slow.log　#②
long_query_time=0.1　＃③
# ...省略

①： スロークエリの出力設定をONにしています。
②： スロークエリのログ出力先を指定しています。
③： どれくらいの時間を要したクエリを出力するかを指定しています。

留意事項
ここでは簡単のため、'0.1'秒という時間をスロークエリの閾値として定義しています。実際はアプリケーションの要件次第で適宜設定する必要があります。

クエリ実行

ようやく準備が整いました。それでは実際にクエリを実行していきます。

Terminal

# MySQLにログイン
make mysql

注意
make init直後だと以下のようなエラーが表示されログインできない場合があります。MySQLサーバーが起動するまでに時間がかかっている可能性があるため数分時間を置いて再度ログインしてください。

docker-compose exec sample-mysql mysql -uroot -ppass
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)
make: *** [mysql] Error 1

設定ファイルの確認も済んだことなので実際にクエリを実行します。

Terminal

# レコード数確認
mysql> USE sample;
mysql> SELECT COUNT(id) FROM item;
+-----------+
| COUNT(id) |
+-----------+
|   1048576 |
+-----------+
1 row in set (0.16 sec)

#　以下を複数回実行する
mysql> SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
110 rows in set (0.25 sec)

mysql> SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
110 rows in set (0.25 sec)

実行したクエリは非常に簡単なもので、かつ実行時間も0.25 secと非常に短いものですが、本ハンズオンでは当該クエリをアプリケーション上のボトルネックとなっているクエリと定義します。

ログ抽出

アプリケーションのパフォーマンス低下がクエリ起因と想定される場合、上記で設定したスロークエリのログファイルの中身からボトルネックになっているクエリを特定していきます。

今回では1種類のみのクエリを数回程度実行しただけなので、ログファイル内のデータは少ないですが、実際は膨大な数が格納されています。そのため、該当する箇所のみを抽出することが重要です。　

以下ではシェルスクリプトとmysqldumpslowツールを使った例をサンプルとして掲載します。

※実運用ではAWSのCLoudWatchを始め各種ログ解析ツール、S3などストレージ等の利用方法を理解する必要がありますが、ここではスコープ外といたします。

mysqldumpslowで抽出する例

mysqldumpslowは、MySQLデータベースサーバー用のユーティリティ・ツールです。このツールは、MySQLのスローログファイル（slow.log）を分析するのに役立ちます。

mysqldumpslowコマンドを使うことでログがわかりやすくサマリーされており、かつ便利なソート機能もいくつか用意されています。

名前	説明
t、at	クエリー時間または平均クエリー時間でソート
l、al	ロック時間または平均ロック時間でソート
r、ar	送信行数または平均送信行数でソート
c	カウントでソート

mysqldumpslow — スロークエリーログファイルの要約

Terminal

# 実行に有した時間でソート
mysqldumpslow -a -s t .docker/log/slow.log

# 実行結果
## ...省略
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  Time: 2023-01-30T09:29:48.724152Z
  # User@Host: root[root] @ localhost []  Id:     8
  # Query_time: 0.178250  Lock_time: 0.000008 Rows_sent: 110  Rows_examined: 1048686
  SET timestamp=1675070988;
  SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC
## ...省略

以下スクリプトの説明になります。
・-aを付与することで情報を非匿名化しています。このオプションを忘れると# Query_time: N.Nのように正しく表示されません。
・-s tはソート(-s)方法を実行時間(t)に指定しています。

■実行結果から読み取れること
今回見るポイントはこちらになります。
Count: 1に実行された回数、Time:に実行された時間、Query_timeクエリにかかった時間、Lock_timeロックしていた時間、Rows_sent、Rows_examinedと実行されたクエリが書かれています。

# ...一部抜粋
Time: 2023-01-30T09:29:48.724152Z
# Query_time: 0.178250  Lock_time: 0.000008 Rows_sent: 110  Rows_examined: 1048686
SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC

実行された時間も確認することで、ボトルネックとなっている当該SELECT句を見つけることができました。

シェルスクリプトで抽出する例

ログファイルからシェルスクリプトのgrepやawkコマンドを使って当該箇所を抽出する方法です。

(1)実行時間が遅い順にフィルターして取得する例

Terminal

# スクリプト
grep -n "Query_time:" .docker/log/slow.log | awk '$2 >= 0.1 {print $0}' | sort -k3 -rn;

# 実行結果
## ...一部省略
20:# Query_time: 0.708349  Lock_time: 0.000001 Rows_sent: 0  Rows_examined: 262144
15:# Query_time: 0.380758  Lock_time: 0.000002 Rows_sent: 0  Rows_examined: 131072
42:# Query_time: 0.215095  Lock_time: 0.000004 Rows_sent: 110  Rows_examined: 1048686
48:# Query_time: 0.178250  Lock_time: 0.000008 Rows_sent: 110  Rows_examined: 1048686
53:# Query_time: 0.164175  Lock_time: 0.000004 Rows_sent: 110  Rows_examined: 1048686

■スクリプト解説
・grepコマンドを使用して、.docker/log/slow.logファイルからQuery_time:という文字列を検索し、オプションで行番号を付加します(-n)。
・awkコマンドを使用して、第２列の条件($2 >= 0.1)に合致した該当行だけをそのまま抽出します。
・sortコマンドを使用して、結果を第3列($3)をキーに(-k3)で降順に(-r)並べ替えて数値(-n)としてソートしています。

■実行結果から読み取れること
・Rows_sentが0のものは結果が返されない or 表示されないクエリINSERT/UPDATEと思われるので該当箇所ではなさそう
・実際にクライアントに結果が返された数(Rows_sent)とSQLクエリ実行時にスキャンされた行数(Rows_examined)の数値に大きく乖離があるのも怪しそう

(2)select句が使われている箇所を特定する例

Terminal

# スクリプト
grep -n SELECT .docker/log/slow.log

# 実行結果
12:INSERT INTO item (id) SELECT 0 FROM item;
17:INSERT INTO item (id) SELECT 0 FROM item;
22:INSERT INTO item (id) SELECT 0 FROM item;
27:INSERT INTO item (id) SELECT 0 FROM item;
45:SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
50:SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
55:SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;

■実行結果から読み取れること
・上記(1)で返された以下と照らし合わせてみると45,50,55行目のSELECT句が怪しそう

42:# Query_time: 0.215095  Lock_time: 0.000004 Rows_sent: 110  Rows_examined: 1048686
48:# Query_time: 0.178250  Lock_time: 0.000008 Rows_sent: 110  Rows_examined: 1048686
53:# Query_time: 0.164175  Lock_time: 0.000004 Rows_sent: 110  Rows_examined: 1048686

EXPLAINでクエリを検証する

これまででボトルネックとなっているクエリを見つけることができました。

これからは具体的にどう改善すべきかさらに細かく見ていきます。

用いるのはSQLのEXPLAIN句になります。

EXPLAIN句を使用すると、MySQLがどのようにSQLクエリを解釈して実行するか、およびどのようなテーブルやインデックスが使用されるかなどの詳細な情報を得ることができます。

　Terminal

EXPLAIN SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;

# 実行結果
mysql> EXPLAIN SELECT id, name, price FROM item WHERE price >= 100 ORDER BY price DESC;
+----+-------------+-------+------------+------+---------------+------+---------+------+---------+----------+-----------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows    | filtered | Extra                       |
+----+-------------+-------+------------+------+---------------+------+---------+------+---------+----------+-----------------------------+
|  1 | SIMPLE      | item  | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 1008017 |    33.33 | Using where; Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+---------+----------+-----------------------------+

EXPLAIN句自体の説明はそれだけでかなりの説明になるので詳細は割愛させて頂きます。
ここで見るべきポイントは以下４つになります。

　

項目	概要説明	結果	結果_内容
type	MySQLがどのようにテーブルへアクセスするか	all	テーブルフルスキャン
possible_keys	オプティマイザが利用可能なインデックス候補	NULL	該当なし
key	実際に選択されたキー	NULL	該当なし
Extra	オプティマイザがどんな実行戦略を取ったのか	Using where; Using filesort	WHERE句の条件で絞り込んでいる。 行をフェッチしてから並び替えるファイルソートを利用。

■実行結果から読み取れること

• type　= allから=>　インデックスが正しく貼られていないことが分かります。その結果的に全件走査が実行されているようです。
• Using filesort => ソート対象となる行数が非常に多い中でのファイルソートが行われているようです。

以上を踏まえて、インデックスが正しく貼られていないことに起因するパフォーマンス劣化 であることが分かりました。

クエリ改善をしよう

検証結果から明らかになったように既存テーブルに対してインデックスを付与します。

# インデックス追加
mysql> ALTER TABLE item ADD INDEX idx_price (price);
Query OK, 0 rows affected (1.37 sec)
Records: 0  Duplicates: 0  Warnings: 0

それでは改めて改善結果を見てみます。

mysql> SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
112 rows in set (0.01 sec)

before: 0.25 sec
after : 0.01

クエリに有する時間が95%程度削減できました。

EXPLAIN句がどのように変化したのかも確認しましょう。

mysql> EXPLAIN SELECT id, name, price FROM item WHERE price >= 10000 ORDER BY price DESC;
+----+-------------+-------+------------+-------+---------------+-----------+---------+------+------+----------+--------------------------------------------+
| id | select_type | table | partitions | type  | possible_keys | key       | key_len | ref  | rows | filtered | Extra                                      |
+----+-------------+-------+------------+-------+---------------+-----------+---------+------+------+----------+--------------------------------------------+
|  1 | SIMPLE      | item  | NULL       | range | idx_price     | idx_price | 5       | NULL |  112 |   100.00 | Using index condition; Backward index scan |
+----+-------------+-------+------------+-------+---------------+-----------+---------+------+------+----------+--------------------------------------------+
1 row in set, 1 warning (0.01 sec)

　

項目	概要説明	結果	結果_内容
type	MySQLがどのようにテーブルへアクセスするか	range	インデックスを用いた範囲検索
possible_keys	オプティマイザが利用可能なインデックス候補	idx_price	idx_priceが候補として表示
key	実際に選択されたキー	idx_price	idx_priceが実際に利用されている
Extra	オプティマイザがどんな実行戦略を取ったのか	Using index condition; Backward index scan	indexを使って降順でスキャン

インデックスが正しく使用されていることが分かります。

いかがでしたでしょうか？

実運用だとさらに複雑な要素が絡んでいたり、EXPLAIN句もより詳細に見ていく必要がありますが、全体の流れはつかめたと思います。

参考記事