Go to Qiita Advent Calendar Top
LoginSignup
8
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Day 8

OPENLOGI Advent Calendar 2025

Day 8

MySQL Advent Calendar 2025

@HrsUed(HrsUed)in株式会社オープンロジ

wait/io/table/sql/handlerの正体

Last updated at Posted at 2025-12-07

はじめに

株式会社オープンロジ CTO室所属の上田です。

この記事では、MySQLパフォーマンススキーマおよび Amazon CloudWatch Database Insights で目にするwait/io/table/sql/handlerについて、MySQLのソースコードレベルまで掘り下げて正体に迫ります。

ドキュメントでは待機イベントの計装範囲が「ストレージエンジンへの委任部分」といった抽象的な説明に留まっていますが、本記事では実際にどのC++コードがこのイベントを計測しているのかを特定し、その正体を解明します。

なお、本記事は以下アドベントカレンダー8日目の記事です。

結論

wait/io/table/sql/handler は MySQLサーバ層がストレージエンジン層（InnoDBなど）のAPIを呼び出してから、制御が戻ってくるまで待機したことを計測したものです。

具体的には、sql/handler.cc に実装されている ha_write_row（INSERT）、ha_update_row（UPDATE）、ha_delete_row（DELETE）、および各種読み取りメソッド（ha_rnd_next 等）の実行時間を指します。

したがって、この待機イベントの記録は、「ストレージエンジンの仕事を待っている時間すべて」 を意味します。
ディスクI/O、行ロックの待機、メモリ上の計算、これら全てが含まれます。

wait/io/table/sql/handler単体の深堀りをしても、ボトルネックの種類までは分からないので、根本原因の分析にはあまり役に立ちません。
他の支配的な待機イベントやメトリクスを組み合わせた別のアプローチのほうが良いと感じます。

wait/io/table/sql/handlerの知識まとめ

  • wait/io/table/sql/handler はMySQLパフォーマンススキーマの計装のイベント名です
  • プリフィックスwait/io/tableは、テーブルに対する待機イベントを表すイベント名です
  • サフィックスsql/handlerは、計装が実装されているファイル名です
  • 待機イベントとは、クライアントや共有リソースの応答を待つことすべてを指します
  • SQLによるCRUD操作すべてで、wait/io/table/sql/handler が記録されます
  • つまり、このイベントが発生しているという事実からは、実際に何が遅いのかは分かりません
  • なので、ロック取得待ち、ストレージI/O遅延、ネットワークI/O遅延など、どれが原因でクエリ実行に時間がかかっているかも教えてくれません

wait/io/table/sql/handlerを調べたいと思ったきっかけ

Database Insightsを見ると、wait/io/table/sql/handlerという待機イベントによく遭遇します。

PerformanceInsights_sample.png

そして、いつも最初に以下のドキュメントを読むことになります。

そこにはこう書かれています。

io/table/sql/handler イベントは、作業がストレージエンジンに委任されたときに発生します。

イベント io/table は、テーブルへのアクセスを待っていることを示します。このイベントは、データがバッファプールにキャッシュされているか、ディスク上でアクセスされているかにかかわらず、発生します。io/table/sql/handler イベントは、ワークロードアクティビティの増加を示します。

ハンドラーは、特定の種類のデータに特化したルーチンか、特定の特別なタスクに焦点を当てたルーチンです。例えば、イベントハンドラーは、オペレーティングシステムまたはユーザーインターフェイスからイベントとシグナルを受信してダイジェストします。メモリハンドラーは、メモリに関連するタスクを実行します。ファイル入力ハンドラは、ファイル入力を受け取り、コンテキストに応じてデータに対して特別なタスクを実行する関数です。

performance_schema.events_waits_current などの ビューは、実際の待機がロックなどのネストされた待機イベントである場合に io/table/sql/handler をよく表示します。実際の待機が io/table/sql/handler ではない場合、Performance Insights はネストされた待機イベントをレポートします。Performance Insights が io/table/sql/handler をレポートする場合、非表示のネストされた待機イベントではなく I/O リクエストの InnoDB 処理を表します。詳細については、MySQL リファレンスマニュアルの「パフォーマンススキーマの原子および分子イベント」を参照してください。

io/table/sql/handler イベントは多くの場合、io/aurora_redo_log_flush のような I/O 待機を伴う上位の待機イベントに表示されます。

実際にデータベースの負荷が高く、早くリカバリや原因特定をしたいと思っている状況では、このドキュメントが何を言っているのか私には全く分かりませんでした。

ドキュメントで分からないことをソースコードで理解する

「ドキュメントが分かりにくいなら、コードを読めばいい」ということで、MySQL 9.5のソースコードを調査します。

要約

mysql-server/sql/handler.cc の中でMYSQL_TABLE_IO_WAIT マクロを呼び出すことで、wait/io/table/sql/handler待機イベントが計装されるようになっていました。

そして、その呼び出しは14箇所あり、すべてのCRUD操作が対象であることもソースコードから理解できました。

以下は計装の流れの概念図です。

イベント名の定義

wait/io/table/sql/handlerというイベント名がどこで定義されているかを探すと、storage/perfschema/pfs_column_values.cc に見つかります。

