[MDEV-19241] InnoDB fails to write MLOG_INDEX_LOAD upon completing ALTER TABLE Created: 2019-04-11  Updated: 2019-12-17  Resolved: 2019-04-17

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.2, 10.3.0, 10.4.0
Fix Version/s: 10.2.24, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: corruption, crash, ddl, recovery, upstream

Issue Links:
Blocks
blocks MDEV-12699 Improve crash recovery of corrupted d... Closed
Relates
relates to MDEV-21339 rpl.rpl_sync test failed, assertion p... Closed

 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.

 Comments   
Comment by Matthias Leich [ 2019-04-12 ] 

# 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)

Comment by Marko Mäkelä [ 2019-04-12 ]

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().

Comment by Matthias Leich [ 2019-04-16 ] 

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 ;

Comment by Marko Mäkelä [ 2019-04-17 ]

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).

Generated at Thu Feb 08 08:50:07 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.