Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.2, 10.3.0, 10.4.0
Description
While testing the fix of MDEV-12699, it became clear that crash recovery of ROW_FORMAT=COMPRESSED tables is broken. If I remember correctly, an assertion would fail while applying the MLOG_COMP_REC_INSERT record.
To repeat this more easily, we should probably try to reduce the page flushing rate, or simply remove the workarounds for this bug in the MDEV-12669 fix.
mleich, please try to find a small case for this, either with or without mariabackup. For 10.2, please use innodb_log_optimize_ddl=OFF if the test involves any CREATE INDEX or table-rebuilding ALTER TABLE.
Attachments
Issue Links
- blocks
-
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
It seems plausible that the problem affects all InnoDB tables. The MDEV-12699 fix would increase the probability of hitting this bug. Normally, we would often read a new version of the page from the data file and skip the redo log application. With MDEV-12699, we would more often reconstruct the page from redo log records.
For ROW_FORMAT=REDUNDANT, there was a different assertion failure, maybe involving rec_get_n_fields_old().
The assert during mariabackup ... --prepare does
|
- not require ROW_FORMAT = COMPRESSED
|
- disappears when setting innodb_log_optimize_ddl=OFF
|
|
|
Simplified RQG grammar
|
---------------------------------------
|
query:
|
ALTER TABLE t2 ADD INDEX IF NOT EXISTS `idx3` ( col1 , col_int ) , LOCK = SHARED |
|
DELETE FROM t2 WHERE col_int = 3 ; INSERT INTO t2 (col1, col_int) VALUES (3,3) ; COMMIT |
|
DELETE FROM t2 WHERE col_int = 3 ; INSERT INTO t2 (col1, col_int) VALUES (3,3) ; COMMIT ;
|
|
|
query_init:
|
CREATE TABLE t2 ( col1 INT, col_int INTEGER ) ENGINE = InnoDB ROW_FORMAT = Compact ; SET AUTOCOMMIT = 0 ;
|
|
The problem appears to affect all InnoDB tables after ALTER TABLE has created indexes or rebuilt the table while innodb_log_optimize_ddl=ON (the default setting) is in effect.
Here is a test case that repeats the problem for me. I do not think that it is fully deterministic.
--source include/have_innodb.inc
|
let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
|
|
|
CREATE TABLE t1(a SERIAL, b INT) ENGINE=InnoDB; |
|
|
delimiter |;
|
CREATE PROCEDURE populate() |
WHILE 1 DO
|
START TRANSACTION; |
DELETE FROM t1; |
INSERT INTO t1 SET b=3; |
COMMIT; |
END WHILE| |
delimiter ;|
|
|
|
--connect (con2, localhost, root)
|
--send
|
CALL populate;
|
|
|
--connection default
|
ALTER TABLE t1 ADD INDEX (b), LOCK=SHARED; |
--echo # remove --echo prefix below to ruin the test
|
--echo SET GLOBAL innodb_log_checkpoint_now=ON;
|
|
|
mkdir $targetdir;
|
--exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir
|
|
|
--disconnect con2
|
DROP PROCEDURE populate; |
DROP TABLE t1; |
|
|
--echo # page_rec_check() fails in page_cur_parse_insert_rec()
|
--exec $XTRABACKUP --prepare --target-dir=$targetdir
|
rmdir $targetdir;
|
Note: If an InnoDB log checkpoint occurs before the backup (or server crash), then it will recover fine.
Recovery will fail if the MDEV-12699 fix is present.
The cause seems to be the LOCK=SHARED clause, which is preventing the function row_merge_write_redo() from being called.
That is, we would fail to write a MLOG_INDEX_LOAD record if the ALTER TABLE operation cannot be performed online, but it requires a lock, either because the user specified a LOCK clause, or the operation is not technically possible to perform online (say, adding an AUTO_INCREMENT column).
# 2019-04-12T11:49:54 [56387] Executing first prepare: bld_debug/extra/mariabackup/mariabackup --host=127.0.0.1 --user=root --password='' --innodb-use-native-aio=0 --port=19644 --prepare --target-dir=/dev/shm/vardir/1555062567/18/1_clone/data# 2019-04-12T11:49:55 [56387] | bld_debug/extra/mariabackup/mariabackup based on MariaDB server 10.2.24-MariaDB Linux (x86_64)# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 cd to /dev/shm/vardir/1555062567/18/1_clone/data/# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 Removing ./test/t3.ibd# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 Renaming ./test/t3.new to ./test/t3.ibd# 2019-04-12T11:49:55 [56387] |# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 This target seems to be not prepared yet.# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 mariabackup: using the following InnoDB configuration for recovery:# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 innodb_data_home_dir = .# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 innodb_data_file_path = ibdata1:12M:autoextend# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 innodb_log_group_home_dir = .# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 Starting InnoDB instance for recovery.# 2019-04-12T11:49:55 [56387] | [00] 2019-04-12 11:49:54 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Uses event mutexes# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Compressed tables use zlib 1.2.11# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Number of pools: 1# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Using SSE2 crc32 instructions# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Completed initialization of buffer pool# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140299460404992 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Highest supported file format is Barracuda.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2096070# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file 'test/t3.ibd' with space ID 16, since the redo log references test/t3.ibd with space ID 14.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file 'test/t3.ibd' with space ID 16, since the redo log references test/t3.ibd with space ID 15.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file 'test/t3.ibd' with space ID 16, since the redo log references test/t3.ibd with space ID 15.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file 'test/t3.ibd' with space ID 16, since the redo log references test/t3.ibd with space ID 15.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file 'test/t3.ibd' with space ID 16, since the redo log references test/t3.ibd with space ID 15.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Ignoring data file './test/#sql-d993_11.ibd' with space ID 16. Another data file called test/t3.ibd exists with the same space ID.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 140300181104128 [Note] InnoDB: Starting final batch to recover 141 pages from redo log.# 2019-04-12T11:49:55 [56387] | 2019-04-12 11:49:54 0x7f9a2e74e600 InnoDB: Assertion failure in file storage/innobase/include/page0page.ic line 544# 2019-04-12T11:49:55 [56387] | InnoDB: Failing assertion: page_offset(rec) <= page_header_get_field(page, PAGE_HEAP_TOP)# 2019-04-12T11:49:55 [56387] | InnoDB: We intentionally generate a memory trap.....# 2019-04-12T11:49:55 [56387] | Thread pointer: 0x0# 2019-04-12T11:49:55 [56387] | Attempting backtrace. You can use the following information to find out# 2019-04-12T11:49:55 [56387] | where mysqld died. If you see no messages after this, something went# 2019-04-12T11:49:55 [56387] | terribly wrong...# 2019-04-12T11:49:55 [56387] | stack_bottom = 0x0 thread_stack 0x49000# 2019-04-12T11:49:55 [56387] | mysys/stacktrace.c:267(my_print_stacktrace)[0x5559fefdffcc]# 2019-04-12T11:49:55 [56387] | sql/signal_handler.cc:168(handle_fatal_signal)[0x5559fe919971]# 2019-04-12T11:49:55 [56387] | /lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7f9a2e32f670]# 2019-04-12T11:49:55 [56387] | linux/raise.c:58(__GI_raise)[0x7f9a2c41277f]# 2019-04-12T11:49:55 [56387] | stdlib/abort.c:91(__GI_abort)[0x7f9a2c41437a]# 2019-04-12T11:49:55 [56387] | ut/ut0mem.cc:42(ut_strlcpy(char*, char const*, unsigned long))[0x5559fed7d32e]# 2019-04-12T11:49:55 [56387] | include/page0page.ic:545(page_rec_check(unsigned char const*))[0x5559fea872f9]# 2019-04-12T11:49:55 [56387] | include/page0page.ic:298(page_rec_is_supremum(unsigned char const*))[0x5559fea8dbdb]# 2019-04-12T11:49:55 [56387] | page/page0cur.cc:1253(page_cur_insert_rec_low(unsigned char*, dict_index_t*, unsigned char const*, unsigned long*, mtr_t*))[0x5559fec3bd98]# 2019-04-12T11:49:55 [56387] | include/page0cur.ic:328(page_cur_rec_insert(page_cur_t*, unsigned char const*, dict_index_t*, unsigned long*, mtr_t*))[0x5559fec39015]# 2019-04-12T11:49:55 [56387] | page/page0cur.cc:1197(page_cur_parse_insert_rec(unsigned long, unsigned char const*, unsigned char const*, buf_block_t*, dict_index_t*, mtr_t*))[0x5559fec3bb34]# 2019-04-12T11:49:55 [56387] | log/log0recv.cc:1654(recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*))[0x5559fec10b07]# 2019-04-12T11:49:55 [56387] | log/log0recv.cc:2158(recv_recover_page(buf_block_t*, mtr_t&, recv_addr_t*, unsigned long))[0x5559fec129eb]# 2019-04-12T11:49:55 [56387] | log/log0recv.cc:2465(recv_apply_hashed_log_recs(bool))[0x5559fec13ad6]# 2019-04-12T11:49:55 [56387] | srv/srv0start.cc:2230(innobase_start_or_create_for_mysql())[0x5559fed24970]# 2019-04-12T11:49:55 [56387] | mariabackup/xtrabackup.cc:1990(innodb_init())[0x5559fe4eefa9]# 2019-04-12T11:49:55 [56387] | mariabackup/xtrabackup.cc:5573(xtrabackup_prepare_func(char**))[0x5559fe4f91ec]# 2019-04-12T11:49:55 [56387] | mariabackup/xtrabackup.cc:6400(main_low(char**))[0x5559fe4fb428]# 2019-04-12T11:49:55 [56387] | mariabackup/xtrabackup.cc:6193(main)[0x5559fe4fac3a]# 2019-04-12T11:49:55 [56387] | csu/libc-start.c:325(__libc_start_main)[0x7f9a2c3fd3f1]# 2019-04-12T11:49:55 [56387] | bld_debug/extra/mariabackup/mariabackup(_start+0x2a)[0x5559fe4ea6ba]# 2019-04-12T11:49:55 [56387] | The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains# 2019-04-12T11:49:55 [56387] | information that should help you find out what is causing the crash.# 2019-04-12T11:49:55 [56387] | Aborted (core dumped)