performance_schemaのTIMERの正体を追って、ついでにトランザクションの開始時刻を取得する

今回は小ネタです。

performance_schema(p_s)内のテーブル名がevent_から始まる各テーブルにはTIMER_STARTなどのカラムが含まれます。（ただしsummaryテーブルは除きます）

以前p_s.events_transactions_currentなどのテーブルを使ってトランザクションを追跡したときに、このTIMER_START, TIMER_ENDから、そのトランザクションがいつ実行されたのかということを、どうやって調べればいいのだろうと考えていました。

このあたりになるともうソースコード読むしかないのかなあと思って、苦労しながら（Ｃわからないマン）コードを読んでいたのですが、結局よく分かりませんでした。

そんなとき、こちらの本を読んでいてとうとう答えにたどり着きました。

MySQL 8 Query Performance Tuning: A Systematic Method for Improving Execution Speeds (English Edition)

作者:Jesper Wisborg Krogh
発売日: 2020/03/16
メディア: Kindle版

5章 The Performance SchemaのEvent Propertiesにこうありました。

When MySQL starts, the internal timer counter is set to 0 and incremented every picosecond. When an event starts, the value of the counter is taken and assigned to TIMER_START.

つまり、TIMER_STARTはMySQLが起動してから経過した時間(ただし単位はピコ秒)だったのです。

これさえ分かってしまえば、あとはこの値をうまく使ってそのトランザクションなり、ステートメントが実行された時刻を求めることができそうです。

f:id:koreshiki-nanno:20200422214240p:plain — クッソ雑な図

図の下手さには目を瞑るとして・・・

$t_0$ = MySQLを起動した時刻

$t_1$ = トランザクションTが開始された時刻

$t_2$ = トランザクションTが終了された時刻

としましょう。

まず、現在の時刻すなわちSELECT now();の結果から、MySQLの稼働時間すなわちSHOW GLOBAL STATUS LIKE 'Uptime';の値を引くと、MySQLを起動した時刻になりそうです。

まずはこれが正しいのか見てみましょう。

起動時刻を確認します。

[root@centos8:/mysql/mysql_home/tmp]# systemctl status mysqld
● mysqld.service - MySQL Server
   Loaded: loaded (/etc/systemd/system/mysqld.service; enabled; vendor preset: disabled)
   Active: active (running) since Wed 2020-04-22 21:20:28 JST; 30min ago
 Main PID: 972 (mysqld)
   Status: "Server is operational"
    Tasks: 43 (limit: 11338)
   Memory: 684.1M
   CGroup: /system.slice/mysqld.service
           └─972 /mysql/mysql_home/bin/mysqld

 4月 22 21:20:05 centos8 systemd[1]: Starting MySQL Server...
 4月 22 21:20:28 centos8 systemd[1]: Started MySQL Server.

sinceから2020-04-22 21:20:28であることがわかります。

mysql80-root@localhost:[p_s] >SELECT DATE_SUB(now(), INTERVAL VARIABLE_VALUE second) AS 'START TIME' FROM global_status WHERE VARIABLE_NAME = 'Uptime';
+----------------------------+
| START TIME                 |
+----------------------------+
| 2020-04-22 21:20:08.000000 |
+----------------------------+
1 row in set (0.01 sec)

うーん、20秒の誤差が出てしまいました。

そもそもsystemctlで表示した時刻とMySQL内部の起動時刻が一致しているのかが怪しいところなのでまあ良しとしましょう。

とりあえず次のことが言えそうです。

$t_0 = NOW - Uptime$

ここでNOWはSELECT now();の結果、UptimeはGLOBAL STATUSの値です。

MySQLの開始時刻が分かれば次の式からトランザクションを開始した時刻が分かるはずです。

$t_1 = t_0 + TIMERSTART$

これを確かめるために、簡単なトランザクションを考えます。

BEGIN;
SELECT NOW();
SELECT ps_current_thread_id();
SELECT ROUND(RAND()*9) + 1 INTO @x;
SELECT SLEEP(@x);
SELECT NOW();
COMMIT;

トランザクション開始直後の時刻と終了直前の時間を計測しておきます。

mysql80-koreshiki@localhost:[(none)] >BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql80-koreshiki@localhost:[(none)] >SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2020-04-22 22:13:40 |
+---------------------+
1 row in set (0.00 sec)

mysql80-koreshiki@localhost:[(none)] >SELECT ps_current_thread_id();
+------------------------+
| ps_current_thread_id() |
+------------------------+
|                    265 |
+------------------------+
1 row in set (0.00 sec)

mysql80-koreshiki@localhost:[(none)] >SELECT ROUND(RAND()*9) + 1 INTO @x;
Query OK, 1 row affected (0.00 sec)

