More than 5 years have passed since last update.

MySQL 8.0でSQL実行時間の分布（ヒストグラム）を確認する

Last updated at 2018-05-01Posted at 2018-04-30

先の記事、**「MySQL 8.0（8.0.3 RC以降）でpt-query-digestっぽいSQL統計情報を大雑把に見てみる」**の続きです。

なお、MySQL 8.0 で「ヒストグラム」というと、SQL の実行計画を決めるためにオプティマイザが使う「ヒストグラム統計」もあります。

MySQL 8.0.3 RCでオプティマイザのヒストグラム統計を使う

こちらは、今回の「SQL の実行時間の分布」とは全く別物です。ご注意ください。

1. 今回取り上げるもの

前回の記事では、正規化した SQL 毎に、

実行回数
総実行時間（レイテンシ合計）
平均レイテンシ
レイテンシ 95 / 99 / 99.9 パーセンタイル値
サンプル SQL（EXPLAIN用）

等を出力しましたが、レイテンシの分布がわからないと、SQL の実行時間がスキャン対象データ量に比例して線形に延びているのか、それとも「山が2つ（以上）ある＝スキャン対象データ量によって採用される実行計画が途中で変わっている」のかが分かりません。
Percona 社が出している pt-query-digest ではこのあたりの情報が出せますが、MySQL 自身でも 8.0 から似たような情報を出すことができるようになりましたので、今回はこれを取り上げます。

なお、前回参照した lefred さんの記事、

MySQL 8.0: Statements Latency Histograms

と、MySQL 8.0 Reference Manual の、

25.11.15.4 Statement Histogram Summary Tables

を参考にします。
※SQL の正規化がどの程度行われるかについて、気になる方はこちらもご覧ください。

MySQL 8.0.11 GAリリース記念／くだらない小ネタ（STATEMENT_DIGEST）

2. やってみる

前回の記事で使ったテーブル（セカンダリ INDEX のないもの）と SQL を使って、INSERT・UPDATEを実行して、それぞれの正規化 SQL 毎の実行時間（レイテンシ）の分布を見ます。
※TRUNCATE TABLE performance_schema.events_statements_summary_by_digest;によって、暗にTRUNCATE TABLE performance_schema.events_statements_histogram_by_digest;も実行されるようです。

2-1. 準備

SQL ファイル
- INSERT10,000 行
- 主キーでのUPDATE5,000 行
- 非キーでのUPDATE2,000 行

digest_test.sql（部分）

TRUNCATE TABLE digest_test.test_db;
TRUNCATE TABLE performance_schema.events_statements_summary_by_digest;
TRUNCATE TABLE performance_schema.events_statements_history;
SET AUTOCOMMIT=0;
INSERT INTO digest_test.test_db SET val = 95;
INSERT INTO digest_test.test_db SET val = 1375;
INSERT INTO digest_test.test_db SET val = 6076;
（中略）
INSERT INTO digest_test.test_db SET val = 1671;
COMMIT;
UPDATE digest_test.test_db SET val = 391 WHERE id = 3822;
UPDATE digest_test.test_db SET val = 5770 WHERE id = 1576;
UPDATE digest_test.test_db SET val = 9523 WHERE id = 7828;
（中略）
UPDATE digest_test.test_db SET val = 8262 WHERE id = 7446;
COMMIT;
UPDATE digest_test.test_db SET val = 2905 WHERE val = 3446;
UPDATE digest_test.test_db SET val = 6602 WHERE val = 8143;
UPDATE digest_test.test_db SET val = 9159 WHERE val = 4193;
（中略）
UPDATE digest_test.test_db SET val = 3256 WHERE val = 9796;
COMMIT;

テーブル作成

テーブル作成

mysql> CREATE DATABASE digest_test;
Query OK, 1 row affected (0.00 sec)

mysql> USE digest_test;
Database changed
mysql> CREATE TABLE test_db (id INT UNSIGNED PRIMARY KEY AUTO_INCREMENT, val INT UNSIGNED);
Query OK, 0 rows affected (0.01 sec)

2-2. 実行

SQL実行

$ mysql -u root -p digest_test < digest_test.sql

2-3. 結果確認

前回利用したsys.statement_analysisビューと結合して確認します。

結果確認その1

