スロークエリログの Lock_time と出力条件の仕様変更について

2023年3月31日

この記事は最終更新から1年以上経過しています。内容が古くなっている可能性があります。

はじめに

MySQL では、一定の秒数(long_query_time)を超える時間がかかったクエリをスロークエリログと呼ばれるログファイルに書き出すことが可能です。

※実際には設定を変更することで、min_examined_row_limit 行以上を走査していたり、インデックスを利用していない(log_queries_not_using_indexes) 場合などにもログへ書き出すことが可能です

今回はこのスロークエリログの出力について、MySQL 8.0.28 で変更された出力の仕様について確認したいと思います。

スロークエリログの出力仕様

スロークエリログの出力内容

スロークエリログは、以下のようなフォーマットでログファイルへ出力されます。

/usr/sbin/mysqld, Version: 8.0.32 (MySQL Community Server - GPL). started with:
Time                 Id Command    Argument
(...)
# Time: 2023-03-28T06:31:12.066339Z
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 0.000068  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1679985072;
SELECT 1;
(...)

/usr/sbin/mysqld, Version: 8.0.32 (MySQL Community Server - GPL). started with:

Time Id Command Argument

(...)

# Time: 2023-03-28T06:31:12.066339Z

# User@Host: root[root] @ localhost [] Id: 9

# Query_time: 0.000068 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1

SET timestamp=1679985072;

SELECT 1;

(...)

それぞれ、以下のような内容を示しています。

Time : ログが出力された(クエリの実行が終了した)時間
User@Host : クエリを実行したアカウント情報
Id : クエリが実行された接続(スレッド) ID
Query_time : クエリの実行時間(秒)
Lock_time : ロックを取得する時間(秒)
Rows_sent : クライアントに送信された結果の行数
Rows_examined : クエリの実行に走査が必要となった行数

なお、MySQL 8.0.14 から追加された log_slow_extra を有効にすることで、さらに詳しい情報を出力内容に含めることが可能です。

スロークエリログの出力条件

まず、スロークエリログが出力される条件は以下のようなシステム変数によって制御されています。

クエリーは管理ステートメントでないか、log_slow_admin_statements が有効になっている必要がある。

クエリーに少なくとも long_query_time 秒かかっているか、log_queries_not_using_indexes が有効であって、クエリーは行参照にインデックスを使用していない。

クエリーは少なくとも min_examined_row_limit 行を検査している必要がある。

クエリーは、log_throttle_queries_not_using_indexes 設定によって抑制されていてはならない。

引用 : https://dev.mysql.com/doc/refman/8.0/ja/slow-query-log.html#slow-query-log-parameters

そしてここからが今回の主題となりますが、MySQL 8.0.27 までは以下の条件を満たしている場合にのみスロークエリログが出力されていました。

(Query_time - Lock_time) > long_query_time

1	(Query_time - Lock_time) > long_query_time

したがって、たとえば以下のように実行時間の大半が行ロック待ちとなっていたクエリ(UPDATE test.t1 SET id=222)については、スロークエリログには出力されませんでした。

[事前準備]
mysql> SET GLOBAL slow_query_log = ON;
mysql> SET GLBOAL long_query_time = 1;
mysql> CREATE TABLE test.t1(id INT);
mysql> INSERT INTO test.t1 VALUES(1);

[検証手順]
session1> UPDATE test.t1 SET id=111;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

session2> UPDATE test.t1 SET id=222;
(session1 の行ロック待ち)

session1> COMMIT;
Query OK, 0 rows affected (0.01 sec)

