LEVEL-15FX069-R9-RXZX に Debian 11 をインストールする

この1年間 VirtualBoxMariaDB を開発してきたが、色々と不便な点 (Mozilla rr が使えない等) があり、Linux をネイティブインストールしたビルドマシンを構築した。その過程を記録しておく。

OS は Debian 11 を使う。サーバーは iiyama の LEVEL-15FX069-R9-RXZX 。ノート PC にデスクトップ用の Ryzen 9 を搭載した変態マシンである。

www.pc-koubou.jp

以下、やったことのメモ:

  • ここ から Live インストールイメージをダウンロードし、Rufus を使って USB メモリに焼く。今回は debian-live-11.0.0-amd64-gnome+nonfree.iso を使った。
    • non-free ファームウェアを含むイメージでないと、Wi-Fi が (out-of-the-box には) 動作しないので注意。
  • 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 あたり。

思った以上にスムーズに動いてしまった。気をつけるとすれば、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 を適用する。

github.com

実例で学ぶ MySQL/MariaDB デバッグ

この記事では、MySQL/MariaDB のバグを修正するための典型的な手順を、具体例を通して解説する。次の MariaDB のバグを例として取り上げるが、基本的なデバッグの手順は MySQL でもまったく同様である。

MDEV-24868: Server crashes in optimize_schema_tables_memory_usage after select from information_schema.innodb_sys_columns

なお、MySQL/MariaDBデバッグ方法についての包括的な解説を与えるのは、この記事のスコープ外である。デバッグ手法の詳細を知りたい場合は、以下の一連の記事を参照してほしい。

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" の表示だが、マージはされている)。

github.com

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/MariaDBGDBデバッグするときのやり方を具体例を通して説明する。ただし、説明には 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)

別ウィンドウで GDBMySQL にアタッチする。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 に関して、いくつか注意点を挙げておく:

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

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

GitHub からソースを取得し、デバッグビルドする。

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

デバッグビルドしようとすると、コンパイル時に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}

TokuDB に関するテストが mariadb-10.4.18 で FAIL する件

Vagrant Box bento/ubuntu-20.04 で Building MariaDB on Ubuntu に従い MariaDB をビルドした(※)ところ、TokuDB に関連するテストが FAIL した。なお MariaDB のバージョンは mariadb-10.4.18 である。ここに解決方法を記しておく。

※ ただし、記事中の 10.3 をすべて 10.4 に置き換えて手順を実行した。


テストの実行結果から重要そうな部分のみ抜粋する。... は省略を表す。

> ./mysql-test/mtr --suite=tokudb --force

...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
tokudb.bf_create_select                  [ skipped ]  Test needs --big-test
tokudb.bf_create_select_hash_part        [ skipped ]  Test needs --big-test

...

tokudb.type_temporal_upgrade             [ disabled ]
tokudb.type_timestamp_explicit           [ disabled ]
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 393963, winpid: 393963, exit: 512] died after mysql-test-run waited 0.2 seconds for /home/vagrant/repo/mariadb-server/build/mysql-test/var/run/mysqld.1.pid to be created.
tokudb.type_varchar                      [ fail ]
        Test ended at 2021-04-13 12:46:49

CURRENT_TEST: tokudb.type_varchar


Failed to start mysqld.1
mysqltest failed but provided no output


 - saving '/home/vagrant/repo/mariadb-server/build/mysql-test/var/log/tokudb.type_varchar/' to '/home/vagrant/repo/mariadb-server/build/mysql-test/var/log/tokudb.type_varchar/'
***Warnings generated in error logs during shutdown after running tests: tokudb.type_varchar

2021-04-13 12:46:48 0 [ERROR] Couldn't load plugins from 'ha_tokudb.so'.
2021-04-13 12:46:48 0 [ERROR] /home/vagrant/repo/mariadb-server/build/sql/mysqld: unknown option '--tokudb'
2021-04-13 12:46:48 0 [ERROR] Aborting

...

