【MySQL】トランザクションの実行時間を調査する

はじめに

こんにちは、スタメンの松谷(@uuushiro)です。この記事では、MySQLのパフォーマンススキーマを利用し、トランザクションの実行時間を調査する方法を紹介します。なお、検証に利用した実行環境は Amazon Aurora MySQL5.7互換 です。

なぜトランザクションの実行時間を調査したいのか

過去に弊社が提供するWEBサービスのデータベースに、ALTER文などのデータ定義言語(以下DDL)をオンラインで実行した際、DDL対象のテーブルへのクエリが「Waiting for table metadata lock」という待機状態になり、結果として障害に繋がったことがありました。なぜトランザクションの実行時間を調査したいのかを説明する前に、まずこの「Waiting for table metadata lock」について少し説明します。

テーブルに対する オンライン DDL は、DDL実行前後に対象テーブルへの排他的アクセス(metadata lock)が必要なため、そのテーブルにアクセスしている実行中のトランザクションがコミットまたはロールバックするのを待機するようになっています。このとき、待機状態になっているDDL の実行ステータスは 「Waiting for table metadata lock」となっており、実行中のトランザクションが完了するまで待ちが発生します。 さらに、DDLが 「Waiting for table metadata lock」状態のときに対象テーブルへSELECT文などのデータ操作言語(以下DML)を実行した場合、このDMLの実行ステータスも「Waiting for table metadata lock」となり待機状態になります。 つまり、DDLが実行される前に実行中だったトランザクションの実行時間分だけ、後続の対象テーブルに対する DDL, DML が待機することになります。

このようにトランザクションの実行時間がクエリの待機状態の継続時間に直接影響する場合があります。しかし、本番環境のデータベースにおいて実際にトランザクションがどれほど長く、頻繁に実行されているのか？を私が把握していなかったため今回調査をしてみました。

トランザクション実行時間の調査方法

performance_schema を利用すればトランザクションの実行時間を追跡できます。 performance_schema に関しては、performance_schemaをsysで使い倒す！ の記事がとても詳しいので是非参照ください。ここでは要点を絞って順に説明します。

パフォーマンススキーマが有効かどうか確認

まず、パフォーマンススキーマが有効かどうかを確認します。performance_schema変数の値がONであれば有効です。 (MySQL5.7以降はデフォルトONになっています)

mysql> SHOW VARIABLES LIKE 'performance_schema';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | ON    |
+--------------------+-------+

setup_instruments と setup_consumers について

トランザクションイベントを収集できるように、パフォーマンススキーマの設定関連のテーブル setup_instruments と setup_consumers を更新します。

setup_instrumentsは、MySQLのソースコード内に設置された、処理時間や待機時間を収集するための計器(instruments)の設定テーブルです。以下のように、テーブルの中身は各instrumentsのどれが有効にされているかを示しています。(トランザクションに関係のあるinstrumentsに絞って表示しています)

mysql> select * from performance_schema.setup_instruments where name like '%transaction%';
+-------------------------------------------------------+---------+-------+
| NAME                                                  | ENABLED | TIMED |
+-------------------------------------------------------+---------+-------+
| wait/synch/mutex/sql/LOCK_transaction_cache           | NO      | NO    |
| stage/sql/Waiting for preceding transaction to commit | NO      | NO    |
| stage/sql/Waiting for dependent transaction to commit | NO      | NO    |
| transaction                                           | NO      | NO    |
| memory/sql/THD::transactions::mem_root                | NO      | NO    |
+-------------------------------------------------------+---------+-------+

setup_consumersは、上記のinstrumentで収集した、現在(current)・過去の(history)データを保存するかどうかの設定テーブルです。以下のように、テーブルの中身は各consumerのどれを有効にしているかを示しています。