mysql> SELECT t1.*, t2.query
    -> FROM performance_schema.events_statements_histogram_by_digest t1
    -> JOIN sys.statement_analysis t2
    ->   ON t2.digest = t1.DIGEST
    -> WHERE (t2.query LIKE 'INSERT %' OR t2.query LIKE 'UPDATE %')
    ->   AND t1.COUNT_BUCKET > 0
    -> ORDER BY t2.total_latency DESC, t1.BUCKET_NUMBER\G
*************************** 1. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: 39ee5b41b81eb0177ddd2cab3c87ff0744d9d7c69d4243feecc00adb112a883c
         BUCKET_NUMBER: 133
      BUCKET_TIMER_LOW: 4365158322
     BUCKET_TIMER_HIGH: 4570881896
          COUNT_BUCKET: 62
COUNT_BUCKET_AND_LOWER: 62
       BUCKET_QUANTILE: 0.031000
                 query: UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ?
*************************** 2. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: 39ee5b41b81eb0177ddd2cab3c87ff0744d9d7c69d4243feecc00adb112a883c
         BUCKET_NUMBER: 134
      BUCKET_TIMER_LOW: 4570881896
     BUCKET_TIMER_HIGH: 4786300923
          COUNT_BUCKET: 953
COUNT_BUCKET_AND_LOWER: 1015
       BUCKET_QUANTILE: 0.507500
                 query: UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ?
*************************** 3. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: 39ee5b41b81eb0177ddd2cab3c87ff0744d9d7c69d4243feecc00adb112a883c
         BUCKET_NUMBER: 135
      BUCKET_TIMER_LOW: 4786300923
     BUCKET_TIMER_HIGH: 5011872336
          COUNT_BUCKET: 974
COUNT_BUCKET_AND_LOWER: 1989
       BUCKET_QUANTILE: 0.994500
                 query: UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ?
*************************** 4. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: 39ee5b41b81eb0177ddd2cab3c87ff0744d9d7c69d4243feecc00adb112a883c
         BUCKET_NUMBER: 136
      BUCKET_TIMER_LOW: 5011872336
     BUCKET_TIMER_HIGH: 5248074602
          COUNT_BUCKET: 11
COUNT_BUCKET_AND_LOWER: 2000
       BUCKET_QUANTILE: 1.000000
                 query: UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ?
*************************** 5. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: 810c6c33e68ebfc59eb88dcf70559678d333651f0180f6bd50db18c1c36f69ab
         BUCKET_NUMBER: 36
      BUCKET_TIMER_LOW: 50118723
     BUCKET_TIMER_HIGH: 52480746
          COUNT_BUCKET: 1
COUNT_BUCKET_AND_LOWER: 1
       BUCKET_QUANTILE: 0.000100
                 query: INSERT INTO `digest_test` . `test_db` SET `val` = ?
（中略）
*************************** 61. row ***************************
           SCHEMA_NAME: digest_test
                DIGEST: f19b14bedfea94d9947ee0c83c75ab4ded31b8417bc75410c5079395fe4398fe
         BUCKET_NUMBER: 91
      BUCKET_TIMER_LOW: 630957344
     BUCKET_TIMER_HIGH: 660693448
          COUNT_BUCKET: 1
COUNT_BUCKET_AND_LOWER: 5000
       BUCKET_QUANTILE: 1.000000
                 query: UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?
61 rows in set (0.01 sec)

これだと見づらいので、ヒストグラム形式で見てみます。

結果確認その2・ヒストグラム

mysql> SELECT t2.query,
    ->   CONCAT('<',ROUND(t1.BUCKET_TIMER_HIGH/1000000000,4),'ms') as 'QRT',
    ->   CONCAT(RPAD('',ROUND(t1.BUCKET_QUANTILE*100),'*'),ROUND(t1.BUCKET_QUANTILE*100,2),"%") bar,
    ->   COUNT(t1.DIGEST) OVER(PARTITION BY t1.DIGEST) as TOT
    -> FROM performance_schema.events_statements_histogram_by_digest t1
    -> JOIN sys.statement_analysis t2
    ->   ON t2.digest = t1.DIGEST
    -> WHERE (t2.query LIKE 'INSERT %' OR t2.query LIKE 'UPDATE %')
    ->   AND t1.COUNT_BUCKET > 0
    -> ORDER BY t2.total_latency DESC, t1.DIGEST, t1.BUCKET_TIMER_HIGH DESC;