Errors/warnings were found in logfiles during server shutdown after running the
following sequence(s) of tests:
    tokudb.type_varchar
    tokudb.ext_key_1_innodb
    tokudb.ext_key_2_innodb
    tokudb.simple_join_tokudb_innodb
    tokudb.truncate_txn_rollback_innodb
    tokudb.type_bit_innodb
    tokudb.bug-1657908
    tokudb.gap_lock_error
    tokudb.dir-per-db-with-custom-data-dir
19 tests were skipped, 0 by the test itself.

mysql-test-run: *** ERROR: there were failing test cases

Couldn't load plugins from 'ha_tokudb.so'. と言われているので、ha_tokudb.so を探してみる。どうやらビルド自体はされていそうだ。

> pwd
/home/vagrant/repo/mariadb-server/build

> ag -g ha_tokudb
storage/tokudb/CMakeFiles/tokudb.dir/ha_tokudb.cc.o
storage/tokudb/ha_tokudb.so

よくわからないので、それっぽい issue がないか MariaDB の JIRA を漁ってみる。MDEV-16183 TokuDB tests fail on Fedora 28 がそれっぽい。

LD_PRELOAD を設定しろと書いてあるので、やってみると…通った!何故これで上手く行くのかは、上の issue に書かれているのでそちらを読んでほしい。

> LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.2 ./mysql-test/mtr --suite=tokudb

...

==============================================================================

TEST                                  WORKER RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
tokudb.bf_create_select                  [ skipped ]  Test needs --big-test
tokudb.bf_create_select_hash_part        [ skipped ]  Test needs --big-test

...

tokudb.hotindex-del-fast                 w3 [ pass ]  61017
tokudb.hotindex-update-0                 w5 [ pass ]  57358
--------------------------------------------------------------------------
The servers were restarted 9 times
Spent 714.488 of 119 seconds executing testcases

Completed: All 214 tests were successful.

27 tests were skipped, 7 by the test itself.

追記: MariaDB10.4 branch の HEAD (c03841ec0e2b7ac11711243d29821038b26e3edf) において、suite やテストを指定せずに mysql-test-run.pl を実行すると、途中で mysqld が死んでエラーになるという問題があったのだが、それも TokuDB が原因のようである。次のいずれかの方法で回避できる。

> LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.2 ./mysql-test/mtr
> ./mysql-test/mtr --skip-test=tokudb    # TokuDB 関連のテストをスキップ

Building MySQL 8.0.23 on Ubuntu 20.04

Vagrant Box bento/ubuntu-20.04MySQL 8.0.23 をビルドした記録。

> cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.1 LTS"

何はともあれソースコードを入手する。最初は GitHub から取ろうとしたのだが、MySQL の boost のバージョン指定が厳しく、面倒だったので boost 同梱版のソースを公式からダウンロードした。

wget https://dev.mysql.com/get/Downloads/MySQL-8.0/mysql-boost-8.0.23.tar.gz
tar xfv mysql-boost-8.0.23.tar.gz
cd mysql-8.0.23/

MySQL Internals Manual の 4.3 Quick How-to-Build Instructions に従って進めていく。yoku さんの ConoHaの上でひたすらMySQLをビルドする簡単なおしごと in 2019年 も参考にした。

何はともあれ cmake がないと始まらないので、それだけ入れてビルドしてみる。

sudo apt-get install cmake
mkdir bld && cd $_
cmake -DWITH_BOOST=../boost ..
# cmake -DWITH_BOOST=../boost .. -DCMAKE_BUILD_TYPE=Debug

「XX がない」と言われるので、XX をインストールして再度 cmake -DWITH_BOOST=../boost ..。cmake が通るまでこれを繰り返す。煩雑になるので過程は省略するが、最終的に↓を実行すれば通るようになる。

sudo apt-get install g++ pkg-config

cmake が通ったことを確認してビルドを実行。MySQL のビルドは時間がかかる。

make -j4

問題なくビルドできたはずだ。以下では、試行錯誤の最中に発見した些細なバグについて解説する。ビルドの方法だけ知りたい場合は読む必要はない。


