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 に関して、いくつか注意点を挙げておく:

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