DEBUG_SYNCことはじめ

TL;DR

• 本気でDEBUG_SYNC使いたい人はそもそもこっち読むべき
  • MySQL :: MySQL Internals Manual :: 24.6 Debug Sync Facility

---

DEBUG_SYNCとは、デバッグビルドのmysqldの中だけでブレークポイントみたいなものを設定して、ブレークポイントに差し掛かったら他のコネクションを使って操作を試してみられる…と思ってもらえれば多分大丈夫。

ただし任意の箇所でブレークできるわけではなく、コードの中に埋め込まれた “synchronization points” の場所にだけ仕掛けられる。以下、わかりやすさ優先で ブレークポイント と呼ぶことにする。

基本的な使い方はこんな感じ。

1. mysqld --debug-sync-timeout=n で起動する (デフォルトは0でDEBUG_SYNC無効)
2. ブレークポイントを通らせたいスレッドで SET DEBUG_SYNC = 'synchronization_pointsの名前 SIGNAL 送信シグナル名 WAIT_FOR テキトーなシグナル名'
3. 2. のスレッドがブレークポイントを通った時に操作をしたいスレッドで SET DEBUG_SYNC = 'now WAIT_FOR 送信シグナル名
4. 3. のスレッドはその時点で debug_sync_timeout 秒間の待機に入るので、その間に 2. のスレッドでブレークポイントを通るような操作をする。
5. 2. のスレッドがブレークポイントを通ると SIGNAL 句で設定した 送信シグナル名 がブロードキャストされて、 3. のスレッドがそれを受け取って復帰する。 2. のスレッドはそのまま WAIT_FOR 句で テキトーなシグナル名 がブロードキャストされるのを待つ
6. 3. のスレッドなりシェルなりで好きな操作をする
7. 3. のスレッドで SET DEBUG_SYNC = 'now SIGNAL テキトーなシグナル名' で テキトーなシグナル名 がブロードキャストされて 2. のスレッドが復帰して残りの処理をする

3. のスレッドは本質ではない(別にこれがなくてもブレークポイントを通ったあと待ちに入る)けれど、これがないと「ブレークポイントを通るまでの処理をしているのか、通ったあとに来ないシグナルを待っているのか」の区別がつかないのでこうするのが吉だと思う。

---

デバッグビルドしたmysqldを --debug-sync-timeout=n (n > 0) で起動。

$ ./bin/mysqld --max-allowed-packet=1G --gtid_mode=ON --enforce_gtid_consistency=ON --debug-sync-timeout=600 --daemonize

autocommit環境下でストレージエンジンへのINSERT後COMMITになる前の状態、とかを観測してみたりできる。

conn1> SET DEBUG_SYNC = 'ib_after_row_insert SIGNAL here WAIT_FOR yoku0825';
Query OK, 0 rows affected (0.01 sec)

conn2> SET DEBUG_SYNC = 'now WAIT_FOR here'; -- nowは特殊なキーワードで常にブレークする。nowにヒットしたのでhereシグナル待ちに入る

conn1> INSERT INTO d1.t1 SET lo = REPEAT('a', 128 * 1024 * 1024); -- ib_after_row_insertに到達したあと hereシグナルを送ってyoku0825シグナルを待つ

conn2> SET DEBUG_SYNC = 'now WAIT_FOR here'; -- hereシグナルを受け取って叩き起こされる
Query OK, 0 rows affected (7.64 sec)

conn2> SHOW PROCESSLIST;
+----+-----------------+-----------+------+---------+------+---------------------------------------+-----------------------------------------------------------+
| Id | User            | Host      | db   | Command | Time | State                                 | Info                                                      |
+----+-----------------+-----------+------+---------+------+---------------------------------------+-----------------------------------------------------------+
|  1 | event_scheduler | localhost | NULL | Daemon  |   87 | Waiting on empty queue                | NULL                                                      |
|  3 | root            | localhost | NULL | Query   |    0 | starting                              | SHOW PROCESSLIST                                          |
|  4 | root            | localhost | NULL | Query   |   20 | debug sync point: ib_after_row_insert | INSERT INTO d1.t1 SET lo = REPEAT('a', 128 * 1024 * 1024) |
+----+-----------------+-----------+------+---------+------+---------------------------------------+-----------------------------------------------------------+
3 rows in set (0.03 sec)

conn2> SELECT COUNT(*) FROM d1.t1; -- ib_after_row_insertはCOMMITの手前なのでautocommitでも行は見えない
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

conn2> quit -- 1回抜けてシェルに
Bye

### バイナリログにも書かれていない
$ mysqlbinlog /usr/mysql/5.7.23/data/bin.000011 | tail 
mysqlbinlog: [Warning] unknown variable 'loose-default-character-set=utf8mb4'.
# at 134218325
#200721 15:34:00 server id 1  end_log_pos 134218402 CRC32 0x8f60827e    Query   thread_id=4     exec_time=1     error_code=0
SET TIMESTAMP=1595313240/*!*/;
TRUNCATE d1.t1
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

$ mysql -S /tmp/mysql.sock -uroot
mysql> SET DEBUG_SYNC = 'now SIGNAL yoku0825';  -- yoku0825シグナルを送ってやる
Query OK, 0 rows affected (0.00 sec)

conn1> INSERT INTO d1.t1 SET lo = REPEAT('a', 128 * 1024 * 1024); -- yoku0825シグナルに叩き起こされてINSERTが完了する
Query OK, 1 row affected (2 min 28.38 sec)

楽しい、いろいろ捗りそう（要出典: 何が）

​