mysql80-koreshiki@localhost:[(none)] >SELECT SLEEP(@x);
+-----------+
| SLEEP(@x) |
+-----------+
|         0 |
+-----------+
1 row in set (8.01 sec)

mysql80-koreshiki@localhost:[(none)] >SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2020-04-22 22:13:48 |
+---------------------+
1 row in set (0.00 sec)

mysql80-koreshiki@localhost:[(none)] >COMMIT;
Query OK, 0 rows affected (0.00 sec)

p_s.events_transactions_currentからTIMER_START, TIMER_ENDを取得します。

mysql80-root@localhost:[p_s] >SELECT TIMER_START, TIMER_END FROM p_s.events_transactions_current WHERE thread_id = 265;
+------------------+------------------+
| TIMER_START      | TIMER_END        |
+------------------+------------------+
| 3213241220660000 | 3221264215457000 |
+------------------+------------------+
1 row in set (0.03 sec)

この値がピコ秒であることに注意して

次のクエリでトランザクションが開始された時刻を確かめてみます。

SELECT
  DATE_ADD(
    DATE_SUB(NOW(), INTERVAL VARIABLE_VALUE second),
    INTERVAL (@timer / pow(1000, 4)) second
  ) AS 'TRANSACTION START TIME'
FROM
  performance_schema.global_status
WHERE
  VARIABLE_NAME = 'Uptime';

さて結果は

mysql80-root@localhost:[p_s] >SELECT TIMER_START, TIMER_END INTO @x, @y FROM p_s.events_transactions_current WHERE thread_id = 265;
Query OK, 1 row affected (0.00 sec)

mysql80-root@localhost:[p_s] >
mysql80-root@localhost:[p_s] >SELECT
    ->   DATE_ADD(
    ->     DATE_SUB(NOW(), INTERVAL VARIABLE_VALUE second),
    ->     INTERVAL (@x / pow(1000, 4)) second
    ->   ) AS 'TRANSACTION START TIME'
    -> FROM
    ->   performance_schema.global_status
    -> WHERE
    ->   VARIABLE_NAME = 'Uptime';
+----------------------------+
| TRANSACTION START TIME     |
+----------------------------+
| 2020-04-22 22:13:41.241220 |
+----------------------------+
1 row in set (0.01 sec)

mysql80-root@localhost:[p_s] >SELECT
    ->   DATE_ADD(
    ->     DATE_SUB(NOW(), INTERVAL VARIABLE_VALUE second),
    ->     INTERVAL (@y / pow(1000, 4)) second
    ->   ) AS 'TRANSACTION START TIME'
    -> FROM
    ->   performance_schema.global_status
    -> WHERE
    ->   VARIABLE_NAME = 'Uptime';
+----------------------------+
| TRANSACTION START TIME     |
+----------------------------+
| 2020-04-22 22:13:49.264215 |
+----------------------------+
1 row in set (0.01 sec)

どうしても誤差が出てしまっていますが、1分以内なんでまあ許容範囲かな？

最後にこんな関数をsysスキーマに作って

CREATE FUNCTION executed_time(timer BIGINT UNSIGNED) RETURNS DATETIME DETERMINISTIC
BEGIN
  DECLARE res DATETIME;
  SELECT
    DATE_ADD(
      DATE_SUB(NOW(), INTERVAL VARIABLE_VALUE second),
      INTERVAL (timer / pow(1000, 4)) second
    ) INTO res
  FROM
    performance_schema.global_status
  WHERE
    VARIABLE_NAME = 'Uptime';
  RETURN res;
END

こうすれば

mysql80-root@localhost:[sys] >SELECT sys.executed_time(TIMER_START), sys.executed_time(TIMER_END)
    -> FROM p_s.events_transactions_current
    -> WHERE thread_id = 265;
+--------------------------------+------------------------------+
| sys.executed_time(TIMER_START) | sys.executed_time(TIMER_END) |
+--------------------------------+------------------------------+
| 2020-04-22 22:13:41            | 2020-04-22 22:13:49          |
+--------------------------------+------------------------------+
1 row in set (0.03 sec)

どうしても誤差が出てしまいますね・・・

まあ、トランザクションの時刻をそこまで正確に求めたいかというと・・・

注意しなくてはいけない点としてTIMER_STARTなどはソースコード内でunsigned long longで定義されています。つまりTIMERの最大値は2⁶⁴-1となります。この数値を時間にすると約213日となります。

実はTIMERはサポートされている最大値を超えてしまうと0にリセットされてしまうようです。ということは1年しないうちにTIMERはリセットされてしまうということです。この方法でトランザクションが開始した時間を調べる際にはこの点に注意したほうがいいですね。

三流エンジニアの落書き帳

さあ、今日も未知という扉を開けてみよう

performance_schemaのTIMERの正体を追って、ついでにトランザクションの開始時刻を取得する