Debugging MySQL/MariaDB (2): DBUG and Trace
この記事は Debugging MySQL/MariaDB (1): Build and Test の続編である。(1) で行った準備を基礎として、DBUG マクロおよびトレースファイルを用いて MySQL/MariaDB をデバッグする方法を説明する。(1) で述べた通り、MySQL 8.0.24 および MariaDB 10.5.9 を前提として解説する。
この記事を書くにあたり、書籍 Expert MySQL を大いに参考にした。これほどにニッチな本を買いてくれた Charles Bell 氏に感謝したい。
DBUG Macros
MySQL/MariaDB のコードをひと目見れば、その随所で DBUG_XXX
なるマクロが使われていることに気づくだろう。これらのマクロは、MySQL/MariaDB をデバッグする上で重要な役割を果たす。この節では、DBUG_XXX
マクロの中でも特に重要と思われる、DBUG_ASSERT
および DBUG_ENTER
, DBUG_RETURN
について説明する。
先に例を挙げておこう。以下は MariaDB 10.5.9 の sql/handler.cc
からの引用である。コード中の ...
は省略を表すものとする。
int handler::ha_rnd_next(uchar *buf) { int result; DBUG_ENTER("handler::ha_rnd_next"); DBUG_ASSERT(table_share->tmp_table != NO_TMP_TABLE || m_lock_type != F_UNLCK); DBUG_ASSERT(inited == RND); ... DBUG_RETURN(result); }
DBUG_ASSERT
DBUG_ASSERT
マクロを使用することで、デバッグビルドでのみチェックされるアサーションを書くことができる。アサーションが真でない場合、DBUG_ASERT
は stack trace を吐いてサーバーを異常終了させる。
すでにコードに書かれているアサーションは、(バグがなければ)常に正しいと想定されるため、コードを読む上で参考になる。上の例であれば、次の式が常に成立すると仮定してコードを読んで差し支えない。
table_share->tmp_table != NO_TMP_TABLE || m_lock_type != F_UNLCK
DBUG_ASSERT
に関して、いくつか注意点を挙げておく:
- MySQL 8.0.24 以降では、
DBUG_ASSERT
はすべて標準のassert
で置き換えられている。詳しくはこちらのコミット を参照。 - MariaDB ではアサーションが失敗した場合の挙動を変えることができる。例えば、cmake に
DBUG_ASSERT_AS_PRINTF
を渡すと、サーバーは異常終了せずエラーログに失敗を記録する。
DBUG_ENTER, DBUG_RETURN
DBUG_ENTER
, DBUG_RETURN
なるマクロをペアで用いることで、トレースファイルに関数の開始および終了が記録されるようになる。上で挙げた handler::ha_rnd_next()
の場合だと次のようなトレースが生成される。生成方法は後述する。
... T@1: >handler::ha_rnd_next T@1: | >int ha_innobase::rnd_next T@1: | | >int ha_innobase::index_first T@1: | | | >int ha_innobase::index_read ... T@1: | | | <int ha_innobase::index_read T@1: | | <int ha_innobase::index_first T@1: | <int ha_innobase::rnd_next T@1: <handler::ha_rnd_next ...
handler::ha_rnd_next()
が呼ばれると、その中で init_ha_innobase::rnd_next()
が呼ばれ、さらにその中で…という具合に関数呼び出しの流れがわかる。この情報があるとデバッグが容易になるので、新しい関数を追加するときは原則 DBUG_ENTER
, DBUG_RETURN
を用いるのがよいだろう。
なお、MySQL 8.0.18 以降においては、DBUG_ENTER
, DBUG_RETURN
の代わりに DBUG_TRACE
を用いるようである。DBUG_TRACE
は関数の先頭に挿入するだけなので、こちらの方が手間が少ないかもしれない。詳しくは MySQL 8.0.18 のリリースノート を参照のこと。
Debug Trace
mysqld に --debug
オプションを渡すと、トレースファイルを生成できるらしい。「らしい」なのは、筆者がこの方法を使ったことがないからである。
筆者はもっぱら mysql-test-run.pl を使ってデバッグしているので、トレースの出力もこちらでやる。(1) の記事のテストケース(以下に example.test のみ掲載)からトレースを生成してみよう。
CREATE TABLE t1 (a INT); INSERT INTO t1 VALUES (1); SELECT * FROM t1; DROP TABLE t1; --error ER_BAD_TABLE_ERROR DROP TABLE t;
(1) の記事で説明した方法で MySQL/MariaDB をデバッグビルドし、--debug
オプションを指定して mysql-test-run.pl を実行すればよい。トレースファイルは bld/mysql-test/var/log/mysqld.1.trace
に生成される。
cd bld/mysql-test/ ./mysql-test-run.pl innodb.example --debug
以下に MySQL 8.0.24 で生成したトレースファイルの一部を掲載する。関数の中で行われている手続きや現在実行されているクエリ (CREATE TABLE t1 (a INT)
)、変数の値など様々な情報が見て取れるだろう。
トレースは、コードの実行の流れを理解する、GDB のブレークポイントの位置を決めるなど様々な目的で活用できる。
... T@9: | >dispatch_command T@9: | | info: command: 3 ... T@9: | | query: CREATE TABLE t1 (a INT) ... T@9: | | | >lex_start T@9: | | | | >LEX::new_top_level_query T@9: | | | | | >LEX::new_query T@9: | | | | | <LEX::new_query T@9: | | | | <LEX::new_top_level_query T@9: | | | <lex_start ... T@9: | | | | | | | | | | | | >THD::decide_logging_format T@9: | | | | | | | | | | | | | info: query: CREATE TABLE t1 (a INT) T@9: | | | | | | | | | | | | | info: variables.binlog_format: 2 ... T@9: | | | | | | | | | | | | <THD::decide_logging_format ... T@9: | <dispatch_command ...
実際に試してみればわかるが、トレースファイルは非常に巨大である。これは、サーバーの起動から終了までのすべての情報が記録されているためである。しかし、example.test のクエリに対応する部分のみであれば、ぎりぎり目で追えるサイズになるはずなので、諦める必要はない。CREATE TABLE t1 (a INT)
と DROP TABLE t
でトレースを検索すれば、ある程度読むべき範囲が絞り込める。
なお、--debug
の代わりに --debug-common
を指定すれば出力される内容をいくらか絞ることができる。詳しくは mysql-test-run.pl のドキュメント を参照してほしい。
./mysql-test-run.pl innodb.example --debug-common