MySQLでPerformance_Schemaから過去に実行したSQLを把握する

MySQLに、OracleのSTATSPACK的なもの、ないの？というアレ。

Oracle文化が根強いSIerと一緒にMySQL案件に関わると質問される5つのこと - なからなLifeで触れた、アレのお話です。

「STATSPACK」に例えられる要件にもレベルがあって、私が質問を受ける文脈としては、「遅かったSQLを、誰が流したか、その時の実行計画も合わせて知りたい」というケースが多いので、STATSPACK level 6以上、という感じでしょうか。

「アドバイスも」なんて話もついてくるので、Diagnostics Packの「SQLチューニング・アドバイザ」もイメージした要求なのかもしれません。

いずれにせよ、MySQLのCommunity版を採用しておきながら、ムシのいい話です。

Enterprise版を採用すれば解決するのかどうか、私もまだ知らないんですけどね。

とにかく無償の範囲でできることを調べたいと思います。

今回も、いつものLinux版 MySQL5.6.31です。

過去に実行したSQLを参照する

Perfomance_Schemaで、setup_consumersから

events_statements_history　（Thread毎に10件）
events_statements_history_long　（Thread毎に10000件）

をENABLED=YESにすると、過去に実行されたSQLの中身が確認できるようになります。
（デフォルトではevents_statements_currentだけが有効です）

以下のような定義で、「SQL_TEXT列」に、実行したSQLが格納されています。

mysql> show create table events_statements_history_long\G
*************************** 1. row ***************************
       Table: events_statements_history_long