mysql> SELECT * FROM performance_schema.setup_consumers;
+----------------------------------+---------+
| NAME                             | ENABLED |
+----------------------------------+---------+
| events_stages_current            | NO      |
| events_stages_history            | NO      |
| events_stages_history_long       | NO      |
| events_statements_current        | YES     |
| events_statements_history        | YES     |
| events_statements_history_long   | NO      |
| events_transactions_current      | NO      |
| events_transactions_history      | NO      |
| events_transactions_history_long | NO      |
| events_waits_current             | NO      |
| events_waits_history             | NO      |
| events_waits_history_long        | NO      |
| global_instrumentation           | YES     |
| thread_instrumentation           | YES     |
| statements_digest                | YES     |
+----------------------------------+---------+

設定変更

今回は、トランザクションに関する instruments と consumers を有効化します。

以下のように、NAMEが 'transaction' のinstrumentを ENABLED = YES とします。(TIMEDはinstrumentの時間が測定されるかどうかのフラグで今回YESとしています。)

UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME = 'transaction';

続いて、NAMEが「events_transactions_history_long」のconsumerを有効にします。(events_transactions_history_longは、すべてのスレッドでグローバルに終了した最新のトランザクションイベントが含まれます)

mysql>  UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME = 'events_transactions_history_long';

上記で有効化した events_transactions_history_long で取得できるフィールドは以下になります。トランザクションの実行時間(TIMER_WAIT)は取得できますが、実行されたSQL情報は取得できません。

mysql> describe events_transactions_history_long;
+---------------------------------+------------------------------------------------+------+-----+---------+-------+
| Field                           | Type                                           | Null | Key | Default | Extra |
+---------------------------------+------------------------------------------------+------+-----+---------+-------+
| THREAD_ID                       | bigint(20) unsigned                            | NO   |     | NULL    |       |
| EVENT_ID                        | bigint(20) unsigned                            | NO   |     | NULL    |       |
| END_EVENT_ID                    | bigint(20) unsigned                            | YES  |     | NULL    |       |
| EVENT_NAME                      | varchar(128)                                   | NO   |     | NULL    |       |
| STATE                           | enum('ACTIVE','COMMITTED','ROLLED BACK')       | YES  |     | NULL    |       |
| TRX_ID                          | bigint(20) unsigned                            | YES  |     | NULL    |       |
| GTID                            | varchar(64)                                    | YES  |     | NULL    |       |
| XID_FORMAT_ID                   | int(11)                                        | YES  |     | NULL    |       |
| XID_GTRID                       | varchar(130)                                   | YES  |     | NULL    |       |
| XID_BQUAL                       | varchar(130)                                   | YES  |     | NULL    |       |
| XA_STATE                        | varchar(64)                                    | YES  |     | NULL    |       |
| SOURCE                          | varchar(64)                                    | YES  |     | NULL    |       |
| TIMER_START                     | bigint(20) unsigned                            | YES  |     | NULL    |       |
| TIMER_END                       | bigint(20) unsigned                            | YES  |     | NULL    |       |
| TIMER_WAIT                      | bigint(20) unsigned                            | YES  |     | NULL    |       |
| ACCESS_MODE                     | enum('READ ONLY','READ WRITE')                 | YES  |     | NULL    |       |
| ISOLATION_LEVEL                 | varchar(64)                                    | YES  |     | NULL    |       |
| AUTOCOMMIT                      | enum('YES','NO')                               | NO   |     | NULL    |       |
| NUMBER_OF_SAVEPOINTS            | bigint(20) unsigned                            | YES  |     | NULL    |       |
| NUMBER_OF_ROLLBACK_TO_SAVEPOINT | bigint(20) unsigned                            | YES  |     | NULL    |       |
| NUMBER_OF_RELEASE_SAVEPOINT     | bigint(20) unsigned                            | YES  |     | NULL    |       |
| OBJECT_INSTANCE_BEGIN           | bigint(20) unsigned                            | YES  |     | NULL    |       |
| NESTING_EVENT_ID                | bigint(20) unsigned                            | YES  |     | NULL    |       |
| NESTING_EVENT_TYPE              | enum('TRANSACTION','STATEMENT','STAGE','WAIT') | YES  |     | NULL    |       |
+---------------------------------+------------------------------------------------+------+-----+---------+-------+

