Debugging MySQL/MariaDB (4): Debugging with rr
重い腰を上げて Debugging MySQL/MariaDB シリーズの第4弾を書いている。今回は rr debugger を使用したデバッグについて説明する。Intel または AMD の CPU を搭載した物理マシンに Linux (kernel 3.11+) をネイティブインストールした環境を前提とする。
rr debugger
rr は Pernoscoによって開発されているデバッガーである。rr は gdb と同じ感覚で使えるが、次に挙げる gdb にはないすばらしい特徴を備えている。
- プログラムの実行を記録し、バグを何度でも決定的に再現することができる。
- ブレークポイントやウォッチポイントまで逆実行 (reverse execution) できる。
これらの特徴の何がすばらしいのか？想像してほしい。散発的なバグ（再現したりしなかったりするバグ）を GDB でデバッグするのは苦痛である。ハズレの実行を引いてしまった場合、すべてが無駄になる。また、散発的でないバグであっても、手が滑って調べたい箇所を過ぎてしまうということはよくある。あるいは、ある値がどこで変数にセットされたか調べたいと思ったことはないだろうか？rr を使えば、これらの問題をすべて解決することができるのである。
Install rr
rr の公式ページ の説明にしたがって rr をインストールしよう。もし、比較的新しい CPU を使っているなら、ソースからビルドしてインストールするのを勧める。リリース版の rr が、その CPU のマイクロアーキテクチャを識別できない可能性があるためである。
Hardware/software configuration > OS configuration にしたがって OS の設定を変更する。AMD Ryzen を使っている場合は、更に こちらの設定 を施す必要がある。
Debug MariaDB with rr
まずデバッグビルドする。※ Performance schema と debug trace が有効だと、rr と組合せたときに遅くなるので無効にしているが、有効だと rr が使えないわけではない。
mkdir bld && cd $_ cmake .. -DCMAKE_BUILD_TYPE=Debug -DPLUGIN_PERFSCHEMA=NO -DWITH_DBUG_TRACE=OFF cmake --build . --config Debug -j 8
デバッグしたいテストケースを指定して、--rr オプション付きで MTR を実行する。
./mysql-test/mtr innodb.alter_table --rr
すると rr のトレースファイルが生成され、今回の実行を何度でもデバッグできるようになる。rr replay でトレースを再生できる。
rr replay ./mysql-test/var/log/mysqld.1.rr/latest-trace
> rr replay ./mysql-test/var/log/mysqld.1.rr/latest-trace
...
(rr) b dispatch_command
Breakpoint 1 at 0x55f844a57dc6: file /home/nayuta_mariadb/repo/mariadb-server/10.9/sql/sql_parse.cc, line 1595.
(rr) c
...
Thread 2 hit Breakpoint 1, dispatch_command (command=COM_QUERY, thd=0x7f8c64001ba8, packet=0x7f8c6400c589 "SHOW SLAVE STATUS", packet_length=17, blocking=true) at /home/nayuta_mariadb/repo/mariadb-server/10.9/sql/sql_parse.cc:1595
1595 {
(rr) n
1596 NET *net= &thd->net;
(rr) n
1597 bool error= 0;
(rr) n
1598 bool do_end_of_statement= true;
(rr) n
1600 DBUG_PRINT("info", ("command: %d %s", command,
(rr) n
1604 bool drop_more_results= 0;
(rr) rn
1600 DBUG_PRINT("info", ("command: %d %s", command,
(rr) watch error
Hardware watchpoint 2: error
(rr) rc
Continuing.
Thread 2 hit Hardware watchpoint 2: error
Old value = false
New value = 85
dispatch_command (command=COM_QUERY, thd=0x7f8c64001ba8, packet=0x7f8c6400c589 "SHOW SLAVE STATUS", packet_length=17, blocking=true) at /home/nayuta_mariadb/repo/mariadb-server/10.9/sql/sql_parse.cc:1597
1597 bool error= 0
上の実行例からわかるように、rn (reverse-next) で1ステップ戻ることができ、rc (reverse-continue) で逆向きに continue することができる。watch 等も gdb と同様に機能する。この便利さがわかるだろうか？私の説明で便利さが伝わなかったとしても、騙されたと思って一度使ってみてほしい。デバッグの効率が数倍上がるはずだ。
Debug MySQL with rr
私の知る限り MySQL の MTR は --rr オプションをサポートしていないが、次のようにしてトレースを生成することができる。
（まだ書いてない）
まとめ
Dive into InnoDB MVCC
LEVEL-15FX069-R9-RXZX に Debian 11 をインストールする
この1年間 VirtualBox で MariaDB を開発してきたが、色々と不便な点 (Mozilla rr が使えない等) があり、Linux をネイティブインストールしたビルドマシンを構築した。その過程を記録しておく。
OS は Debian 11 を使う。サーバーは iiyama の LEVEL-15FX069-R9-RXZX 。ノート PC にデスクトップ用の Ryzen 9 を搭載した変態マシンである。
以下、やったことのメモ:
- ここ から Live インストールイメージをダウンロードし、Rufus を使って USB メモリに焼く。今回は debian-live-11.0.0-amd64-gnome+nonfree.iso を使った。
- Windows 10 の「設定 > 更新とセキュリティ > 回復 > PC の起動をカスタマイズする（今すぐ再起動する）> デバイスの使用」から、USB から Debian を起動し動作確認。Wi-Fi 含め out-of-the-box で使えた。
- もう一度 USB メモリから Debian を起動し、Graphical Installer から Debian をインストール。特に迷うような箇所はない。何となく encrypted LVM にした。
apt-get install sshして、/etc/ssh_configをいい感じに設定する。sudo group に個人ユーザーを追加する。あとは ssh 経由でいい感じに設定する。- Debian での MariaDB のビルドは Building MariaDB on Debian を見ればよい。
- 他にインストールするものとしては、gdb linux-perf rr clang-format silversearcher-ag あたり。
- /usr/bin/setxkbmap -option "ctrl:nocaps"
思った以上にスムーズに動いてしまった。気をつけるとすれば、non-free ファームウェアを含む ISO を使うことぐらいだろうか。
追記:
後になって LEVEL-15 が、System76 の "Serval WS" と同一のハードウェアを使っていることに気づいた。試しに System76 が提供している Pop!_OS 21.04 をインストールしてみたところ、安定性が高まったのでいまはそちらを使っている。
Debian のときは rr が動作せず困っていた（zen_workaround.py がエラーを吐く、↓と同じエラーが出る）が、Pop!_OS にしたところまったく問題なく動作している。変更したのは OS とセキュアブートの設定だが、あまりにも変化が大きすぎて何がよかったのかわからない。
セットアップ上の注意点:
- Encrypted LVM を有効化すると、MariaDB のビルド時に著しい IO wait が出てしまい、ビルド時間が倍程度になる。セキュリティ上問題がなければオフにする。
- リリース版だと一部の system call が instrument されない場合があるため、rr はソースからビルドする。Zen · rr-debugger/rr の kernel module による workaround を適用する。
実例で学ぶ MySQL/MariaDB デバッグ
この記事では、MySQL/MariaDB のバグを修正するための典型的な手順を、具体例を通して解説する。次の MariaDB のバグを例として取り上げるが、基本的なデバッグの手順は MySQL でもまったく同様である。
なお、MySQL/MariaDB のデバッグ方法についての包括的な解説を与えるのは、この記事のスコープ外である。デバッグ手法の詳細を知りたい場合は、以下の一連の記事を参照してほしい。
- Debugging MySQL/MariaDB (1): Build and Test
- Debugging MySQL/MariaDB (2): DBUG and Trace
- Debugging MySQL/MariaDB (3): GDB Debugging
- Debugging MySQL/MariaDB (4): Debugging with rr
Step 1: バグの再現
チケットの説明をよく読み、バグの概要を把握する。どうやら次のようなクエリを実行すると、MariaDB Server が落ちてしまうというバグのようだ。
select * from t1 where (name, len) in (select name, len from information_schema.innodb_sys_columns having len = 8);
概要が把握できたらバグの再現を試みる。このチケットには幸いにもテストケースが添付されているので、それを適切なディレクトリに配置しテストを実行するだけでよい。通常は自分でテストケースを作らねばならない。
下準備として、MariaDB Server のソースを GitHub から取得し、デバッグビルドする。10.3-10.5 のブランチで起こるバグなので、10.3 での再現を試みる。
git clone -b 10.3 git@github.com:MariaDB/server.git mariadb-server # git checkout mariadb-10.3.28
※ 当該のバグは筆者がすでに修正しているため、最新の 10.3 のブランチでは再現しない。75f781f よりの前、例えば mariadb-10.3.28 ならば再現する。
mkdir mariadb-server/bld && cd $_ cmake -DCMAKE_BUILD_TYPE=Debug .. cmake --build . --config Debug -j 8
上手くビルドできたらテストを mysql-test/ 配下の適当なディレクトリに配置する。とりあえず mysql-test/suite/innodb/ 配下に配置してみる。テストケースは *.test と *.result で一組である。
cat mariadb-server/mysql-test/suite/innodb/t/MDEV-24868.test
--echo #
--echo # MDEV-24868 Server crashes in optimize_schema_tables_memory_usage after select from information_schema.innodb_sys_columns
--echo #
--source include/have_innodb.inc
create table t1 (name varchar(64) character set utf8, len int);
select * from t1 where (name, len) in (
select name, len from information_schema.innodb_sys_columns having len = 8
);
drop table t1;
cat mariadb-server/mysql-test/suite/innodb/r/MDEV-24868.result
# # MDEV-24868 Server crashes in optimize_schema_tables_memory_usage after select from information_schema.innodb_sys_columns # create table t1 (name varchar(64) character set utf8, len int); select * from t1 where (name, len) in ( select name, len from information_schema.innodb_sys_columns having len = 8 ); name len drop table t1;
mysql-test-run.pl でテストを実行すると、チケットの説明の通り失敗する。スタックトレースも同一に見える。
cd bld && ./mysql-test/mysql-test-run.pl innodb.MDEV-24868
...
#
# MDEV-24868 Server crashes in optimize_schema_tables_memory_usage after select from information_schema.innodb_sys_columns
#
create table t1 (name varchar(64) character set utf8, len int);
select * from t1 where (name, len) in (
select name, len from information_schema.innodb_sys_columns having len = 8
); innodb.MDEV-24868 'innodb' [ fail ] Test ended at 2021-05-18 11:57:34
CURRENT_TEST: innodb.MDEV-24868
mysqltest: At line 8: query 'select * from t1 where (name, len) in (
select name, len from information_schema.innodb_sys_columns having len = 8
)' failed: 2013: Lost connection to MySQL server during query
...
Program terminated with signal SIGSEGV, Segmentation fault.
#0 __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56 56 ../sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7fb5f40a4700 (LWP 318069))]
#0 __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1 0x000055e4f2498a57 in my_write_core (sig=11) at /home/vagrant/repo/mariadb-server/mysys/stacktrace.c:386
#2 0x000055e4f1c0887d in handle_fatal_signal (sig=11) at /home/vagrant/repo/mariadb-server/sql/signal_handler.cc:343
#3 <signal handler called>
#4 0x000055e4f199f3f2 in optimize_schema_tables_memory_usage (tables=...) at /home/vagrant/repo/mariadb-server/sql/sql_show.cc:8680
#5 0x000055e4f192a10f in JOIN::optimize_inner (this=0x7fb59c015a40) at /home/vagrant/repo/mariadb-server/sql/sql_select.cc:1628
#6 0x000055e4f1929af0 in JOIN::optimize (this=0x7fb59c015a40) at /home/vagrant/repo/mariadb-server/sql/sql_select.cc:1501
#7 0x000055e4f1933c42 in mysql_select (thd=0x7fb59c000d90, tables=0x7fb59c012d68, wild_num=1, fields=..., conds=0x7fb59c014ed8, og_num=0, order=0x0,
...
#17 0x00007fb5f997f609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#18 0x00007fb5f9559293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
...
Step 2: 原因の特定
バグを再現できたので、次はバグの原因を特定しよう。
git-bisect
いきなり GDB デバッグを行ってもよいかもしれないが、調べる範囲を限定するために、どのコミットでバグが混入したのか特定しよう。
まず、このバグが混入していないコミットを探す。例えば、mariadb-10.3.25 はどうだろう？
git checkout mariadb-10.3.25 cd bld && cmake --build . --config Debug -j 8
./mysql-test/mysql-test-run.pl innodb.MDEV-24868
... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 innodb.MDEV-24868 'innodb' [ pass ] 2 -------------------------------------------------------------------------- The servers were restarted 0 times Spent 0.002 of 6 seconds executing testcases Completed: All 1 tests were successful.
問題なく通った。よって、バグは mariadb-10.3.25 以降に混入したことがわかる。
上と同様にして mariadb-10.3.28 の時点でテストが失敗することを確認できる。つまり、バグは mariadb-10.3.28 以前に混入したのである。
ここまでわかれば、git-bisect を使うことで、簡単に問題のあるコミットを特定できる。 まず、git-bisect に食わせるシェルスクリプトを作成しよう。
cat git-bisect.sh
#!/bin/bash cd bld; rm CMakeCache.txt cmake .. && cmake --build . -j 8 && ./mysql-test/mysql-test-run.pl $1
次に、git-bisect を実行してみよう。これにはかなり時間がかかる。
git bisect start mariadb-10.3.28 mariadb-10.3.25
git bisect run ./git-bisect.sh innodb.MDEV-24868
...
4e503aec7feaeb2297035f565ca92c98d4557577 is the first bad commit
commit 4e503aec7feaeb2297035f565ca92c98d4557577
Author: Sergei Golubchik <serg@mariadb.org>
Date: Thu Jan 21 16:40:36 2021 +0100
MDEV-24593 Signal 11 when group by primary key of table joined to information_schema.columns
I_S tables were materialized too late, an attempt to use table
statistics before the table was created caused a crash.
Let's move table creation up. it only needs read_set to
be calculated properly, this happens in JOIN::optimize_inner(),
after semijoin transformation.
Note that tables are not populated at that point, so most of the
statistics would make no sense anyway. But at least field sizes
will be correct. And it won't crash.
mysql-test/main/information_schema.result | 9 +++
mysql-test/main/information_schema.test | 10 ++++
sql/sql_select.cc | 6 +-
sql/sql_show.cc | 98 ++++++++++++++++---------------
sql/sql_show.h | 1 +
storage/heap/ha_heap.cc | 3 -
storage/maria/ha_maria.cc | 3 -
7 files changed, 77 insertions(+), 53 deletions(-)
bisect run success
バグは 4e503aec7feaeb2297035f565ca92c98d4557577 で混入したとわかった。
上のコミットはほとんど optimize_schema_tables_memory_usage() のみを修正している。また、MariaDB server が死ぬのもこの関数の中であった。したがって、当該の関数のみに注目してデバッグすれば、この問題は解決できそうだとわかる。
GDB Debug
前節の内容を踏まえて、GDB を使ってデバッグしてみよう。mysql-test-run.pl に --manual-gdb オプションを与え、MariaDB server が落ちる直前にブレークポイントを打つ。
./mysql-test/mysql-test-run.pl innodb.MDEV-24868 --manual-gdb
...
(gdb) b sql/sql_show.cc:8680
Breakpoint 1 at 0x7b73ee: file /home/vagrant/repo/mariadb-server/sql/sql_show.cc, line 8680.
(gdb) run
...
Thread 28 "mysqld" hit Breakpoint 1, optimize_schema_tables_memory_usage (tables=...) at /home/vagrant/repo/mariadb-server/sql/sql_show.cc:8680
8680 THD *thd=table->in_use;
(gdb) p table_list->table_name->str
$1 = 0x7fff9c014f70 "t1"
(gdb) p table_list->table
$2 = (TABLE *) 0x7fff9c025910
(gdb) continue
Continuing.
Thread 28 "mysqld" hit Breakpoint 1, optimize_schema_tables_memory_usage (tables=...) at /home/vagrant/repo/mariadb-server/sql/sql_show.cc:8680
8680 THD *thd=table->in_use;
(gdb) p table_list->table_name->str
$3 = 0x0
(gdb) p table_list->table
$4 = (TABLE *) 0x0
(gdb) p table_list->alias
$5 = {str = 0x7fffa4019648 "<subquery2>", length = 11}
(gdb) continue
Continuing.
Thread 28 "mysqld" received signal SIGSEGV, Segmentation fault.
0x0000555555d0b3f2 in optimize_schema_tables_memory_usage (tables=...) at /home/vagrant/repo/mariadb-server/sql/sql_show.cc:8680
8680 THD *thd=table->in_use;
table が NULL なのに、table->in_use としてしまっているのが原因である。table_list は多くのアトリビュートが NULL のままになっているが、これはこの変数がサブクエリに対応するからのようだ。次のように修正すれば解決する。
bool optimize_schema_tables_memory_usage(List<TABLE_LIST> &tables)
{
List_iterator<TABLE_LIST> tli(tables);
while (TABLE_LIST *table_list= tli++)
{
+ if (!table_list->schema_table)
+ continue;
TABLE *table= table_list->table;
THD *thd=table->in_use;
- if (!table_list->schema_table || !thd->fill_information_schema_tables())
+ if (!thd->fill_information_schema_tables())
...
...
}
return 0;
}
参考として筆者が作成したプルリクエストを添付しておく（"Closed" の表示だが、マージはされている）。
Debugging MySQL/MariaDB (3): GDB Debugging
この記事は次の2つの記事の続編である。2つの記事を基礎とし、GDB を用いた MySQL/MariaDB のデバッグについて解説する。なお、(1) で述べた通り、MySQL 8.0.24 および MariaDB 10.5.9 を前提として説明する。
以下では、(1) の記事の方法で MySQL/MariaDB がデバッグビルドしている前提で解説を行う。
Debugging with GDB
筆者が MySQL/MariaDB を GDB でデバッグするときのやり方を具体例を通して説明する。ただし、説明には MySQL 8.0.24 を使うものとする。
例えば、(1) の記事で作成した example.test の実行をデバッグしたいとしよう。
# mysql-test/suite/innodb/t/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;
「よい」ブレークポイントが打てるケース
ブレークポイントをどこに打てばよいかわかっており、そのブレークポイントが頻繁にヒットしないものならば、mysql-test-run.pl に --manual-gdb オプションを与えて実行するのがよい。
cd bld/mysql-test/ ./mysql-test-run.pl innodb.example --manual-gdb
すると、次のような文言が出力される。
To start gdb for mysqld.1, type in another window: gdb -cd /home/vagrant/repo/mysql-8.0.24/mysql-test -x /home/vagrant/repo/mysql-8.0.24/bld/mysql-test/var/tmp/gdbinit.mysqld.1 /home/vagrant/repo/mysql-8.0.24/bld/runtime_output_directory/mysqld
このコマンドを別のウィンドウで実行すると、MySQL 8.0.24 では main() 関数で停止した状態になる。適当にブレークポイントを設定し continue するとテストケースが実行される。
※ MariaDB 10.5.9 では、プログラムの実行開始前 (run されていない状態) で停止するようだ。
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
...
Reading symbols from /home/vagrant/repo/mysql-8.0.24/bld/runtime_output_directory/mysqld...
Breakpoint 1 at 0x32c4ea9: file /home/vagrant/repo/mysql-8.0.24/sql/main.cc, line 25.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Breakpoint 1, main (argc=0, argv=0x7fffffffe8e0) at /home/vagrant/repo/mysql-8.0.24/sql/main.cc:25
25 int main(int argc, char **argv) { return mysqld_main(argc, argv); }
(gdb)
「よい」ブレークポイントを打てないケース
どこにブレークポイントを打てばいいかわからない場合や、わかっているがブレークポイントが頻繁にヒットしすぎる部類のものの場合、--manual-gdb は使いづらい。何故なら、MySQL の初期化プロセスや興味のないクエリも GDB デバッグの対象となってしまうからである。
このようなケースでは、筆者ならば mysql-test-run.pl に --start-and-exits オプションを渡して起動し、手でクエリを投入しながら、デバッグしたい箇所に到達したら GDB をアタッチする。実際にやってみよう。
まず、MySQL server を innodb.example の設定で起動する。
> cd bld/mysql-test/
> ./mysql-test-run.pl innodb.example --start-and-exit
...
==============================================================================
TEST NAME RESULT TIME (ms) COMMENT
------------------------------------------------------------------------------
worker[1] - 'localhost:13000' was not free
worker[1] - 'localhost:13020' was not free
worker[1] - 'localhost:13020' was not free
worker[1]
Started [mysqld.1 - pid: 2222438, winpid: 2222438]
worker[1] Using config include/default_my.cnf
worker[1] Port and socket path for server(s):
worker[1] mysqld.1 13030 /home/vagrant/repo/mysql-8.0.24/bld/mysql-test/var/tmp/mysqld.1.sock
worker[1] Server(s) started, not waiting for them to finish
ビルドした MySQL client で MySQL server に接続し、SELECT の直前までクエリを投入する。
../bin/mysql -u root -S /home/vagrant/repo/mysql-8.0.24/bld/mysql-test/var/tmp/mysqld.1.sock
mysql> USE test; Database changed mysql> CREATE TABLE t1 (a INT); Query OK, 0 rows affected (0.04 sec) mysql> INSERT INTO t1 VALUES (1); Query OK, 1 row affected (0.01 sec)
別ウィンドウで GDB を MySQL にアタッチする。PID は mysql-test-run.pl の出力にあるものを使えばよい。
sudo gdb -p 2222438
これでいい感じに GDB デバッグできる状態になったはずだ。 ブレークポイントを置くべき場所はわかっているがヒットしすぎるというケースはこれで解決だ。
一方、問題の箇所が特定できていないケースでは、GDB をお伴にコードの中を嗅ぎ回ることになる。そのような作業をしなくてはならない場合、代表的な関数を知っているとそこにブレークポイントを置けて便利である。
何が代表的な関数なのかわからなければ、書籍 "Expert MySQL" を読むとよい（古い本なので最新のコードとは乖離があることに注意）。例えば、InnoDB のテーブルスキャンであれば、mysql_execute_command(), ha_innobase::rnd_init(), ha_innobase::rnd_next() 等に打つのがよいのではないだろうか。
雰囲気を味わうために ha_innobase::rnd_next() ブレークポイントを置きバックトレースを見てみよう。
(gdb) b ha_innobase::rnd_next Breakpoint 2 at 0x56204df892b8: file /home/vagrant/repo/mysql-8.0.24/storage/innobase/handler/ha_innodb.cc, line 10469. (gdb) c Continuing. ...
MySQL client のウィンドウに戻り、SELECT を実行する。
mysql> SELECT * FROM t1;
すると GDB のウィンドウがブレークポイントで止まっているはずなので、バックトレースを出力させる。
...
Thread 38 "mysqld" hit Breakpoint 2, ha_innobase::rnd_next (this=0x7f978cabf3a8, buf=0x7f978c1b01c0 "\001\001\001\001")
at /home/vagrant/repo/mysql-8.0.24/storage/innobase/handler/ha_innodb.cc:10469
10469 {
(gdb) bt
#0 ha_innobase::rnd_next (this=0x7f978cabf3a8, buf=0x7f978c1b01c0 "\001\001\001\001") at /home/vagrant/repo/mysql-8.0.24/storage/innobase/handler/ha_innodb.cc:10469
#1 0x000056204ca37a62 in handler::ha_rnd_next (this=0x7f978cabddf8, buf=0x7f978cb48698 "\377") at /home/vagrant/repo/mysql-8.0.24/sql/handler.cc:2985
#2 0x000056204c50a251 in TableScanIterator::Read (this=0x7f978cac2f40) at /home/vagrant/repo/mysql-8.0.24/sql/records.cc:361
#3 0x000056204c7b5a51 in Query_expression::ExecuteIteratorQuery (this=0x7f978cb46698, thd=0x7f978c000f00) at /home/vagrant/repo/mysql-8.0.24/sql/sql_union.cc:1230
#4 0x000056204c7b5dda in Query_expression::execute (this=0x7f978cb46698, thd=0x7f978c000f00) at /home/vagrant/repo/mysql-8.0.24/sql/sql_union.cc:1283
#5 0x000056204c6fe340 in Sql_cmd_dml::execute_inner (this=0x7f978cac21d8, thd=0x7f978c000f00) at /home/vagrant/repo/mysql-8.0.24/sql/sql_select.cc:791
#6 0x000056204c6fd7fe in Sql_cmd_dml::execute (this=0x7f978cac21d8, thd=0x7f978c000f00) at /home/vagrant/repo/mysql-8.0.24/sql/sql_select.cc:575
#7 0x000056204c679446 in mysql_execute_command (thd=0x7f978c000f00, first_level=true) at /home/vagrant/repo/mysql-8.0.24/sql/sql_parse.cc:4412
#8 0x000056204c67b467 in dispatch_sql_command (thd=0x7f978c000f00, parser_state=0x7f98342f8b90) at /home/vagrant/repo/mysql-8.0.24/sql/sql_parse.cc:5000
#9 0x000056204c671588 in dispatch_command (thd=0x7f978c000f00, com_data=0x7f98342f9b80, command=COM_QUERY) at /home/vagrant/repo/mysql-8.0.24/sql/sql_parse.cc:1841
#10 0x000056204c66fa2b in do_command (thd=0x7f978c000f00) at /home/vagrant/repo/mysql-8.0.24/sql/sql_parse.cc:1320
#11 0x000056204c86c6b7 in handle_connection (arg=0x562055755770) at /home/vagrant/repo/mysql-8.0.24/sql/conn_handler/connection_handler_per_thread.cc:301
#12 0x000056204e720230 in pfs_spawn_thread (arg=0x562055913a60) at /home/vagrant/repo/mysql-8.0.24/storage/perfschema/pfs.cc:2898
#13 0x00007f9845984609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x00007f98450c2293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
MySQL 5.7 からずいぶんリファクタリングが進んだなと思わせるバックトレースである。
"Debugging MySQL/MariaDB" をタイトルに冠した記事は、この記事 (3) で一旦終わりとする。将来、新たに書きたいテーマが生まれたら、(4) を書くかもしれない。
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
Debugging MySQL/MariaDB (1): Build and Test
MySQL/MariaDB をデバッグする実践的方法を解説する。この記事ではデバッグを行うための準備を行い、具体的なデバッグの方法については (2) 以降の記事で説明する予定である。なお、一連の記事すべてにおいて MySQL 8.0.24 および MariaDB 10.5.9 を前提として解説する。
Building MySQL/MariaDB
MySQL/MariaDB のそれぞれについて、ビルドする方法を簡単にまとめておく。以下の記述は筆者の開発環境 (Vagrant Box bento/ubuntu-20.04) を前提としたものである。
MySQL
Boost 同梱版のソースを公式からダウンロードし展開する。GitHub から取得すると Boost のバージョンを合わせるのがかなり面倒なので、Boost 同梱版を使うのが吉である。
wget https://dev.mysql.com/get/Downloads/MySQL-8.0/mysql-boost-8.0.24.tar.gz tar xfv mysql-boost-8.0.24.tar.gz
次に必要なパッケージをインストールし、デバッグビルドする。
apt-get install g++ cmake pkg-config # ビルドに必要 apt-get install libjson-perl zip unzip # テストに必要
mkdir -p mysql-8.0.24/bld && cd $_ cmake -DWITH_BOOST=../boost .. -DCMAKE_BUILD_TYPE=Debug cmake --build . --config Debug -j 4
MariaDB
Building MariaDB on Ubuntu に従って依存パッケージをインストールする。
apt-get install software-properties-common devscripts equivs
apt-key adv --recv-keys --keyserver hkp://keyserver.ubuntu.com:80 0xF1656F24C74CD1D8
add-apt-repository --update --yes --enable-source \
'deb [arch=amd64] http://nyc2.mirrors.digitalocean.com/mariadb/repo/10.5/ubuntu '$(lsb_release -sc)' main'
apt-get build-dep mariadb-10.5
git clone -b mariadb-10.5.9 --depth=1 git@github.com:MariaDB/server.git mariadb-server
mkdir mariadb-server/bld && cd $_ cmake -DCMAKE_BUILD_TYPE=Debug .. cmake --build . --config Debug -j 4
デバッグビルドしようとすると、コンパイル時に1つでも警告が出るとコンパイルエラーになる (-Werror)。HEAD で開発する場合はこの動作で問題ないが、例えば git-bisect のために古いバージョンをビルドする場合に邪魔になることがある。-DMYSQL_MAINTAINER_MODE=OFF することで警告を警告のままにできる。
cmake -DCMAKE_BUILD_TYPE=Debug -DMYSQL_MAINTAINER_MODE=OFF ..
Testing MySQL/MariaDB
同じ SQL を何度も手で投入するのは苦痛であり効率も悪いので、デバッグを始める前にテストケースを作成しよう。MySQL Test Framework、特に mysql-test-run.pl を使えば、SQL を書く感覚で E2E テストを書くことができる。なお、筆者が知る限りにおいて、MySQL におけるテストは E2E テストが主体であり、ユニットテストを書くことはあまりないようだ。
Running Test Cases
まずは MySQL のテストについて簡単に説明しよう。以下、MySQL を例に取って説明するが、MariaDB の場合もほとんど同様である。
各々のテストケースは、suite という単位でまとめられている。mysql-test/suite/ のディレクトリ1つ1つが suite に一対一対応し、その中に個々のテストケースが配置されている。
> ls -A mysql-test/suite audit_null innodb_fts network_namespace auth_sec innodb_gis opt_trace binlog innodb_stress parts binlog_gtid innodb_undo perfschema binlog_nogtid innodb_zip query_rewrite_plugins clone interactive_utilities rpl collations jp rpl_gtid component_keyring_file json rpl_ndb connection_control json_ndb rpl_nogtid encryption large_tests secondary_engine engines lock_order service_status_var_registration federated max_parts service_sys_var_registration funcs_1 memcached service_udf_registration funcs_2 ndb special gcol ndb_big stress gcol_ndb ndb_binlog sys_vars gis ndb_ddl sysschema group_replication ndb_opt test_service_sql_api information_schema ndb_rpl test_services innodb ndbcluster x
※ MariaDB の場合もほぼ同様だが、main suite のみ mysql-test/ の直下に配置されている。main suite は特別扱いされているようで、他の suite とはやや扱いが異なるので注意すること。
MySQL Test Framework のテストは、様々な単位での実行が可能である。以下に例を示す。
cd bld/mysql-test/ ./mysql-test-run.pl # すべてのテストを実⾏ ./mysql-test-run.pl --suite innodb # innodb suite のテストをすべて実⾏ ./mysql-test-run.pl innodb.create_table # innodb suite の create_table を実⾏
複数のテストを同時に実行する場合は、--parallel と --force という2つのオプションを与えるのがオススメだ。--parallel は読んで字の如く並列数を指定するもので、--force はいくつかのテストケースが失敗しても最後までテストを実行するよう指示するものである。
./mysql-test-run.pl --parallel=8 --force
Writing Test Cases
新規にテストケースを作る方法を説明する。なお、同様にして既存のテストケースにテストを追加することもできるが、デバッグのしやすさを考えると新規に作成する方がよいだろう。
まず、適切な suite を選び、テストファイルと結果ファイルを作成する。例示のためなのでどこでもよいのだが、仮に innodb suite を使うこととしよう。
touch mysql-test/suite/innodb/t/example.test touch mysql-test/suite/innodb/r/example.result
テストファイルにはSQL と テストコマンド が書ける。結果ファイルにはテストファイルに書いた SQL とその望ましい返り値を書けばよい。以下に簡単な例を挙げる。
# mysql-test/suite/innodb/t/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;
# mysql-test/suite/innodb/r/example.result CREATE TABLE t1 (a INT); INSERT INTO t1 VALUES (1); SELECT * FROM t1; a 1 DROP TABLE t1; DROP TABLE t; ERROR 42S02: Unknown table 'test.t'
結果ファイルを手で書くのが面倒な場合は、結果ファイルは空のままテストを実行する。すると実⾏結果が結果ファイルと同じディレクトリに example.reject という名前で生成されるので、それをベースにして結果ファイルを作ることができる。
テスト開始時にサーバーにオプションを渡したい場合や、特定の my.cnf を使わせたい場合は、*.opt および *.cnf ファイルを用いる。どのテストにどの設定ファイルが適用されるかの判定ルールはやや複雑なので、その説明はドキュメント に譲ることとする。
Running Server without Installation
mysql-test-run.pl の使い道はテストの実行だけではない。--start オプションを与えることで、make install せずとも、ビルド済みバイナリから MySQL/MariaDB サーバーを起動できる。これは、テストケースを作るために試行錯誤する段階で役に立つ。
例えば以下のようにすると、innodb suite の create_table.test の起動設定 (*.opt, *.cnf) で、サーバーを起動することができる。
./mysql-test-run.pl innodb.create_table --start
ソケットのパスが表示されるので、それを使って起動したサーバーに接続する。
mysql -u root -S ${SOCKET}