storage/perfschema/pfs_column_values.cc
LEX_CSTRING table_io_class_name = {
    STRING_WITH_LEN("wait/io/table/sql/handler")};

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs_column_values.cc#L49-L50

これはパフォーマンススキーマにおけるテーブルI/Oクラスの名称として定義されています。

つまり、特定のテーブルに対する操作ではなく、テーブルI/Oという「操作カテゴリそのもの」を表す計装（Instrumentation）の名前となっています。

table_io_class_nameという文字列でリポジトリを検索すると、以下のように、register_global_classes() →init_instr_class()→PFS_instr_name::set()を使ってグローバル変数global_table_io_classにイベント名をセットしていることも分かります。

:point_right: グローバル変数にイベント名をセットするソースコードを見る
storage/perfschema/pfs_instr_class.cc
void register_global_classes() {
  /* Table I/O class */
  init_instr_class(&global_table_io_class, table_io_class_name.str,
                   (uint)table_io_class_name.length, 0, 0, PSI_DOCUMENT_ME,
                   PFS_CLASS_TABLE_IO);
  global_table_io_class.m_event_name_index = GLOBAL_TABLE_IO_EVENT_INDEX;
  configure_instr_class(&global_table_io_class);

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs_instr_class.cc#L329-L335

storage/perfschema/pfs_instr_class.cc
static void init_instr_class(PFS_instr_class *klass, const char *name,
                             uint name_length, int flags, int volatility,
                             const char *documentation,
                             PFS_class_type class_type) {
  assert(name_length <= PFS_MAX_INFO_NAME_LENGTH);
  memset(klass, 0, sizeof(PFS_instr_class));
  klass->m_name.set(class_type, name, name_length);

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs_instr_class.cc#L1188-L1194

storage/perfschema/pfs_instr_class.h
struct PFS_instr_class {
  /** Class type */
  PFS_class_type m_type;
  
  /** Instrument name. */
  PFS_instr_name m_name;

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs_instr_class.h#L248C1-L271C25

storage/perfschema/pfs_instr_class.h
class PFS_instr_name {
 public:
  /**
    Copy the specified name to this name.

    @param class_type The class type of this name, i.e., whether it is
    the name of a mutex, thread, etc.

    @param name The buffer to read from.

    @param max_length_arg If is given, at most that many chars are
    copied, plus the terminating '\0'. Otherwise, up to buffer_size-1
    characters are copied, plus the terminating '\0'.
  */
  void set(PFS_class_type class_type, const char *name,
           uint max_length_arg = max_length);

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs_instr_class.h#L232-L244

計装されている場所

では、実際にどこで計測されているのか調べてみます。

実は、イベント名の末尾にある sql/handler は、ファイル名 sql/handler.cc を指しています。

このファイルには、すべてのストレージエンジンで共有されるhandlerインターフェイスが実装されています。
ここで MYSQL_TABLE_IO_WAIT というマクロが使われている箇所が計測ポイントです。

sql/handler.cc
// マクロ定義（簡略化）
#define MYSQL_TABLE_IO_WAIT(OP, INDEX, RESULT, PAYLOAD) \
  { \
    /* ... 前処理 ... */ \
    PSI_TABLE_CALL(start_table_io_wait)(...); \
    PAYLOAD /* 実際の処理実行 */ \
    PSI_TABLE_CALL(end_table_io_wait)(...); \
  }

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/sql/handler.cc#L137-L193

このマクロは、以下流れで計装しています。

  1. PSI_TABLE_CALL(start_table_io_wait)を呼び出して、タイマーを開始する
  2. PAYLOAD（実際の処理）を実行する
  3. PSI_TABLE_CALL(end_table_io_wait)を呼び出して、タイマーを終了する

タイマー開始の処理については、更にPSI_TABLE_CALLマクロを経由して、ビルドごとに実装が差し替えられています。

:point_right: ビルドごとのマクロ定義を見る
include/mysql/psi/mysql_table.h
#define PSI_TABLE_CALL(M) psi_table_service->M

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/include/mysql/psi/mysql_table.h#L40

include/mysql/components/services/psi_table.h
#define PSI_TABLE_CALL(M) mysql_service_psi_table_v1->M

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/include/mysql/components/services/psi_table.h#L36

include/pfs_table_provider.h
#define PSI_TABLE_CALL(M) pfs_##M##_v1

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/include/pfs_table_provider.h#L46

最後の実装では、pfs_start_table_io_wait_v1という関数名に置換されています。
この関数定義は以下になります。

storage/perfschema/pfs.cc
/**
  Implementation of the table instrumentation interface.
  @sa PSI_v1::start_table_io_wait_v1
*/
PSI_table_locker *pfs_start_table_io_wait_v1(PSI_table_locker_state *state,
                                             PSI_table *table,
                                             PSI_table_io_operation op,
                                             uint index, const char *src_file,
                                             uint src_line) {

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs.cc#L4140-L4148

この関数内では、待機イベントテーブルevents_waits_currentに記録される情報の元ネタがセットされていることも読み取れます。

pfs_start_table_io_wait_v1
      wait->m_thread_internal_id = pfs_thread->m_thread_internal_id;
      wait->m_class = &global_table_io_class;
      wait->m_timer_start = timer_start;
      wait->m_timer_end = 0;
      wait->m_object_instance_addr = pfs_table->m_identity;
      wait->m_event_id = pfs_thread->m_event_id++;
      wait->m_end_event_id = 0;
      wait->m_operation = table_io_operation_map[static_cast<int>(op)];
      wait->m_flags = 0;
      wait->m_object_type = share->get_object_type();
      wait->m_weak_table_share = share;
      wait->m_weak_version = share->get_version();
      wait->m_index = index;
      wait->m_source_file = src_file;
      wait->m_source_line = src_line;
      wait->m_wait_class = WAIT_CLASS_TABLE;

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/storage/perfschema/pfs.cc#L4197-L4212

計装を呼び出すSQL

では実際にこの計装ヘルパーを呼び出している箇所を特定します。

MYSQL_TABLE_IO_WAITというのは、以下のようなインデックス読み取りや行更新などの主要なデータ操作メソッドで使われています。

ha_index_read_map
int handler::ha_index_read_map(uchar *buf, const uchar *key,
                               key_part_map keypart_map,
                               enum ha_rkey_function find_flag) {
  // ...
  MYSQL_TABLE_IO_WAIT(PSI_TABLE_FETCH_ROW, active_index, result, {
    result = index_read_map(buf, key, keypart_map, find_flag);
  })
  // ...
}

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/sql/handler.cc#L3383-L3411

ha_update_row
int handler::ha_update_row(const uchar *old_data, uchar *new_data) {
  // ...
  MYSQL_TABLE_IO_WAIT(PSI_TABLE_UPDATE_ROW, active_index, error,
                      { error = update_row(old_data, new_data); })
  // ...
}

https://github.com/mysql/mysql-server/blob/056a391cdc1af9b17b5415aee243483d1bac532d/sql/handler.cc#L8229-L8255

つまり、行更新の場合にwait/io/table/sql/handler は、「InnoDBさん、この行を更新してください」とお願いしてから、「終わりました」と返事が来るまでの時間 そのものと言えます。

なお、ここで呼び出されている index_read_map や update_row は仮想関数であり、実際にはInnoDBやMyISAMなどのストレージエンジンの実装が呼び出されます。

MYSQL_TABLE_IO_WAIT を呼び出している箇所をすべて検索すると、sql/handler.cc の中で以下が該当することが分かります。

No 関数名 行番号 説明 SQLクエリ例
1 ha_rnd_next() 3114 テーブルスキャン（次の行） SELECT * FROM table
2 ha_rnd_pos() 3145 位置指定読み取り SELECT * FROM table WHERE rowid = ?
3 ha_sample_next() 3225 サンプリング読み取り SELECT * FROM table TABLESAMPLE SYSTEM(10)
4 ha_index_read_map() 3395 インデックス使用の読み取り SELECT * FROM table WHERE id = 1
5 ha_index_read_last_map() 3424 インデックス最終行読み取り SELECT * FROM table ORDER BY id DESC LIMIT 1
6 ha_index_read_idx_map() 3456 特定インデックス使用の読み取り SELECT * FROM table USE INDEX(idx) WHERE ...
7 ha_index_next() 3492 インデックススキャン（次の行） SELECT * FROM table WHERE id > 10 ORDER BY id
8 ha_index_prev() 3537 インデックススキャン（前の行） SELECT * FROM table WHERE id < 10 ORDER BY id DESC
9 ha_index_first() 3573 インデックス最初の行 SELECT MIN(id) FROM table
10 ha_index_last() 3611 インデックス最後の行 SELECT MAX(id) FROM table
11 ha_index_next_same() 3646 同一キー値の次の行 SELECT * FROM table WHERE id = 1 (複数行)
12 ha_write_row() 8217 行の挿入 INSERT INTO table VALUES (...)
13 ha_update_row() 8248 行の更新 UPDATE table SET col = value WHERE id = 1
14 ha_delete_row() 8278 行の削除 DELETE FROM table WHERE id = 1

このことから、ドキュメントに記載のとおりすべてのCRUD操作が対象になっていることが分かりました。

SQLステートメントごとにイベント発生するのであれば、Database Insightsでよく観測されるのも納得です。

また、AWSドキュメントに記載のあった「io/table/sql/handler イベントは、作業がストレージエンジンに委任されたときに発生します」という記述も、これらのha_*系関数を呼び出したときのことなんだと理解ができます。

ローカルでwait/io/table/sql/handler 待機イベントを発生させてみる

ソースコードで概要を理解したので、実際に体験してみます。

準備

ローカルでMySQL 9を起動します。

:point_right: セットアップの詳細を見る

performance_schema_events_*_history_sizeを指定しているのは、デフォルトの件数ではすぐに履歴が揮発してしまうので、データをゆっくり見る時間を確保するためです。

docker container run --name mysql-9 -e MYSQL_ALLOW_EMPTY_PASSWORD=true -p 13306:3306 --rm mysql:9 \
--performance_schema_events_transactions_history_size=200 \
--performance_schema_events_statements_history_size=1000 \
--performance_schema_events_stages_history_size=1000 \
--performance_schema_events_waits_history_size=1000

パフォーマンススキーマの設定を変更します。

SHOW VARIABLES LIKE 'performance_schema';
-- => ON

-- すべてのインストゥルメントを有効にする
UPDATE performance_schema.setup_instruments
SET ENABLED = 'YES',
      TIMED = 'YES';

 -- コンシューマをすべて有効にする
 -- どのコンシューマが必要なのかは、以下のドキュメントで確認できる
 -- https://dev.mysql.com/doc/refman/9.5/en/performance-schema-consumer-filtering.html
UPDATE performance_schema.setup_consumers
SET ENABLED = 'YES';

適当なテーブルを作って、サンプルデータを挿入します。

CREATE DATABASE sample_db;

USE sample_db;

CREATE TABLE `user` (
  `id` int NOT NULL AUTO_INCREMENT,
  `name` varchar(64) DEFAULT NULL,
  `created_at` timestamp NULL DEFAULT CURRENT_TIMESTAMP,
  `updated_at` timestamp NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;

INSERT INTO user(name) VALUES ('ken');

ここからは、以下のトランザクションを例に待機イベントを見ていきます。

BEGIN;
SELECT * FROM sample_db.user WHERE id = 1 FOR UPDATE;
UPDATE user SET updated_at = now() WHERE id = 1;
COMMIT;

イベントの階層構造

インストゥルメントは以下のドキュメントに記載のとおり、階層構造を持っています。

Within the event hierarchy, wait events nest within stage events, which nest within statement events, which nest within transaction events.

図示すると以下のようになります。

イベント階層構造
transaction
└── statement
    └── stage
        └── wait

この階層に合わせて、順に履歴テーブルを見ていきます。

transactionイベント

まずは、transactionイベントをチェックします。

transactionイベントのクエリ
SELECT
  thread_id, event_id, nesting_event_id, end_event_id,
  ROUND(timer_wait/1000000) duration_in_micro_seconds
FROM
  performance_schema.events_transactions_history
;
thread_id event_id nesting_event_id end_event_id duration_in_micro_seconds
47 173 166 443 2763889

このイベントが、ID=166~443の範囲のイベントの中にネストされていることが分かります。

ちなみに、待機時間が2.7秒となっていますが、これは私が手動でクエリを実行していて、COMMITを実行するまでにかかる時間になっています。

statementイベント

ID=166~443の範囲のイベントに限定して、statementイベントをチェックします。

statementイベントのクエリ
SELECT
  event_id, end_event_id, event_name,
  ROUND(timer_wait/1000000) duration_in_micro_seconds,
  ROUND(lock_time/1000000) lock_duration_in_micro_seconds,
  LEFT(sql_text, 1000) sql_text,
  COALESCE(current_schema,'') db,
  nesting_event_id, nesting_event_type
FROM
  performance_schema.events_statements_history
WHERE
      thread_id = 47
  AND event_id BETWEEN 166 and 443
;
:point_right: statementイベントクエリ結果を見る
event_id end_event_id event_name duration_in_micro_seconds lock_duration_in_micro_seconds sql_text db nesting_event_id nesting_event_type
166 180 statement/sql/begin 136 0 BEGIN sample_db
197 262 statement/sql/select 1695 44 SELECT * FROM sample_db.user WHERE id = 1 LIMIT 0, 1000 FOR UPDATE sample_db 173 TRANSACTION
279 361 statement/sql/update 2625 7 UPDATE user SET updated_at = now() WHERE id = 1 sample_db 173 TRANSACTION
378 450 statement/sql/commit 5087 0 COMMIT sample_db 173 TRANSACTION

BEGINステートメント以外が先程のID=177のtransactionイベントにネストされていることが分かります。

逆に、BEGINステートメントが、transactionイベントをネストしていたことも分かります。

また、各ステートメントは数msで実行完了していたことが分かります。

クエリ結果から分かるイベントの階層構造は以下になります。

イベント階層構造
transaction
└── BEGIN statement ID=166
    └── transaction ID=173
        └── SELECT statement ID=197
        └── UPDATE statement ID=279
        └── COMMIT statement ID=378

stageイベント

続いて、stageイベントをチェックします。先程のCOMMITステートメントイベントのend_event_idが450になっているので、範囲を広げて検索します。

SELECT
  event_id, end_event_id, event_name,
  ROUND(timer_wait/1000000) duration_in_micro_seconds,
  nesting_event_id, nesting_event_type
FROM
  performance_schema.events_stages_history
WHERE
      thread_id = 47
  AND event_id BETWEEN 166 and 450
;
:point_right: stageイベントクエリ結果を見る

BEGINステートメントのstage

event_id end_event_id event_name duration_in_micro_seconds nesting_event_id nesting_event_type
167 169 stage/sql/starting 48 166 STATEMENT
170 170 stage/sql/Executing hook on transaction begin. 1 166 STATEMENT
171 173 stage/sql/starting 12 166 STATEMENT
174 175 stage/sql/query end 5 166 STATEMENT
176 176 stage/sql/closing tables 1 166 STATEMENT
177 178 stage/sql/freeing items 66 166 STATEMENT
179 180 stage/sql/cleaning up 0 166 STATEMENT

SELECTステートメントのstage

event_id end_event_id event_name duration_in_micro_seconds nesting_event_id nesting_event_type
198 201 stage/sql/starting 260 197 STATEMENT
202 202 stage/sql/checking permissions 6 197 STATEMENT
203 203 stage/sql/checking permissions 2 197 STATEMENT
204 210 stage/sql/Opening tables 336 197 STATEMENT
211 213 stage/sql/init 20 197 STATEMENT
214 219 stage/sql/System lock 85 197 STATEMENT
220 220 stage/sql/optimizing 38 197 STATEMENT
221 237 stage/sql/statistics 527 197 STATEMENT
238 239 stage/sql/preparing 48 197 STATEMENT
240 240 stage/sql/executing 132 197 STATEMENT
241 241 stage/sql/end 3 197 STATEMENT
242 243 stage/sql/query end 3 197 STATEMENT
244 247 stage/sql/waiting for handler commit 41 197 STATEMENT
248 258 stage/sql/closing tables 16 197 STATEMENT
259 260 stage/sql/freeing items 167 197 STATEMENT
261 262 stage/sql/cleaning up 1 197 STATEMENT

UPDATEステートメントのstage

event_id end_event_id event_name duration_in_micro_seconds nesting_event_id nesting_event_type
280 283 stage/sql/starting 297 279 STATEMENT
284 284 stage/sql/checking permissions 7 279 STATEMENT
285 291 stage/sql/Opening tables 90 279 STATEMENT
292 294 stage/sql/init 7 279 STATEMENT
295 301 stage/sql/System lock 201 279 STATEMENT
302 341 stage/sql/updating 1747 279 STATEMENT
342 342 stage/sql/end 6 279 STATEMENT
343 344 stage/sql/query end 4 279 STATEMENT
345 347 stage/sql/waiting for handler commit 25 279 STATEMENT
348 357 stage/sql/closing tables 28 279 STATEMENT
358 359 stage/sql/freeing items 204 279 STATEMENT
360 361 stage/sql/cleaning up 1 279 STATEMENT

COMMITステートメントのstage

event_id end_event_id event_name duration_in_micro_seconds nesting_event_id nesting_event_type
379 382 stage/sql/starting 107 378 STATEMENT
383 443 stage/sql/waiting for handler commit 4767 378 STATEMENT
444 445 stage/sql/query end 10 378 STATEMENT
446 446 stage/sql/closing tables 4 378 STATEMENT
447 448 stage/sql/freeing items 185 378 STATEMENT
449 450 stage/sql/cleaning up 1 378 STATEMENT

nesting_event_idを使って、どのステートメントによるステージなのかを区別できます。

イベント階層構造
transaction
└── BEGIN statement ID=166
    └── transaction ID=173
        └── SELECT statement ID=197
        │   └── stage/sql/executing ID=240
        └── UPDATE statement ID=279
        │   └── stage/sql/updating ID=302
        └── COMMIT statement ID=378

クエリ結果からは、各SQLステートメントは複数のステージ処理で構成されていることが分かります。

waitイベント

最後に、waitイベントをチェックします。

:point_right: 待機イベントの全量を見る
SELECT
  event_id, end_event_id, event_name,
  source,
  ROUND(timer_wait/1000000) t,
  COALESCE(object_type, '') obj_type,
  COALESCE(object_schema,'') obj_scheme,
  COALESCE(object_name,'') obj_name,
  COALESCE(index_name, '') idx,
  operation op,
  nesting_event_id, nesting_event_type
FROM
  performance_schema.events_waits_history
WHERE
      thread_id = 47
  AND event_id BETWEEN 166 and 450
;

# event_id	end_event_id	event_name	source	duration_in_micro_seconds	obj_type	obj_scheme	obj_name	idx	op	nesting_event_id	nesting_event_type
294	294	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	292	STAGE
297	297	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	296	WAIT
298	298	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	296	WAIT
299	299	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	296	WAIT
296	299	wait/lock/table/sql/handler	handler.cc:8148	4	TABLE	sample_db	user	PRIMARY	write external	295	STAGE
300	300	wait/synch/sxlock/innodb/dict_table_stats	dict0dict.cc:436	0					shared_lock	295	STAGE
301	301	wait/synch/mutex/sql/THD::LOCK_query_plan	sql_class.h:1324	0					lock	295	STAGE
304	304	wait/synch/mutex/innodb/trx_mutex	lock0priv.ic:155	0					lock	303	WAIT
305	305	wait/synch/sxlock/innodb/index_tree_rw_lock	btr0cur.cc:865	0					shared_lock	303	WAIT
306	306	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	1					shared_lock	303	WAIT
307	307	wait/synch/sxlock/innodb/lock_sys_global_rw_lock	lock0lock.cc:5521	6					shared_lock	303	WAIT
308	308	wait/synch/mutex/innodb/lock_sys_page_mutex	lock0lock.cc:5521	0					lock	303	WAIT
309	309	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:1672	0					lock	303	WAIT
303	309	wait/io/table/sql/handler	handler.cc:3395	108	TABLE	sample_db	user	PRIMARY	fetch	302	STAGE
311	311	wait/synch/sxlock/innodb/hash_table_locks	buf0block_hint.cc:73	0					shared_lock	310	WAIT
312	312	wait/synch/mutex/innodb/trx_undo_mutex	trx0rec.cc:2197	0					lock	310	WAIT
313	313	wait/synch/mutex/innodb/undo_space_rseg_mutex	trx0types.h:224	1					lock	310	WAIT
314	314	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
315	315	wait/synch/mutex/innodb/fil_system_mutex	fil0fil.cc:2220	1					lock	310	WAIT
316	316	wait/synch/sxlock/innodb/fil_space_latch	fsp0fsp.cc:3139	1					exclusive_lock	310	WAIT
317	317	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	1					shared_lock	310	WAIT
318	318	wait/synch/mutex/innodb/fil_system_mutex	fil0fil.cc:7278	0					lock	310	WAIT
319	319	wait/synch/mutex/innodb/fil_system_mutex	fil0fil.cc:2220	0					lock	310	WAIT
320	320	wait/synch/sxlock/innodb/fil_space_latch	fsp0fsp.cc:2312	0					exclusive_lock	310	WAIT
321	321	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
322	322	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
323	323	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
324	324	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
325	325	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
326	326	wait/synch/mutex/innodb/buf_pool_free_list_mutex	buf0lru.cc:1208	0					lock	310	WAIT
327	327	wait/synch/mutex/innodb/buf_pool_LRU_list_mutex	buf0buf.cc:5091	0					lock	310	WAIT
328	328	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:5095	0					exclusive_lock	310	WAIT
329	329	wait/synch/mutex/innodb/fil_system_mutex	fil0fil.cc:2220	0					lock	310	WAIT
330	330	wait/synch/mutex/innodb/fil_system_mutex	fil0fil.cc:7303	0					lock	310	WAIT
331	331	wait/synch/sxlock/innodb/log_sn_lock	log0buf.cc:553	0					shared_lock	310	WAIT
332	332	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	310	WAIT
333	333	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	310	WAIT
334	334	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	310	WAIT
335	335	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	310	WAIT
336	336	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	310	WAIT
337	337	wait/synch/sxlock/innodb/log_sn_lock	log0buf.cc:553	0					shared_lock	310	WAIT
338	338	wait/synch/sxlock/innodb/log_sn_lock	log0buf.cc:553	0					shared_lock	310	WAIT
339	339	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	310	WAIT
340	340	wait/synch/mutex/innodb/recalc_pool_mutex	dict0stats_bg.cc:124	1					lock	310	WAIT
310	340	wait/io/table/sql/handler	handler.cc:8248	850	TABLE	sample_db	user	PRIMARY	update	302	STAGE
341	341	wait/synch/mutex/sql/THD::LOCK_query_plan	sql_class.h:1324	0					lock	302	STAGE
344	344	wait/synch/mutex/sql/THD::LOCK_query_plan	sql_class.h:1324	0					lock	343	STAGE
346	346	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:5871	0					lock	345	STAGE
347	347	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:5871	0					lock	345	STAGE
349	349	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	348	STAGE
350	350	wait/synch/mutex/sql/THD::LOCK_thd_data	sql_base.cc:1811	0					lock	348	STAGE
351	351	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	348	STAGE
352	352	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	1					lock	348	STAGE
353	353	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	348	STAGE
354	354	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	348	STAGE
355	355	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	348	STAGE
356	356	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	348	STAGE
357	357	wait/synch/mutex/sql/LOCK_table_cache	table_cache.h:167	0					lock	348	STAGE
359	359	wait/io/socket/sql/client_connection	open_ssl::bio::socket:3	146	SOCKET		::ffff:160.79.104.10:61530		send	358	STAGE
361	361	wait/synch/mutex/sql/THD::LOCK_thd_query	sql_class.cc:2608	0					lock	360	STAGE
363	363	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	362	WAIT
364	364	wait/io/socket/sql/client_connection	viosocket.cc:861		SOCKET		::ffff:160.79.104.10:61530		select	362	WAIT
365	365	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	362	WAIT
366	366	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	362	WAIT
362	366	idle	init_net_server_extension.cc:68	1046080					idle		
369	369	wait/synch/mutex/sql/THD::LOCK_thd_data	sql_class.h:4326	0					lock	368	STAGE
370	370	wait/io/socket/sql/client_connection	open_ssl::bio::socket:3	170	SOCKET		::ffff:160.79.104.10:61530		send	368	STAGE
372	372	wait/synch/mutex/sql/THD::LOCK_thd_query	sql_class.cc:2608	1					lock	371	STAGE
374	374	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	373	WAIT
375	375	wait/io/socket/sql/client_connection	viosocket.cc:861		SOCKET		::ffff:160.79.104.10:61530		select	373	WAIT
376	376	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	373	WAIT
377	377	wait/io/socket/sql/client_connection	open_ssl::bio::socket:2		SOCKET		::ffff:160.79.104.10:61530		recv	373	WAIT
373	377	idle	init_net_server_extension.cc:68	17555					idle		
380	380	wait/synch/mutex/sql/THD::LOCK_thd_data	sql_class.h:4326	0					lock	379	STAGE
381	381	wait/synch/mutex/sql/THD::LOCK_thd_query	sql_class.cc:2608	0					lock	379	STAGE
382	382	wait/synch/mutex/sql/THD::LOCK_query_plan	sql_class.h:1324	0					lock	379	STAGE
384	384	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	383	STAGE
385	385	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1471	0					lock	383	STAGE
386	386	wait/synch/mutex/innodb/undo_space_rseg_mutex	trx0types.h:224	0					lock	383	STAGE
387	387	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	383	STAGE
388	388	wait/synch/sxlock/innodb/log_sn_lock	log0buf.cc:553	0					shared_lock	383	STAGE
389	389	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	383	STAGE
390	390	wait/synch/mutex/innodb/trx_sys_mutex	trx0sys.h:813	0					lock	383	STAGE
391	391	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	383	STAGE
392	392	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue	rpl_commit_stage_manager.h:107	7					lock	383	STAGE
393	393	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log	rpl_commit_stage_manager.cc:380	0					lock	383	STAGE
394	394	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_flush_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
395	395	wait/synch/mutex/sql/LOCK_plugin	sql_plugin.cc:2696	0					lock	383	STAGE
396	396	wait/synch/mutex/innodb/log_writer_mutex	log0write.cc:971	0					lock	383	STAGE
397	397	wait/io/file/innodb/innodb_log_file	log0files_io.cc:378	37	FILE		/var/lib/mysql/#innodb_redo/#ib_redo9		write	383	STAGE
398	398	wait/synch/mutex/innodb/log_flusher_mutex	log0write.cc:1033	0					try_lock	383	STAGE
399	399	wait/io/file/innodb/innodb_log_file	log0files_io.cc:307	829	FILE		/var/lib/mysql/#innodb_redo/#ib_redo9		sync	383	STAGE
400	400	wait/synch/rwlock/sql/gtid_commit_rollback	rpl_gtid.h:487	6					read_lock	383	STAGE
401	401	wait/synch/mutex/sql/Gtid_state	rpl_gtid.h:962	0					lock	383	STAGE
402	402	wait/synch/rwlock/sql/gtid_commit_rollback	rpl_gtid.h:487	0					read_lock	383	STAGE
403	403	wait/io/file/sql/binlog	mf_iocache.cc:1693	102	FILE		/var/lib/mysql/binlog.000002		write	383	STAGE
404	404	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
405	405	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync	rpl_commit_stage_manager.cc:380	0					lock	383	STAGE
406	406	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_sync_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
407	407	wait/io/file/sql/binlog	basic_ostream.cc:89	2719	FILE		/var/lib/mysql/binlog.000002		sync	383	STAGE
408	408	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_binlog_end_pos	binlog.h:962	0					lock	383	STAGE
409	409	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
410	410	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit	rpl_commit_stage_manager.cc:380	0					lock	383	STAGE
411	411	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_commit_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
412	412	wait/synch/mutex/sql/LOCK_replica_trans_dep_tracker	binlog.cc:7554	0					lock	383	STAGE
413	413	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1471	0					lock	383	STAGE
414	414	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1495	0					lock	383	STAGE
415	415	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1471	0					lock	383	STAGE
416	416	wait/synch/mutex/innodb/undo_space_rseg_mutex	trx0types.h:224	0					lock	383	STAGE
417	417	wait/synch/mutex/innodb/purge_sys_pq_mutex	trx0trx.cc:1496	0					lock	383	STAGE
418	418	wait/synch/mutex/innodb/trx_sys_serialisation_mutex	trx0sys.h:831	0					lock	383	STAGE
419	419	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	383	STAGE
420	420	wait/synch/sxlock/innodb/hash_table_locks	buf0buf.cc:3821	0					shared_lock	383	STAGE
421	421	wait/synch/sxlock/innodb/log_sn_lock	log0buf.cc:553	0					shared_lock	383	STAGE
422	422	wait/synch/mutex/innodb/flush_list_mutex	buf0flu.cc:383	0					lock	383	STAGE
423	423	wait/synch/mutex/innodb/trx_sys_mutex	trx0sys.h:813	0					lock	383	STAGE
424	424	wait/synch/mutex/innodb/trx_sys_shard_mutex	trx0trx.cc:1878	0					lock	383	STAGE
425	425	wait/synch/mutex/innodb/trx_mutex	trx0trx.cc:1842	0					lock	383	STAGE
426	426	wait/synch/mutex/innodb/trx_sys_serialisation_mutex	trx0sys.h:831	0					lock	383	STAGE
427	427	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:5894	0					lock	383	STAGE
428	428	wait/synch/sxlock/innodb/lock_sys_global_rw_lock	lock0lock.cc:4121	1					shared_lock	383	STAGE
429	429	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:4147	0					lock	383	STAGE
430	430	wait/synch/mutex/innodb/lock_sys_page_mutex	lock0priv.h:1045	0					lock	383	STAGE
431	431	wait/synch/mutex/innodb/trx_mutex	lock0priv.h:1046	0					lock	383	STAGE
432	432	wait/synch/mutex/innodb/lock_sys_table_mutex	lock0priv.h:1054	0					lock	383	STAGE
433	433	wait/synch/mutex/innodb/trx_mutex	lock0priv.h:1055	0					lock	383	STAGE
434	434	wait/synch/mutex/innodb/trx_mutex	lock0lock.cc:5933	0					lock	383	STAGE
435	435	wait/synch/mutex/innodb/trx_mutex	trx0trx.cc:2085	0					lock	383	STAGE
436	436	wait/synch/mutex/innodb/trx_mutex	trx0trx.h:1523	0					lock	383	STAGE
437	437	wait/synch/rwlock/sql/gtid_commit_rollback	rpl_gtid.h:487	0					read_lock	383	STAGE
438	438	wait/synch/mutex/sql/Gtid_state	rpl_gtid.h:962	1					lock	383	STAGE
439	439	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_xids	binlog.cc:5608	0					lock	383	STAGE
440	440	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_after_commit_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
441	441	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_after_commit	rpl_commit_stage_manager.cc:380	0					lock	383	STAGE
442	442	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_after_commit_queue	rpl_commit_stage_manager.h:107	0					lock	383	STAGE
443	443	wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_done	rpl_commit_stage_manager.cc:485	0					lock	383	STAGE
445	445	wait/synch/mutex/sql/THD::LOCK_query_plan	sql_class.h:1324	1					lock	444	STAGE
448	448	wait/io/socket/sql/client_connection	open_ssl::bio::socket:3	124	SOCKET		::ffff:160.79.104.10:61530		send	447	STAGE
450	450	wait/synch/mutex/sql/THD::LOCK_thd_query	sql_class.cc:2608	0					lock	449	STAGE

量が多いので、wait/io/table/sql/hanlderに相当する部分だけ抜き出します。

SELECT
  event_id, end_event_id, event_name,
  source,
  ROUND(timer_wait/1000000) duration_in_micro_seconds,
  operation op,
  nesting_event_id, nesting_event_type
FROM
  performance_schema.events_waits_history
WHERE
      thread_id = 47
  AND event_id BETWEEN 166 and 450
  AND event_name = 'wait/io/table/sql/handler'
;
event_id end_event_id source duration_in_micro_seconds op nesting_event_id nesting_event_type
303 309 handler.cc:3395 108 fetch 302 STAGE
310 340 handler.cc:8248 850 update 302 STAGE
イベント階層構造
transaction
└── BEGIN statement ID=166
    └── transaction ID=173
        └── SELECT statement ID=197
        └── UPDATE statement ID=279
        │   └── stage/sql/updating ID=302
        │       └── wait/io/table/sql/handler fetch ID=302
        │       └── wait/io/table/sql/handler update ID=310
        └── COMMIT statement ID=378

遂にたどり着きました。

sourceを見ると、前述のソースコード調査で特定した以下の関数での計装ヘルパー呼び出し行番号と一致しています。

関数名 行番号
ha_index_read_map() 3395
ha_update_row() 8248

なぜwait/io/table/sql/handler待機イベントは「原因特定」に役立たないのか

このイベント単体は「DB内で仕事をしている時間の合計」であり、ボトルネックの種類（I/Oかロックか CPUか）については教えてくれないことが、原因特定に役立たないとした理由です。

この記事では、wait/io/table/sql/handlerの正体をソースコードレベルで明らかにしてきました。

その結果、記録された待機イベントは単に、どのトランザクション、ステートメント、ステージでどのくらいの時間を使ったか、という事実しか分からないということです。

つまり、なぜそれが引き起こされたのかは待機イベントを見ても分かりません。

このイベントの性質を理解すると、なぜwait/io/table/sql/handlerがデバッグの決定打にならないのかが分かります。

  1. 範囲が広すぎる
    • ストレージエンジンの中で何が起きているか（ディスク読み込み中なのか、ロック待ち中なのか、単にCPU計算中なのか）を区別しません
  2. 包含関係
    • パフォーマンススキーマはイベントをネストして計測します。例えば、ha_update_row の中でロック取得が発生した場合、wait/synch待機イベントが発生します。しかし、親イベントである wait/io/table/sql/handler の計測時間は、その子イベントの時間も含んでいます。

したがって、Database Insights などでこのイベントが支配的であることは、「DBで時間がかかっている」以上の情報をほとんど与えてくれません。

幸い、Database Insightsはその点を考慮して独自のレポーティングを提供しています。

具体的には、wait/io/table/sql/handler待機イベントにネストされた他の待機イベント（例：synch/mutex/innodb/aurora_lock_thread_slot_futex）が支配的である場合は、その待機イベントを根本原因と捉えて、wait/io/table/sql/handler待機イベントではなく、synch/mutex/innodb/aurora_lock_thread_slot_futexを表示してくれるようです。

トップSQLセクションでは、wait/io/table/sql/handler待機イベント以外も含めた待機イベントごとの負荷の割合を見ることができるので、そこで切り分けていくのが良いと思います。

image.png

では、代わりに何を見るべきか？

実際のケースでは、wait/io/table/sql/handler以外の待機イベントとその他メトリクスを組み合わせて、デバッグすることが必要になります。

いろんなシナリオでのデバッグ例はAWS公式が情報発信しているので、こちらに倣うのが良いと思います。

誰かが「wait/io/table/sql/handlerという待機イベントが大量に出ていてCPU負荷が上がってるっぽいです！このイベントについて調査してみます！」と言い始めたら、そっと本記事と上記AWS記事を差し出し、別のアプローチでの調査を促すのが良いかと思います。

参考

8
0
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
8
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?