+----------------------------------------------------------------+-----------+-------------------------------------------------------------------------------------------------------------+-----+
| query                                                          | QRT       | bar                                                                                                         | TOT |
+----------------------------------------------------------------+-----------+-------------------------------------------------------------------------------------------------------------+-----+
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ? | <5.2481ms | ****************************************************************************************************100.00% |   4 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ? | <5.0119ms | ***************************************************************************************************99.45%   |   4 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ? | <4.7863ms | ***************************************************50.75%                                                   |   4 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `val` = ? | <4.5709ms | ***3.10%                                                                                                    |   4 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.7378ms | ****************************************************************************************************100.00% |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.5849ms | ****************************************************************************************************99.98%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.5136ms | ****************************************************************************************************99.95%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.3804ms | ****************************************************************************************************99.94%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.3183ms | ****************************************************************************************************99.91%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <1.2589ms | ****************************************************************************************************99.86%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.7586ms | ****************************************************************************************************99.83%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.4786ms | ****************************************************************************************************99.82%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.2754ms | ****************************************************************************************************99.81%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1514ms | ****************************************************************************************************99.80%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1445ms | ****************************************************************************************************99.78%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1380ms | ****************************************************************************************************99.77%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1318ms | ****************************************************************************************************99.76%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1259ms | ****************************************************************************************************99.75%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1202ms | ****************************************************************************************************99.70%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1148ms | ****************************************************************************************************99.62%  |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1096ms | ***************************************************************************************************99.36%   |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1047ms | ***************************************************************************************************99.16%   |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.1000ms | **************************************************************************************************98.46%    |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0955ms | *************************************************************************************************97.18%     |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0912ms | ***********************************************************************************************94.97%       |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0871ms | *******************************************************************************************91.37%           |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0832ms | *************************************************************************************85.37%                 |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0794ms | *****************************************************************************77.14%                         |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0759ms | *********************************************************************69.34%                                 |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0724ms | ****************************************************************63.95%                                      |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0692ms | *****************************************************52.61%                                                 |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0661ms | **********************************33.63%                                                                    |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0631ms | ***************15.31%                                                                                       |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0603ms | *********9.22%                                                                                              |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0575ms | ***3.32%                                                                                                    |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0550ms | 0.12%                                                                                                       |  33 |
| INSERT INTO `digest_test` . `test_db` SET `val` = ?            | <0.0525ms | 0.01%                                                                                                       |  33 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.6607ms | ****************************************************************************************************100.00% |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.6310ms | ****************************************************************************************************99.98%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.3162ms | ****************************************************************************************************99.96%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1995ms | ****************************************************************************************************99.94%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1905ms | ****************************************************************************************************99.92%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1820ms | ****************************************************************************************************99.90%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1738ms | ****************************************************************************************************99.88%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1660ms | ****************************************************************************************************99.82%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1585ms | ****************************************************************************************************99.70%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1514ms | ****************************************************************************************************99.64%  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1445ms | ***************************************************************************************************99.40%   |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1380ms | ***************************************************************************************************99.04%   |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1318ms | **************************************************************************************************98.18%    |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1259ms | ************************************************************************************************96.34%      |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1202ms | **********************************************************************************************93.68%        |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1148ms | ******************************************************************************************90.00%            |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1096ms | ************************************************************************************84.34%                  |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1047ms | **************************************************************************74.46%                            |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.1000ms | ************************************************************59.52%                                          |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.0955ms | ************************************************47.58%                                                      |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.0912ms | ********************************31.58%                                                                      |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.0871ms | ***********11.22%                                                                                           |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.0832ms | *0.80%                                                                                                      |  24 |
| UPDATE `digest_test` . `test_db` SET `val` = ? WHERE `id` = ?  | <0.0794ms | 0.02%                                                                                                       |  24 |
+----------------------------------------------------------------+-----------+-------------------------------------------------------------------------------------------------------------+-----+
61 rows in set (0.01 sec)

pt-query-digest のように縦軸（実行時間）の目盛りは固定ではなく可変になるのと、分布をそのまま示すのではなく「積み上げ」で示す形になっていますが、「正規化した SQL 毎に、何ミリ秒までの間にどれぐらいの割合で実行できているか」が分かるようになりました。

今回テストしたケースでは（結合等もないので）実行計画が途中で切り替わっている様子はないのですが、切り替わっている場合はグラフ（右端）が波状になるか、縦軸（実行時間）の間隔が極端に広がっている箇所があるはずです。

Qiitaに投稿したMySQL 8.0関連記事

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up