2017年3月21日火曜日

sql_select_limitを設定したらXtraBackupがsignal 11で転けた

TL;DR

SET GLOBAL sql_select_limit = ? で結果セットのサイズを制限していると、xtrabackupが内部的に発行している SHOW ステートメントの出力結果が切り詰められてクラッシュすることがある。

xtrabackupで遊んでいたら、ある時からおもむろにsignal 11で落ちるようになった。それ以前はフツーにバックアップ取れてたのに。
$ innobackupex -S /usr/mysql/5.7.17/data/mysql.sock -uroot .
170321 10:43:26 innobackupex: Starting the backup operation

IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".

Unrecognized character \x01; marked by <-- HERE after <-- HERE near column 1 at - line 1374.
170321 10:43:26 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: /usr/mysql/5.7.17/data/mysql.sock
01:43:26 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
innobackupex(my_print_stacktrace+0x2c)[0xc2078c]
innobackupex(handle_fatal_signal+0x262)[0xa36bf2]
/lib64/libpthread.so.0(+0xf370)[0x7f3150796370]
/lib64/libc.so.6(+0x1354ab)[0x7f314e5954ab]
innobackupex(_Z14get_mysql_varsP8st_mysql+0x44b)[0x734e5b]
innobackupex(_Z7xb_initv+0x12b)[0x71f77b]
innobackupex(main+0x37b)[0x6ff14b]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f314e481b35]
innobackupex[0x7175d4]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup
最初は Unrecognized character \x01; marked by <-- HERE after <-- HERE near column 1 at - line 1374. が怪しいのかと思って色々調べてみてたけれど、なんか正常終了するケースでも出力されているぽい(2.4.5では出なかった && 2.4.6では常に出る)
ステップ実行してみたら、ここを通り抜けた後にsignal 11なのでこれが直接の原因ではなさげ。
次の容疑者(?)は get_mysql_vars なのでここにブレークポイントを打ってステップ実行。
$ gdb --args innobackupex -S /usr/mysql/5.7.17/data/mysql.sock -uroot .
(gdb) b get_mysql_vars
(gdb) r
Breakpoint 1, get_mysql_vars (connection=0x1b1e630)
    at /usr/src/debug/percona-xtrabackup-2.4.6/storage/innobase/xtrabackup/src/backup_mysql.cc:369
(gdb) n
..
461             if (!(ret = check_server_version(server_version, version_var,
(gdb)
+n

Program received signal SIGSEGV, Segmentation fault.
__strstr_sse42 (s1=0x0, s2=0x111b524 "Percona") at ../sysdeps/x86_64/multiarch/strstr.c:174
174       if (__builtin_expect (p1[0] == '\0', 0))
(gdb)
+n
handle_fatal_signal (sig=11) at /usr/src/debug/percona-xtrabackup-2.4.6/sql/signal_handler.cc:57
57      {
ここ で落ちた。
もう一度そこにブレークポイントを入れて渡してる変数を見てみる。
Breakpoint 2, get_mysql_vars (connection=0x1b1e630)
    at /usr/src/debug/percona-xtrabackup-2.4.6/storage/innobase/xtrabackup/src/backup_mysql.cc:461
461             if (!(ret = check_server_version(server_version, version_var,
(gdb) p server_version
+p server_version
$1 = 50717
(gdb) p version_var
+p version_var
$2 = 0x0
(gdb) p version_comment_var
+p version_comment_var
$3 = 0x0
(gdb) p innodb_version_var
+p innodb_version_var
$4 = 0x0
あれー。いくつかNULLになってる。これがSEGVの原因か。
ここで使っている変数を読み取っているのは このへん で、 やってること はどうも SHOW VARIABLES の出力結果を素直に配列に詰めてるだけに見えるんだけどな。。
mysql57> SHOW VARIABLES;
+-----------------------------------------+-----------------------------------+
| Variable_name                           | Value                             |
+-----------------------------------------+-----------------------------------+
..
| innodb_adaptive_flushing                | ON                                |
| innodb_adaptive_flushing_lwm            | 10                                |
+-----------------------------------------+-----------------------------------+
100 rows in set (0.00 sec)
(つд⊂)ゴシゴシ
あれ? 明らかにInnoDB関連のパラメーター足りなくね? 100 rowsしかない?
mysql57> SHOW VARIABLES LIKE 'innodb%version%';
+----------------+--------+
| Variable_name  | Value  |
+----------------+--------+
| innodb_version | 5.7.17 |
+----------------+--------+
1 row in set (0.00 sec)
これは引ける…。。あ。
これ を見てた時に SET GLOBAL sql_select_limit= 100 したからいけないのか…。orz
本番で起きるとは思えないけど、こんなことがあったメモ。

2017年3月11日土曜日

OSC 2017 Tokyo/Spring でMySQL 8.0を雑に予測してきた

ネタ的には YAPC::Hokkaido 2016 Sapporo の時のリライト(8.0.1のリリースノートの情報を追加した感じ)で、相変わらずいくつかの側面に分けてMySQL 8.0に期待していることやこうなるんじゃないかな感を発表しました。

MySQL 8.0.1のリリースノート が結構量が増えていて、時間も前回の20分に対して45分と倍増していたんですが、時間ギリギリまで結構色々しゃべりました。





MySQL 8.0は相当ゴツいな、というイメージなんですが、MySQL 5.7の時も同じようなこと言ってたし、きっと出てきたら出てきたで楽しく 地雷を踏み抜く 新機能で遊ぶんだろうな、とこのスライドのためにリリースノートを読みながらほんのり思いました。

さあ、みんないっしょにMySQL 8.0で遊びましょう :)
Have Fun!!