正しくビルドできていることを確認する意味で、テストを実行してみる。

 ./mysql-test/mtr --parallel=4

最初はいい感じに動くのだが、テストが依存しているライブラリやコマンドが足りず、一部のテストが落ちる。それらをインストールしてから再実行。

 sudo apt-get install libjson-perl unzip zip
 ./mysql-test/mtr --parallel=4

しかし、main.cast がまだ通らない。次の diff で落ちているようだ。なお、テストの完全な出力は記事末尾に載せた。

 SELECT CAST(TIME'08:09:10' AS YEAR);
 CAST(TIME'08:09:10' AS YEAR)
-2020
+2021
 SELECT CAST(TIME'00:00:00' AS YEAR);
 CAST(TIME'00:00:00' AS YEAR)
-2020
+2021

公式ドキュメント によれば、

For a TIME value, return the current year.

とのことなので、SELECT CAST(TIME'08:09:10' AS YEAR); が2021年現在において、2021 を返すのは正しい振る舞いと考えられる。よって、これはテストがおかしい。一応、それらしきバグレポも上がっている。

MySQL(のテスト)のバグで、すべてのテストを完走させることはできなかったが、ビルド自体は正しくできていると思ってよさそうだ。


vagrant@vagrant:~/mysql-8.0.23/bld
> ./mysql-test/mtr main.cast --retry=0
Logging: /home/vagrant/mysql-8.0.23/mysql-test/mysql-test-run.pl  main.cast --retry=0
MySQL Version 8.0.23
Checking supported features
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/home/vagrant/mysql-8.0.23/bld/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[ 50%] main.cast                                 [ fail ]
        Test ended at 2021-01-23 01:40:47

CURRENT_TEST: main.cast
--- /home/vagrant/mysql-8.0.23/mysql-test/r/cast.result 2020-12-11 10:42:20.000000000 +0300
+++ /home/vagrant/mysql-8.0.23/bld/mysql-test/var/log/cast.reject       2021-01-23 04:40:47.304244731 +0300
@@ -1760,10 +1760,10 @@
 2010
 SELECT CAST(TIME'08:09:10' AS YEAR);
 CAST(TIME'08:09:10' AS YEAR)
-2020
+2021
 SELECT CAST(TIME'00:00:00' AS YEAR);
 CAST(TIME'00:00:00' AS YEAR)
-2020
+2021
 SELECT CAST(ST_PointFromText('POINT(10 10)') AS YEAR);
 ERROR HY000: Incorrect arguments to cast_as_year
 CREATE TABLE t AS SELECT CAST("2010" AS YEAR);

mysqltest: Result content mismatch


The result from queries just before the failure was:
TIMESTAMPADD(MINUTE, 1, CAST(1988 AS YEAR))
NULL
Warnings:
Warning 1292    Incorrect datetime value: '1988'
SELECT CAST(CAST(1988 AS YEAR) AS SIGNED);
CAST(CAST(1988 AS YEAR) AS SIGNED)
1988
SELECT CAST(CAST(1988 AS YEAR) AS UNSIGNED);
CAST(CAST(1988 AS YEAR) AS UNSIGNED)
1988
SELECT CAST(TIMESTAMP'579-10-10 10:10:10' AS YEAR);
CAST(TIMESTAMP'579-10-10 10:10:10' AS YEAR)
NULL
Warnings:
Warning 1292    Truncated incorrect YEAR value: '579'
SELECT CAST(STR_TO_DATE('nope','%d-%m-%Y') AS YEAR);
CAST(STR_TO_DATE('nope','%d-%m-%Y') AS YEAR)
NULL
Warnings:
Warning 1411    Incorrect datetime value: 'nope' for function str_to_date
safe_process[1263073]: Child process: 1263074, exit: 1

 - the logfile can be found in '/home/vagrant/mysql-8.0.23/bld/mysql-test/var/log/main.cast/cast.log'

[100%] shutdown_report                           [ pass ]
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 0.000 of 5 seconds executing testcases

Completed: Failed 1/2 tests, 50.00% were successful.

Failing test(s): main.cast

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases