yoshiislandblog.net
元営業の駆け出しアラサーSEが、休日にMACと戯れた際の殴り書きメモ。日々勉強。日々進歩。
20210314_pt-query-digest_mysql_2

「pt-query-digest」を使って最も遅いMySQLのクエリを特定する

2021-03-15

「pt-query-digest」を使って最も遅いmysqlのクエリを特定する

  1. MySQLのインストール(Mac)
  2. サンプルデータからデータベースを作成
  3. 「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>

サンプルデータからデータベースを作成

こちらの記事を参考にサンプルデータをデータベースに入れてみる

参考:第2回 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  | 北海道     | ホッカイドウ               | 札幌市北区      | サッポロシキタク                   | 北十条西(1〜4丁目)               | キタ10ジョウニシ(1-4チョウメ)                           |
| 0010011  | 北海道     | ホッカイドウ               | 札幌市北区      | サッポロシキタク                   | 北十一条西(1〜4丁目)             | キタ11ジョウニシ(1-4チョウメ)                           |
+----------+------------+-----------------------+-----------------+-----------------------------+--------------------------------------+-----------------------------------------------+
3 rows in set (0.08 sec)

mysql>

20210314_pt-query-digest_mysql_1


「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

解析してみる

20210314_pt-query-digest_mysql_2

% 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’」のクエリに最も時間がかかったことがわかる

うん、便利だ。
以上。