実例で学ぶ 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" の表示だが、マージはされている）。