SQL情報の確認

そこで、SQL情報を追加するために、過去に実行されたSQLの中身が確認できるようになるconsumer「events_statements_history_long」を有効化します。

UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME = 'events_statements_history_long';

上記で有効化した events_statements_history_long で取得できるフィールドは以下になります。実行されたSQL情報(SQL_TEXT)が取得できます。

mysql> describe events_statements_history_long;
+-------------------------+------------------------------------------------+------+-----+---------+-------+
| Field                   | Type                                           | Null | Key | Default | Extra |
+-------------------------+------------------------------------------------+------+-----+---------+-------+
| THREAD_ID               | bigint(20) unsigned                            | NO   |     | NULL    |       |
| EVENT_ID                | bigint(20) unsigned                            | NO   |     | NULL    |       |
| END_EVENT_ID            | bigint(20) unsigned                            | YES  |     | NULL    |       |
| EVENT_NAME              | varchar(128)                                   | NO   |     | NULL    |       |
| SOURCE                  | varchar(64)                                    | YES  |     | NULL    |       |
| TIMER_START             | bigint(20) unsigned                            | YES  |     | NULL    |       |
| TIMER_END               | bigint(20) unsigned                            | YES  |     | NULL    |       |
| TIMER_WAIT              | bigint(20) unsigned                            | YES  |     | NULL    |       |
| LOCK_TIME               | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SQL_TEXT                | longtext                                       | YES  |     | NULL    |       |
| DIGEST                  | varchar(32)                                    | YES  |     | NULL    |       |
| DIGEST_TEXT             | longtext                                       | YES  |     | NULL    |       |
| CURRENT_SCHEMA          | varchar(64)                                    | YES  |     | NULL    |       |
| OBJECT_TYPE             | varchar(64)                                    | YES  |     | NULL    |       |
| OBJECT_SCHEMA           | varchar(64)                                    | YES  |     | NULL    |       |
| OBJECT_NAME             | varchar(64)                                    | YES  |     | NULL    |       |
| OBJECT_INSTANCE_BEGIN   | bigint(20) unsigned                            | YES  |     | NULL    |       |
| MYSQL_ERRNO             | int(11)                                        | YES  |     | NULL    |       |
| RETURNED_SQLSTATE       | varchar(5)                                     | YES  |     | NULL    |       |
| MESSAGE_TEXT            | varchar(128)                                   | YES  |     | NULL    |       |
| ERRORS                  | bigint(20) unsigned                            | NO   |     | NULL    |       |
| WARNINGS                | bigint(20) unsigned                            | NO   |     | NULL    |       |
| ROWS_AFFECTED           | bigint(20) unsigned                            | NO   |     | NULL    |       |
| ROWS_SENT               | bigint(20) unsigned                            | NO   |     | NULL    |       |
| ROWS_EXAMINED           | bigint(20) unsigned                            | NO   |     | NULL    |       |
| CREATED_TMP_DISK_TABLES | bigint(20) unsigned                            | NO   |     | NULL    |       |
| CREATED_TMP_TABLES      | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SELECT_FULL_JOIN        | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SELECT_FULL_RANGE_JOIN  | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SELECT_RANGE            | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SELECT_RANGE_CHECK      | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SELECT_SCAN             | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SORT_MERGE_PASSES       | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SORT_RANGE              | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SORT_ROWS               | bigint(20) unsigned                            | NO   |     | NULL    |       |
| SORT_SCAN               | bigint(20) unsigned                            | NO   |     | NULL    |       |
| NO_INDEX_USED           | bigint(20) unsigned                            | NO   |     | NULL    |       |
| NO_GOOD_INDEX_USED      | bigint(20) unsigned                            | NO   |     | NULL    |       |
| NESTING_EVENT_ID        | bigint(20) unsigned                            | YES  |     | NULL    |       |
| NESTING_EVENT_TYPE      | enum('TRANSACTION','STATEMENT','STAGE','WAIT') | YES  |     | NULL    |       |
| NESTING_EVENT_LEVEL     | int(11)                                        | YES  |     | NULL    |       |
+-------------------------+------------------------------------------------+------+-----+---------+-------+

