「pt-query-digest」を使って最も遅いMySQLのクエリを特定する
2021-03-15
「pt-query-digest」を使って最も遅いmysqlのクエリを特定する
MySQLのインストール（Mac）
まずは、MacにMySQLのインストール
homebrewでインストールする
% brew install mysql
...
We've installed your MySQL database without a root password. To secure it run:
mysql_secure_installation
MySQL is configured to only allow connections from localhost by default
To connect run:
mysql -uroot
To have launchd start mysql now and restart at login:
brew services start mysql
Or, if you don't want/need a background service you can just run:
mysql.server start
サービスの起動
% brew services start mysql
これでログインできるようになった
% mysql -uroot Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 8 Server version: 8.0.23 Homebrew Copyright (c) 2000, 2021, Oracle and/or its affiliates. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql>
サンプルデータからデータベースを作成
こちらの記事を参考にサンプルデータをデータベースに入れてみる
※「%」から始まるコマンドはMacのシェルプロンプトから実行、「mysql>」から始まるコマンドはmysqlのプロンプトから実行する
※二つTerminal Windowを開いておくのがおすすめです
サンプルデータのインストール
% wget http://www.post.japanpost.jp/zipcode/dl/kogaki/zip/ken_all.zip
データの解凍
% unzip ken_all.zip
文字コードの変更
% iconv -f Shift_JIS -t UTF-8 KEN_ALL.CSV > /tmp/KEN_ALL_UTF8.CSV
データベースの枠を作成
mysql> CREATE DATABASE zipcode CHARACTER SET utf8mb4; Query OK, 1 row affected (0.00 sec)
データベースの見出しを定義
mysql> CREATE TABLE zipcode.zipcode(
-> code varchar(12) NOT NULL,
-> old_zipcode varchar(5) NOT NULL,
-> zip_code varchar(7) NOT NULL,
-> prefecture_kana varchar(255) NOT NULL,
-> city_kana varchar(255) NOT NULL,
-> town_kana varchar(255) NOT NULL,
-> prefecture varchar(128) NOT NULL,
-> city varchar(128) NOT NULL,
-> town varchar(128) NOT NULL
-> ) DEFAULT CHARACTER SET= utf8mb4;
Query OK, 0 rows affected (0.01 sec)
※コピペ用
CREATE TABLE zipcode.zipcode( code varchar(12) NOT NULL, old_zipcode varchar(5) NOT NULL, zip_code varchar(7) NOT NULL, prefecture_kana varchar(255) NOT NULL, city_kana varchar(255) NOT NULL, town_kana varchar(255) NOT NULL, prefecture varchar(128) NOT NULL, city varchar(128) NOT NULL, town varchar(128) NOT NULL ) DEFAULT CHARACTER SET= utf8mb4;
MySQL側の文字コードを設定
mysql> SET character_set_server= utf8mb4; Query OK, 0 rows affected (0.00 sec) mysql> SET NAMES utf8mb4; Query OK, 0 rows affected (0.00 sec)
作成した「zipcode」というデータベースを使うよ宣言
mysql> use zipcode Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql>
ここでデータを投入しようとしたら、「ERROR 1290 (HY000): The MySQL server is running with the –secure-file-priv option so it cannot execute this statement」のエラー
mysql> LOAD DATA INFILE '/tmp/KEN_ALL_UTF8.CSV' INTO TABLE zipcode.zipcode FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' (code, old_zipcode, zip_code, prefecture_kana, city_kana, town_kana, prefecture, city, town, @dummy, @dummy, @dummy, @dummy, @dummy, @dummy); ERROR 1290 (HY000): The MySQL server is running with the --secure-file-priv option so it cannot execute this statement
「secure_file_priv」の設定値を見るとNULLになっているので空にする
mysql> SELECT @@global.secure_file_priv; +---------------------------+ | @@global.secure_file_priv | +---------------------------+ | NULL | +---------------------------+ 1 row in set (0.00 sec) mysql>
mysql> set global secure_file_priv=""; ERROR 1238 (HY000): Variable 'secure_file_priv' is a read only variable mysql>
MySQLのプロンプトで設定しようとしたらエラーになってしまったので、こちらの記事を参考に対処
参考：[ MySQL ] データをCSVでエクスポートしようとして、secure-file-privに引っかかった件
設定ファイルの作成
% sudo cp /usr/local/opt/mysql/support-files/my-default.cnf /etc/my.cnf
中身を以下のように記載
% cat /etc/my.cnf [mysqld] secure-file-priv = ""
設定反映のためMySQLの再起動
% brew services restart mysql
無事に反映されていることを確認
mysql> SELECT @@global.secure_file_priv; +---------------------------+ | @@global.secure_file_priv | +---------------------------+ | | +---------------------------+ 1 row in set (0.00 sec) mysql>
今度はデータ投入に成功
mysql> LOAD DATA INFILE '/tmp/KEN_ALL_UTF8.CSV' INTO TABLE zipcode.zipcode FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' (code, old_zipcode, zip_code, prefecture_kana, city_kana, town_kana, prefecture, city, town, @dummy, @dummy, @dummy, @dummy, @dummy, @dummy); Query OK, 124568 rows affected (1.08 sec) Records: 124568 Deleted: 0 Skipped: 0 Warnings: 0 mysql>
中身もきちんと入っている
mysql> SELECT zip_code, prefecture, prefecture_kana, city, city_kana, town, town_kana FROM zipcode.zipcode ORDER BY zip_code LIMIT 3; +----------+------------+-----------------------+-----------------+-----------------------------+--------------------------------------+-----------------------------------------------+ | zip_code | prefecture | prefecture_kana | city | city_kana | town | town_kana | +----------+------------+-----------------------+-----------------+-----------------------------+--------------------------------------+-----------------------------------------------+ | 0010000 | 北海道 | ﾎｯｶｲﾄﾞｳ | 札幌市北区 | ｻｯﾎﾟﾛｼｷﾀｸ | 以下に掲載がない場合 | ｲｶﾆｹｲｻｲｶﾞﾅｲﾊﾞｱｲ | | 0010010 | 北海道 | ﾎｯｶｲﾄﾞｳ | 札幌市北区 | ｻｯﾎﾟﾛｼｷﾀｸ | 北十条西（１〜４丁目） | ｷﾀ10ｼﾞｮｳﾆｼ(1-4ﾁｮｳﾒ) | | 0010011 | 北海道 | ﾎｯｶｲﾄﾞｳ | 札幌市北区 | ｻｯﾎﾟﾛｼｷﾀｸ | 北十一条西（１〜４丁目） | ｷﾀ11ｼﾞｮｳﾆｼ(1-4ﾁｮｳﾒ) | +----------+------------+-----------------------+-----------------+-----------------------------+--------------------------------------+-----------------------------------------------+ 3 rows in set (0.08 sec) mysql>
「pt-query-digest」を使って最も遅いmysqlのクエリを特定する
それではこちらの記事を参考に、本題の、pt-query-digestを使ってみる
参考：第9回 pt-query-digestを使って遅いクエリーを発見する
まずは、「遅いクエリ」を「ログファイル」に書き出すための設定
遅いクエリをログとして出力する設定
mysql> set global slow_query_log=1; Query OK, 0 rows affected (0.01 sec)
1秒以上のクエリを遅いクエリと定義して記録する
mysql> set global long_query_time=1; Query OK, 0 rows affected (0.00 sec)
index未使用のクエリは遅いクエリとして記録する
mysql> set global log_queries_not_using_indexes=1; Query OK, 0 rows affected (0.00 sec)
遅いクエリを記録するファイルを定義
mysql> set global slow_query_log_file ='/usr/local/var/mysql/slow_query.log'; Query OK, 0 rows affected (0.00 sec)
ここまでで設定が完了したので、実際にクエリを3回ほど発行してみる
mysql> SELECT COUNT(*) FROM zipcode WHERE city='渋谷区' AND prefecture='東京都'; +----------+ | COUNT(*) | +----------+ | 121 | +----------+ 1 row in set (0.06 sec) mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150'; +----------+ | COUNT(*) | +----------+ | 0 | +----------+ 1 row in set (0.05 sec) mysql> SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150'; +----------+ | COUNT(*) | +----------+ | 0 | +----------+ 1 row in set (0.05 sec) mysql>
きちんとログとして出力されていることを確認
% cat /usr/local/var/mysql/slow_query.log /usr/local/opt/mysql/bin/mysqld, Version: 8.0.23 (Homebrew). started with: Tcp port: 3306 Unix socket: /tmp/mysql.sock Time Id Command Argument # Time: 2021-03-14T14:19:19.190985Z # User@Host: root[root] @ localhost [] Id: 8 # Query_time: 0.058439 Lock_time: 0.000102 Rows_sent: 1 Rows_examined: 124568 use zipcode; SET timestamp=1615731559; SELECT COUNT(*) FROM zipcode WHERE city='渋谷区' AND prefecture='東京都'; # Time: 2021-03-14T14:19:24.495346Z # User@Host: root[root] @ localhost [] Id: 8 # Query_time: 0.050539 Lock_time: 0.000149 Rows_sent: 1 Rows_examined: 124568 SET timestamp=1615731564; SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150'; # Time: 2021-03-14T14:19:31.153646Z # User@Host: root[root] @ localhost [] Id: 8 # Query_time: 0.051114 Lock_time: 0.000123 Rows_sent: 1 Rows_examined: 124568 SET timestamp=1615731571; SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150';
しかし、このままではどれが最も遅いクエリかわからないので、「pt-query-digest」を使って解析する
インストール
% brew install percona-toolkit
解析してみる
% pt-query-digest /usr/local/var/mysql/slow_query.log # A software update is available: # 310ms user time, 180ms system time, 38.08M rss, 4.13G vsz # Current date: Sun Mar 14 23:21:28 2021 # Hostname: hogehoge # Files: /usr/local/var/mysql/slow_query.log # Overall: 3 total, 2 unique, 0.25 QPS, 0.01x concurrency ________________ # Time range: 2021-03-14T14:19:19 to 2021-03-14T14:19:31 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 160ms 51ms 58ms 53ms 56ms 3ms 51ms # Lock time 374us 102us 149us 124us 144us 19us 119us # Rows sent 3 1 1 1 1 0 1 # Rows examine 364.95k 121.65k 121.65k 121.65k 121.65k 0 121.65k # Query size 186 54 78 62 76.28 11.62 51.63 # Profile # Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============= ===== ====== ==== # 1 0x6E321232B1E04173EDFEDB113DDF641D 0.1017 63.5% 2 0.0508 0.00 SELECT zipcode # 2 0xBEEF6137A7E4D93EB3E8CD045E2D1B43 0.0584 36.5% 1 0.0584 0.00 SELECT zipcode # Query 1: 0.29 QPS, 0.01x concurrency, ID 0x6E321232B1E04173EDFEDB113DDF641D at byte 699 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: 2021-03-14T14:19:24 to 2021-03-14T14:19:31 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 66 2 # Exec time 63 102ms 51ms 51ms 51ms 51ms 406us 51ms # Lock time 72 272us 123us 149us 136us 149us 18us 136us # Rows sent 66 2 1 1 1 1 0 1 # Rows examine 66 243.30k 121.65k 121.65k 121.65k 121.65k 0 121.65k # Query size 58 108 54 54 54 54 0 54 # String: # Databases zipcode # Hosts localhost # Users root # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms ################################################################ # 100ms # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `zipcode` LIKE 'zipcode'\G # SHOW CREATE TABLE `zipcode`.`zipcode`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT COUNT(*) FROM zipcode WHERE old_zipcode = '150'\G # Query 2: 0 QPS, 0x concurrency, ID 0xBEEF6137A7E4D93EB3E8CD045E2D1B43 at byte 0 # This item is included in the report because it matches --limit. # Scores: V/M = 0.00 # Time range: all events occurred at 2021-03-14T14:19:19 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 33 1 # Exec time 36 58ms 58ms 58ms 58ms 58ms 0 58ms # Lock time 27 102us 102us 102us 102us 102us 0 102us # Rows sent 33 1 1 1 1 1 0 1 # Rows examine 33 121.65k 121.65k 121.65k 121.65k 121.65k 0 121.65k # Query size 41 78 78 78 78 78 0 78 # String: # Databases zipcode # Hosts localhost # Users root # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms ################################################################ # 100ms # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `zipcode` LIKE 'zipcode'\G # SHOW CREATE TABLE `zipcode`.`zipcode`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT COUNT(*) FROM zipcode WHERE city='渋谷区' AND prefecture='東京都'\G
最初に全体のサマリ、その後にクエリごとの結果が記載されている
「Rank Query ID 」の結果とその後のクエリごとの結果を照らし合わせると、
「SELECT COUNT(*) FROM zipcode WHERE old_zipcode = ‘150’」のクエリに最も時間がかかったことがわかる
うん、便利だ。
以上。