Create Table: CREATE TABLE `events_statements_history_long` (
  `THREAD_ID` bigint(20) unsigned NOT NULL,
  `EVENT_ID` bigint(20) unsigned NOT NULL,
  `END_EVENT_ID` bigint(20) unsigned DEFAULT NULL,
  `EVENT_NAME` varchar(128) NOT NULL,
  `SOURCE` varchar(64) DEFAULT NULL,
  `TIMER_START` bigint(20) unsigned DEFAULT NULL,
  `TIMER_END` bigint(20) unsigned DEFAULT NULL,
  `TIMER_WAIT` bigint(20) unsigned DEFAULT NULL,
  `LOCK_TIME` bigint(20) unsigned NOT NULL,
  `SQL_TEXT` longtext,
  `DIGEST` varchar(32) DEFAULT NULL,
  `DIGEST_TEXT` longtext,
  `CURRENT_SCHEMA` varchar(64) DEFAULT NULL,
  `OBJECT_TYPE` varchar(64) DEFAULT NULL,
  `OBJECT_SCHEMA` varchar(64) DEFAULT NULL,
  `OBJECT_NAME` varchar(64) DEFAULT NULL,
  `OBJECT_INSTANCE_BEGIN` bigint(20) unsigned DEFAULT NULL,
  `MYSQL_ERRNO` int(11) DEFAULT NULL,
  `RETURNED_SQLSTATE` varchar(5) DEFAULT NULL,
  `MESSAGE_TEXT` varchar(128) DEFAULT NULL,
  `ERRORS` bigint(20) unsigned NOT NULL,
  `WARNINGS` bigint(20) unsigned NOT NULL,
  `ROWS_AFFECTED` bigint(20) unsigned NOT NULL,
  `ROWS_SENT` bigint(20) unsigned NOT NULL,
  `ROWS_EXAMINED` bigint(20) unsigned NOT NULL,
  `CREATED_TMP_DISK_TABLES` bigint(20) unsigned NOT NULL,
  `CREATED_TMP_TABLES` bigint(20) unsigned NOT NULL,
  `SELECT_FULL_JOIN` bigint(20) unsigned NOT NULL,
  `SELECT_FULL_RANGE_JOIN` bigint(20) unsigned NOT NULL,
  `SELECT_RANGE` bigint(20) unsigned NOT NULL,
  `SELECT_RANGE_CHECK` bigint(20) unsigned NOT NULL,
  `SELECT_SCAN` bigint(20) unsigned NOT NULL,
  `SORT_MERGE_PASSES` bigint(20) unsigned NOT NULL,
  `SORT_RANGE` bigint(20) unsigned NOT NULL,
  `SORT_ROWS` bigint(20) unsigned NOT NULL,
  `SORT_SCAN` bigint(20) unsigned NOT NULL,
  `NO_INDEX_USED` bigint(20) unsigned NOT NULL,
  `NO_GOOD_INDEX_USED` bigint(20) unsigned NOT NULL,
  `NESTING_EVENT_ID` bigint(20) unsigned DEFAULT NULL,
  `NESTING_EVENT_TYPE` enum('STATEMENT','STAGE','WAIT') DEFAULT NULL
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

公式ドキュメントでいうと、このへんの話です。
MySQL :: MySQL 5.6 リファレンスマニュアル :: 22.9.6 パフォーマンススキーマステートメントイベントテーブル

なお、完全なSQL文を見る場合は、「SQL_TEXT」列を見ます。
「DIGEST_TEXT」列もSQL文が見えますが、Where条件に指定した値などは？で表示されます。

実行タイミングの確認とsys.format_time関数

TIMER_START、TIMER_ENDという列があるのですが、ここに出てくるのは、「サーバー起動からの経過時間」、しかもデフォルトで「ピコ秒(1兆分の1秒) 」です。

sysスキーマをセットアップしておくと、format_timeというストアドファンクションがありますので、これを使うと見やすい単位で返してくれます。
どんな単位で値を返してくるかは、実際にformat_time関数に渡されるピコ秒の値次第で変化します。

これはソースを見るとよく分かります。

mysql> show create function sys.format_time\G
*************************** 1. row ***************************
            Function: format_time
            sql_mode: STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION
     Create Function: CREATE DEFINER=`dbauser`@`%` FUNCTION `format_time`(
        
        
        picoseconds TEXT
    ) RETURNS text CHARSET utf8
    NO SQL
    DETERMINISTIC
    SQL SECURITY INVOKER
    COMMENT '\n             Description\n             -----------\n\n             Takes a raw picoseconds value, and converts it to a human readable form.\n             \n             Picoseconds are the precision that all latency values are printed in \n             within Performance Schema, however are not user friendly when wanting\n             to scan output from the command line.\n\n             Parameters\n             -----------\n\n             picoseconds (TEXT): \n               The raw picoseconds value to convert.\n\n             Returns\n             -----------\n\n             TEXT\n\n             Example\n             -----------\n\n             mysql> select format_time(342342342342345);\n             +------------------------------+\n             | format_time(342342342342345) |\n             +------------------------------+\n             | 00:05:42                     |\n             +------------------------------+\n             1 row in set (0.00 sec)\n\n             mysql> select format_time(342342342);\n             +------------------------+\n             | format_time(342342342) |\n             +------------------------+\n             | 342.34 us              |\n             +------------------------+\n             1 row in set (0.00 sec)\n\n             mysql> select format_time(34234);\n              +--------------------+\n             | format_time(34234) |\n             +--------------------+\n             | 34.23 ns           |\n             +--------------------+\n             1 row in set (0.00 sec)\n            '
BEGIN
  IF picoseconds IS NULL THEN RETURN NULL;
  ELSEIF picoseconds >= 604800000000000000 THEN RETURN CONCAT(ROUND(picoseconds / 604800000000000000, 2), ' w');
  ELSEIF picoseconds >= 86400000000000000 THEN RETURN CONCAT(ROUND(picoseconds / 86400000000000000, 2), ' d');
  ELSEIF picoseconds >= 3600000000000000 THEN RETURN CONCAT(ROUND(picoseconds / 3600000000000000, 2), ' h');
  ELSEIF picoseconds >= 60000000000000 THEN RETURN CONCAT(ROUND(picoseconds / 60000000000000, 2), ' m');
  ELSEIF picoseconds >= 1000000000000 THEN RETURN CONCAT(ROUND(picoseconds / 1000000000000, 2), ' s');
  ELSEIF picoseconds >= 1000000000 THEN RETURN CONCAT(ROUND(picoseconds / 1000000000, 2), ' ms');
  ELSEIF picoseconds >= 1000000 THEN RETURN CONCAT(ROUND(picoseconds / 1000000, 2), ' us');
  ELSEIF picoseconds >= 1000 THEN RETURN CONCAT(ROUND(picoseconds / 1000, 2), ' ns');
  ELSE RETURN CONCAT(picoseconds, ' ps');
  END IF;
END
character_set_client: utf8
collation_connection: utf8_general_ci
  Database Collation: utf8_general_ci
1 row in set (0.06 sec)

サーバ起動からの経過時間を「時刻」に直したい

残念ながら、ダイレクトに時刻に直す方法が見当たりませんでした。

ということで、現在日時時点でのサーバ起動からの経過時間を元に、その差異から、そのSQLの実行時刻を算出することにします。

現在の日時

現在の日時はsysdate関数やnow関数を使えばわかります。
https://dev.mysql.com/doc/refman/5.6/ja/date-and-time-functions.html#function_sysdate
https://dev.mysql.com/doc/refman/5.6/ja/date-and-time-functions.html#function_now
now関数とsysdate関数の違いについて触れると本題からそれるので、ドキュメントを参照してください。

サーバ起動からの経過時間

現時点の「サーバ起動からの経過時間」は、サーバーステータス変数「Uptime」に保持していますので、「SHOW GLOBAL STATUS LIKE 'Uptime'」で確認できます。
単位は「秒」です。

Uptime

サーバーが作動している秒数。
MySQL :: MySQL 5.6 リファレンスマニュアル :: 5.1.6 サーバーステータス変数

なお、「SHOW GLOBAL STATUS」は、「information_schema.GLOBAL_STATUS」から取得できます。

SQLの中で計算させたいので、SHOWコマンドよりもSELECTで引いてこれる方が都合がいいですね。

mysql> show create table GLOBAL_STATUS\G
*************************** 1. row ***************************
       Table: GLOBAL_STATUS
Create Table: CREATE TEMPORARY TABLE `GLOBAL_STATUS` (
  `VARIABLE_NAME` varchar(64) NOT NULL DEFAULT '',
  `VARIABLE_VALUE` varchar(1024) DEFAULT NULL
) ENGINE=MEMORY DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql> SELECT * FROM GLOBAL_STATUS WHERE VARIABLE_NAME = 'Uptime'; SHOW GLOBAL STATUS LIKE 'Uptime';
+---------------+----------------+
| VARIABLE_NAME | VARIABLE_VALUE |
+---------------+----------------+
| UPTIME        | 513            |
+---------------+----------------+
1 row in set (0.00 sec)

+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Uptime        | 513   |
+---------------+-------+
1 row in set (0.00 sec)

VARIABLE_NAMEが大文字統一だったり、小文字混じりだったり。
そして、どっちでも検索にヒットしてしまう。

うーん、この。。。

SQL実行時の時刻を導出する

材料は揃いました。
SQLの実行時刻[[年月日時分秒]
= 現在時刻[年月日時分秒] - （現時点のサーバ起動からの経過時間[秒] - SQL実行開始時点のサーバ起動からの経過時間[ピコ秒]）

が、単位を揃えなくてはいけません。

sys.format_time関数は、戻り値の単位が安定しないので使えません。素直に１兆分の１(/10^12)して秒に換算しましょう。

現時点のサーバ起動からの経過時間[秒] - SQL実行開始時点のサーバ起動からの経過時間[秒]は、現在時点の何秒前にSQLを実行したか、になります。

SQLの実行時刻[[年月日時分秒]
= 現在時刻[年月日時分秒] - （現時点のサーバ起動からの経過時間[秒] - SQL実行開始時点のサーバ起動からの経過時間[ピコ秒]/10^12）
= 現在時刻[年月日時分秒] - 現在時点の何秒前にSQLを実行したか

時刻に対する加算減算は、DATE_ADD関数が使えるようです。

DATE_ADD(date,INTERVAL expr unit), DATE_SUB(date,INTERVAL expr unit)

これらの関数は日付演算を実行します。date 引数は、開始日付値または開始日付時間値を指定します。expr は、開始日付から加算または減算される間隔値を指定する式です。expr は文字列であり、負の間隔の場合は「-」で始めることができます。unit は、式を解釈する際の単位を示すキーワードです。
MySQL :: MySQL 5.6 リファレンスマニュアル :: 12.7 日付および時間関数

これに倣って
SQLの実行時刻[[年月日時分秒]
= 現在時刻[年月日時分秒] - （現時点のサーバ起動からの経過時間[秒] - SQL実行開始時点のサーバ起動からの経過時間[ピコ秒]/10^12）
= 現在時刻[年月日時分秒] - 現在時点の何秒前にSQLを実行したか[秒]
= DATE_ADD(現在時刻[年月日時分秒] INTERVAL 現在時点の何秒前にSQLを実行したか[秒] SECOND)
= DATE_ADD(SYSDATE() INTERVAL -現在時点の何秒前にSQLを実行したか[秒] SECOND)

とすると、

SELECT DATE_ADD(SYSDATE(),INTERVAL -((SELECT VARIABLE_VALUE FROM information_schema.GLOBAL_STATUS WHERE VARIABLE_NAME = 'Uptime') - eshl.TIMER_START*POW(10,-12)) SECOND) as result
FROM performance_schema.events_statements_history_long eshl

といった感じになりました。

もう少しラクにならないんでしょうか！？

ていうか、最初からシステム日付で持ってていただけませんかね。（パフォーマンスを考慮してピコ秒管理にした、という記述がマニュアル上にあるのは知ってます）

あと、「誰が」を取る方法が未解決です。
昔のTHREAD_IDがあっても、その時点のTHREAD-PROCESS-HOST-USERに紐付ける情報がないのに、それが何の役に立つというのか。。。

「誰が」のところは、OracleのSTATSPACKでも対応してないっけ？

ニーズは尽きないのですが、

「いつ」の要件を「初めて実行された日時、最後に実行された日時」
「どんなSQL」を、可変部分（Where条件）をサマリしてよい
「誰が」はわからなくてもよい

など、条件を緩めると、もっと簡単に情報が取れるテーブルがあります。

「performance_schema.events_statements_summary_by_digest」

yoku0825さん絶賛のテーブルです。
日々の覚書: MySQLのperformance_schemaでどれくらいの情報が見られるのか

テーブル定義は以下のとおり。

mysql> show create table events_statements_summary_by_digest\G
*************************** 1. row ***************************
       Table: events_statements_summary_by_digest
Create Table: CREATE TABLE `events_statements_summary_by_digest` (
  `SCHEMA_NAME` varchar(64) DEFAULT NULL,
  `DIGEST` varchar(32) DEFAULT NULL,
  `DIGEST_TEXT` longtext,
  `COUNT_STAR` bigint(20) unsigned NOT NULL,
  `SUM_TIMER_WAIT` bigint(20) unsigned NOT NULL,
  `MIN_TIMER_WAIT` bigint(20) unsigned NOT NULL,
  `AVG_TIMER_WAIT` bigint(20) unsigned NOT NULL,
  `MAX_TIMER_WAIT` bigint(20) unsigned NOT NULL,
  `SUM_LOCK_TIME` bigint(20) unsigned NOT NULL,
  `SUM_ERRORS` bigint(20) unsigned NOT NULL,
  `SUM_WARNINGS` bigint(20) unsigned NOT NULL,
  `SUM_ROWS_AFFECTED` bigint(20) unsigned NOT NULL,
  `SUM_ROWS_SENT` bigint(20) unsigned NOT NULL,
  `SUM_ROWS_EXAMINED` bigint(20) unsigned NOT NULL,
  `SUM_CREATED_TMP_DISK_TABLES` bigint(20) unsigned NOT NULL,
  `SUM_CREATED_TMP_TABLES` bigint(20) unsigned NOT NULL,
  `SUM_SELECT_FULL_JOIN` bigint(20) unsigned NOT NULL,
  `SUM_SELECT_FULL_RANGE_JOIN` bigint(20) unsigned NOT NULL,
  `SUM_SELECT_RANGE` bigint(20) unsigned NOT NULL,
  `SUM_SELECT_RANGE_CHECK` bigint(20) unsigned NOT NULL,
  `SUM_SELECT_SCAN` bigint(20) unsigned NOT NULL,
  `SUM_SORT_MERGE_PASSES` bigint(20) unsigned NOT NULL,
  `SUM_SORT_RANGE` bigint(20) unsigned NOT NULL,
  `SUM_SORT_ROWS` bigint(20) unsigned NOT NULL,
  `SUM_SORT_SCAN` bigint(20) unsigned NOT NULL,
  `SUM_NO_INDEX_USED` bigint(20) unsigned NOT NULL,
  `SUM_NO_GOOD_INDEX_USED` bigint(20) unsigned NOT NULL,
  `FIRST_SEEN` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `LAST_SEEN` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00'
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

とりあえず、このテーブルを参照して、「AVG_TIMER_WAIT」「MAX_TIMER_WAIT」に著しく大きい値が出ているようであれば、異常に時間がかかるSQLが実行されたということが推測できますね。

表示単位はデフォルトではナノ秒です。

performance_schema.setup_timersに、テーブルの種類毎にTIMER系の列にどの単位で管理するかを設定してあります。

mysql> select * from performance_schema.setup_timers;
+-----------+-------------+
| NAME      | TIMER_NAME  |
+-----------+-------------+
| idle      | MICROSECOND |
| wait      | CYCLE       |
| stage     | NANOSECOND  |
| statement | NANOSECOND  |
+-----------+-------------+
4 rows in set (0.00 sec)

タイマー系以外にも、パフォーマンス悪化につながりそうなイベントの発生回数を「SUM_」で集計してあります。

「COUNT_STAR」が、そのDIGEST（≒SQL）に集約集計された件数なので、この数字で割れば平均となります。

「FIRST_SEEN列」「LAST_SEEN」列に、「YYYY-MM-DD HH24:MI:SS」形式で表示されるのもありがたいですね。