パフォーマンススキーマでは、ステートメントイベント(events_statements_history_long)はトランザクションイベント(events_transactions_history_long)内にネストされます(1トランザクションイベントの中で、複数のステートメントイベント(SQL)が実行されるので)。このため、events_transactions_history_long.event_id が events_statements_history_long.nesting_event_id と対応づけされています。 つまり、events_transactions_history_long.event_id = events_statements_history_long.nesting_event_id の条件でJOINをすれば、トランザクション時間とSQLを一緒に表示することができます。

以下で、SQLの例を示します。

SELECT 
    transactions.thread_id,
    transactions.event_id,
    transactions.nesting_event_id,
    sys.format_time(transactions.timer_wait),
    statements.nesting_event_id,
    statements.sql_text
FROM
    performance_schema.events_transactions_history_long AS transactions
JOIN
    performance_schema.events_statements_history_long AS statements ON transactions.event_id = statements.nesting_event_id;

以下が結果例です。トランザクションのスレッドID、実行時間、SQL情報を確認することができました。

+-----------+----------+------------------+------------------------------------------+------------------+--------------------------------------------------------------------------------------------------------------------------
| thread_id | event_id | nesting_event_id | sys.format_time(transactions.timer_wait) | nesting_event_id | sql_text                                                                                                                |
+-----------+----------+------------------+------------------------------------------+------------------+--------------------------------------------------------------------------------------------------------------------------
|   3926618 |  4665986 |          4665979 | 174.72 ms                                |          4665986 | SELECT  1 AS one FROM `hoge` WHERE `hoge`.`name` = 'huga' LIMIT 1                                                       |
|   3926618 |  4665986 |          4665979 | 174.72 ms                                |          4665986 | INSERT INTO `hoge` (`user_id`, `created_at`, `updated_at`) VALUES (99999, '2021-05-13 10:18:23', '2021-05-13 10:18:23') |
|   3926618 |  4665986 |          4665979 | 174.72 ms                                |          4665986 | UPDATE `hoge` SET `updated_at` = '2021-05-13 10:18:23.912636' WHERE `hoge`.`user_id` = 999                              |
|   3926618 |  4665986 |          4665979 | 174.72 ms                                |          4665986 | UPDATE `hoge` SET `updated_at` = '2021-05-13 10:18:23.762849' WHERE `hoge`.`id` = 9999 AND `hoge`.`user_id` = 999       |
|   3926618 |  4665986 |          4665979 | 174.72 ms                                |          4665986 | COMMIT                                                                                                                  |
|   3926536 |  1651132 |          1651125 | 103.89 ms                                |          1651132 | SELECT  `hoge`.* FROM `hoge` WHERE `hoge`.`id` = 514 LIMIT 1                                                            |
|   3926536 |  1651132 |          1651125 | 103.89 ms                                |          1651132 | COMMIT                                                                                                                  |
|   3926485 |  1385528 |          1385521 | 134.75 ms                                |          1385528 | SELECT  `hoge`.* FROM `hoge` WHERE `hoge`.`id` = 9999 LIMIT 1                                                           |
|   3926485 |  1385528 |          1385521 | 134.75 ms                                |          1385528 | SELECT  `hoge`.* FROM `hoge` WHERE `hoge`.`id` = 9999 LIMIT 1                                                           |
|   3926485 |  1385528 |          1385521 | 134.75 ms                                |          1385528 | SELECT  `hoge`.* FROM `hoge` WHERE `hoge`.`id` = 9999 LIMIT 1                                                           |
|   3926485 |  1385528 |          1385521 | 134.75 ms                                |          1385528 | COMMIT                                                                                                                  |
+-----------+----------+------------------+------------------------------------------+------------------+--------------------------------------------------------------------------------------------------------------------------