(行ロック待ちの session2 が完了する)
Query OK, 1 row affected (24.29 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[事前準備]

mysql> SET GLOBAL slow_query_log = ON;

mysql> SET GLBOAL long_query_time = 1;

mysql> CREATE TABLE test.t1(id INT);

mysql> INSERT INTO test.t1 VALUES(1);

[検証手順]

session1> UPDATE test.t1 SET id=111;

Query OK, 1 row affected (0.00 sec)

Rows matched: 1 Changed: 1 Warnings: 0

session2> UPDATE test.t1 SET id=222;

(session1 の行ロック待ち)

session1> COMMIT;

Query OK, 0 rows affected (0.01 sec)

(行ロック待ちの session2 が完了する)

Query OK, 1 row affected (24.29 sec)

Rows matched: 1 Changed: 1 Warnings: 0

MySQL 8.0.28 以降のスロークエリログの出力仕様

変更内容

MySQL 8.0.28 以降、上述したロック待ちに関する出力条件が変更されて、以下のようになっているようです。

Query_time > long_query_time

1	Query_time > long_query_time

したがって、先ほどと同じようにクエリを実行すると、以下のようにスロークエリログにも出力されることが確認できました。

# Time: 2023-03-28T07:00:40.376073Z
# User@Host: root[root] @ localhost []  Id:    12
# Query_time: 24.291940  Lock_time: 24.291577 Rows_sent: 0  Rows_examined: 1
SET timestamp=1679986816;
UPDATE test.t1 SET id=222;

# Time: 2023-03-28T07:00:40.376073Z

# User@Host: root[root] @ localhost [] Id: 12

# Query_time: 24.291940 Lock_time: 24.291577 Rows_sent: 0 Rows_examined: 1

SET timestamp=1679986816;

UPDATE test.t1 SET id=222;

実際にスロークエリログの出力する条件をソースコードから確認すると、以下のように条件が変更されていることがわかりました。
ここで、utime_after_lock はざっくり言うと各種ロック時間を待機した後の時刻、start_utime はクエリの実行開始時刻を示しています。

【sql/sql_parse.cc】
[MySQL 8.0.27]
void THD::update_slow_query_status() {
  if (my_micro_time() > utime_after_lock + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

[MySQL 8.0.32]
void THD::update_slow_query_status() {
  if (my_micro_time() > start_utime + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

【sql/sql_parse.cc】

[MySQL 8.0.27]

void THD::update_slow_query_status() {

if (my_micro_time() > utime_after_lock + variables.long_query_time)

server_status |= SERVER_QUERY_WAS_SLOW;

}

[MySQL 8.0.32]

void THD::update_slow_query_status() {

if (my_micro_time() > start_utime + variables.long_query_time)

server_status |= SERVER_QUERY_WAS_SLOW;

}

変更された理由

仕様が変更となった MySQL 8.0.28 のリリースノートからは、以下のようなバグ修正の情報を確認することができました。

The LOCK_TIME returned by the performance schema was under evaluated, missing time spent in rows locks, and time spent when locking multiple tables. As of this release, LOCK_TIME accounts for:

all the time waited on SQL TABLES

all the time waited on DATA locks

LOCK_TIME is now reported consistently in the slow log and the performance schema. (Bug #33236909)

引用 : Changes in MySQL 8.0.28 (2022-01-18, General Availability)

どうやら、スロークエリログの Lock_time と performance_schema.events_statements_current テーブルの LOCK_TIME カラムの計算方法が異なっていたバグを修正したようです。

ソースコード上の変更内容としては、inc_lock_usec 関数の m_lock_usec 変数でロック時間を計測するようになったようですが、この実装にともない MySQL 8.0.27 までの utime_after_lock 変数が削除されたため、この変数を使用していたスロークエリログの出力条件も一緒に変更されたと推測されます。

まとめ

ここまで、MySQL 8.0.28 以降のスロークエリログの出力条件の仕様変更について確認してきました。
これまでの仕様が変更されるような重要な変更ではないかと思うのですが、2023 年 3 月 28 日時点でリリース情報などからは今回の変更がおこなわれたことは直接記載されていないようです。

※そもそも、MySQL 8.0.27 までのロック待機時間が long_query_time に含まれない事象もマニュアルなどに明記されていた訳ではないので、あまり重要視されていないのかもしれません

いずれにせよ、運用レベルだと今までは出力されていなかった行ロック待機待ちのクエリがスロークエリログに出力されるようになるなどの影響が出る可能性もありますので、MySQL 8.0.28 以降にアップグレードをおこなう場合は、急にスロークエリログが増える可能性に留意する必要がありそうです。

よかったらシェアしてね！

URLをコピーしました！