LoginSignup
2
2

More than 5 years have passed since last update.

@hmatsu47

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

Last updated at Posted at 2018-04-30

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

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

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

1. 今回取り上げるもの

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

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

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

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

と、MySQL 8.0 Reference Manual の、

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

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 毎に、何ミリ秒までの間にどれぐらいの割合で実行できているか」が分かるようになりました。

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

2
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
2