監視

本番環境において、どれくらい長いトランザクションがどれくらいの頻度発生しているのかを確認するために、定期的にポーリングし、Slackなどに通知する監視プログラムをRubyで作成しました。

events_transactions_history_long と events_statements_history_long が保存できる履歴数は、performance_schema_events_transactions_history_long_size および performance_schema_events_statements_history_long_size で決まっており、この数を超えると履歴から消えてしまうので、履歴テーブルから消えないくらいのタイミングでポーリングする頻度を調整しています(以下の例では3秒としています)。

また、先程のSQLのWHERE句に「transactions.timer_wait > 10000000000000」を加えれば、10秒以上実行されたトランザクションに絞ることができます。

# 10秒以上のトランザクションを取得する
sql = <<-SQL
  SELECT 
    transactions.thread_id,
    transactions.event_id,
    transactions.nesting_event_id,
    sys.format_time(transactions.timer_wait),
    statements.nesting_event_id,
    statements.sql_text
  FROM
    performance_schema.events_transactions_history_long AS transactions
  JOIN
    performance_schema.events_statements_history_long AS statements ON transactions.event_id = statements.nesting_event_id
  WHERE transactions.timer_wait > 10000000000000;
    SQL

mysql = Mysql2::Client.new(host: host, username: username, password: password, database: database)

begin
  loop do
    results = mysql.query(sql, as: :hash)

    if results.size > 0
      message = "Long transaction detected. performance_schema's rows: #{results.to_a.to_s}"
      Bugsnag.notify(message) # 外部へ通知
    end

    sleep 3
  end
rescue => e
  Bugsnag.notify(e)  # 外部へ通知
ensure
  mysql.close
  Bugsnag.notify("detect_long_transaction stopped.")  # 外部へ通知
end

まとめ

パフォーマンススキーマを利用することで、トランザクションの実行時間を取得できるようになりました。 この情報を利用し、ほぼリアルタイムで本番環境で実行されているトランザクションを監視することで、以下のように改善が進みました。

• どのテーブルでどれくらいの長さのトランザクションがどういった頻度で実行されているのか？が可視化され、オンラインDDLを実行したときのリスク評価ができるようになった。
• どのアプリケーションコードが長時間のトランザクションを発生させているのかが分かるようになり、アプリケーションコードの改善が進んだ。
• 「Waiting for table metadata lock」という待機状態が長時間発生した場合にも、原因となるトランザクションのスレッドIDをすぐに取得できるので、問題の処理を素早くKILLできる(問題がなければ)。

今回の調査で少しパフォーマンススキーマに関しての理解が深まりました。今後もMySQLの理解を深めていければと思います！

最後になりますが、スタメンでは自社プロダクトの開発する仲間を募集しています。興味を持ってくれた方は、ぜひ下記の採用サイトをご覧ください。

• スタメン エンジニア採用サイト
• インフラエンジニア募集ページ
• サーバーサイドエンジニア募集ページ
• フロントエンドエンジニア募集ページ
• モバイルアプリエンジニア募集ページ
• デザイナー募集ページ

参考にさせていただいた資料

• MySQL :: MySQL 5.6 リファレンスマニュアル :: 8.10.4 メタデータのロック
• MySQL :: MySQL 5.6 リファレンスマニュアル :: 14.11.2 オンライン DDL でのパフォーマンスと並列性に関する考慮事項
• Waiting for table metadata lockとオンラインDDLについて【MySQL5.6】 - 銀行員からのRailsエンジニア
• performance_schemaをsysで使い倒す！ | Think IT（シンクイット）
• MySQLでトランザクションを追跡したい ~その1~ - 三流エンジニアの落書き帳