Matthias Leich added a comment - 2019-04-26 13:44 PRT -- Output of the mariabackup calls with "--backup" and later "--prepare" mtr.prt -- Output of my MTR call ./mysql-test-run.pl --mem --parallel=8 --repeat=10 --mysqld=--debug="d,ib_log_checkpoint_avoid" \ table_stress1 table_stress1 table_stress1 table_stress1 table_stress1 table_stress1 table_stress1 table_stress1 \ 2>&1 | tee mtr.prt table_stress1.test -- The MTR test You might need several run the MTR call several times in order to achieve at least one replay. In case replaying makes too much trouble than please show up.

Marko Mäkelä added a comment - 2019-04-29 08:22 - edited table_stress1.test does not repeat a crash for me every time, so the test is not deterministic. It is reproducing the following assertion for me: 10.2 bb4f4b3a1b6c9287fcef6a6d290fd228e8a181f1 mariabackup: /mariadb/10.2/storage/innobase/fil/fil0fil.cc:582: bool fil_node_t::read_page0(bool): Assertion `space->free_limit == 0 || space->free_limit == free_limit' failed. I helped the reproducibility with the following patch: diff --git a/storage/innobase/srv/srv0srv.cc b/storage/innobase/srv/srv0srv.cc index 58596175681..8dbb5aec827 100644 --- a/storage/innobase/srv/srv0srv.cc +++ b/storage/innobase/srv/srv0srv.cc @@ -2252,6 +2252,7 @@ srv_master_do_active_tasks(void) production server, those calls could cause "furious flushing" and stall the server. Normally we want to perform checkpoints early and often to avoid those situations. */ + return; DBUG_EXECUTE_IF("ib_log_checkpoint_avoid", return;); if (srv_shutdown_state != SRV_SHUTDOWN_NONE) { @@ -2341,6 +2342,7 @@ srv_master_do_idle_tasks(void) production server, those calls could cause "furious flushing" and stall the server. Normally we want to perform checkpoints early and often to avoid those situations. */ + return; DBUG_EXECUTE_IF("ib_log_checkpoint_avoid", return;); if (srv_shutdown_state != SRV_SHUTDOWN_NONE) { For one failure, I am seeing that tablespace ID 346 (table400_innodb_int_autoinc), the space->free_limit is first assigned to 64, then later to 128 (which is causing the assertion failure). The first assignment occurs with the following call stack: #0 fil_node_t::read_page0 (this=0x555557ad8b50, first=<optimized out>) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:586 #1 0x0000555555e8c417 in fil_node_open_file (node=<optimized out>) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:659 #2 0x0000555555e9b01a in fil_node_prepare_for_io (node=0x555557ad8b50, system=0x555557422970, space=0x555557ad8840) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:4701 #3 0x0000555555e8b842 in fil_space_get_space (id=<optimized out>) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:1575 #4 0x0000555555e8b9ec in fil_space_set_recv_size (id=346, size=4) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:1636 #5 0x0000555555f7dc63 in recv_parse_log_rec (type=0x7fffffff6380, ptr=0x7fffeff38377 "\004\201Z", end_ptr=0x7fffeff3a5bc "\001\004", space=0x7fffffff6388, page_no=0x7fffffff6390, apply=<optimized out>, body=0x7fffffff6398) Later, the field is assigned to 0,64,128, all with the following call stacks: #0 0x0000555555f83329 in recv_parse_or_apply_log_rec_body ( type=<optimized out>, ptr=0x7ffff13d7eab "", end_ptr=<optimized out>, space_id=346, page_no=0, apply=<optimized out>, block=0x7ffff0684840, mtr=0x7fffffff62a8) at /mariadb/10.2/storage/innobase/log/log0recv.cc:1633 #1 0x0000555555f7a3f0 in recv_recover_page (block=<optimized out>, mtr=..., recv_addr=<optimized out>, init_lsn=<optimized out>) at /mariadb/10.2/storage/innobase/log/log0recv.cc:2153 Then, we will read the page 0 again, because the file had been closed by fil_system->LRU meanwhile. At this point, fil_node_t::read_page0() is reading back stale data from page 0. We already have newer data in the buffer pool (and in fil_space_t )! So, we should not replace it with what we re-read from the file. The system tablespace is a special case: diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc index ccf1ac0ecef..d892898f555 100644 --- a/storage/innobase/fil/fil0fil.cc +++ b/storage/innobase/fil/fil0fil.cc @@ -579,13 +579,9 @@ bool fil_node_t::read_page0(bool first) return false; } - ut_ad(space->free_limit == 0 || space->free_limit == free_limit); - ut_ad(space->free_len == 0 || space->free_len == free_len); - space->size_in_header = size; - space->free_limit = free_limit; - space->free_len = free_len; - if (first) { + ut_ad(space->id != TRX_SYS_SPACE); + /* Truncate the size to a multiple of extent size. */ ulint mask = psize * FSP_EXTENT_SIZE - 1; @@ -598,8 +594,19 @@ bool fil_node_t::read_page0(bool first) this->size = ulint(size_bytes / psize); space->size += this->size; + } else if (space->id != TRX_SYS_SPACE || space->size_in_header) { + /* If this is not the first-time open, do nothing. + For the system tablespace, we always get invoked as + first=false, so we detect the true first-time-open based + on size_in_header and proceed to initiailze the data. */ + return true; } + ut_ad(space->free_limit == 0 || space->free_limit == free_limit); + ut_ad(space->free_len == 0 || space->free_len == free_len); + space->size_in_header = size; + space->free_limit = free_limit; + space->free_len = free_len; return true; }

Marko Mäkelä added a comment - 2019-04-29 09:07 mleich , I reported and fixed MDEV-19356 . I hope that you can now more easily create a test case for the original assertion failure.

Marko Mäkelä added a comment - 2019-04-30 12:39 backup.tar.bz2 is from a recent failure that mleich repeated. I can repeat the crash on that as follows: tar xjf backup.tar.bz2 gdb --args /dev/shm/10.2/extra/mariabackup/mariabackup --dbug=d,ib_log --prepare --target-dir=backup The output ends with the following: 10.2 810f014ca7a705381e110cb26649c528bc00f179 recv_group_scan_log_rec810f014ca7a705381e110cb26649c528bc00f179s: ib_log: MLOG_CHECKPOINT(21163148) reread at 22256297 mariabackup: /mariadb/10.2/storage/innobase/log/log0recv.cc:2858: bool recv_parse_log_recs(lsn_t, store_t, bool): Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed. … (gdb) p recv_sys->mlog_checkpoint_lsn $2 = 22277548 (gdb) p recv_sys->recovered_lsn $3 = 22256297

Marko Mäkelä added a comment - 2019-05-02 07:08 The assertion is complaining that multiple MLOG_CHECKPOINT records are referring to the same checkpoint LSN, from which the recovery started. Here is the relevant part of the ib_log output: 2019-05-02 9:25:53 140737339255808 [Note] InnoDB: Starting crash recovery from checkpoint LSN=22267837 recv_group_scan_log_recs: ib_log: scan 22267882: multi-log rec MLOG_FILE_NAME len 45 page 1372:0 … recv_group_scan_log_recs: ib_log: scan 22277538: multi-log end total_len 9398 n=152 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) read at 22277548 recv_group_scan_log_recs: ib_log: scan 22332928 completed recv_group_scan_log_recs: ib_log: scan 21163148: multi-log rec MLOG_1BYTE len 7 page 0:0 … recv_group_scan_log_recs: ib_log: scan 22241664: multi-log rec MLOG_FILE_NAME len 45 page 1372:0 … recv_group_scan_log_recs: ib_log: scan 22256287: multi-log rec MLOG_FILE_NAME len 63 page 1599:0 recv_group_scan_log_recs: ib_log: scan 22256287: multi-log end total_len 14205 n=229 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22256297 mariabackup: /mariadb/10.2/storage/innobase/log/log0recv.cc:2858: bool recv_parse_log_recs(lsn_t, store_t, bool): Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed. We start by jumping to the metadata ( MLOG_FILE_NAME records followed by MLOG_CHECKPOINT ) that were written at the completion of the log checkpoint. Then, we rewind to the start of the log, and at an earlier LSN, find another bunch of MLOG_FILE_NAME and MLOG_CHECKPOINT records for the same checkpoint LSN. To track this down, we must instrument log_checkpoint() in the server. Why are we issuing multiple checkpoints for the same LSN, with so many log records in between?

Marko Mäkelä added a comment - 2019-05-02 07:49 If I comment out the failing assertion, the backup will be recovered, and there will be more messages about `MLOG_CHECKPOINT` records for the same checkpoint: recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) read at 22277548 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22256297 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22266040 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22277548 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22287271 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22296982 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(21163148) reread at 22306693 It looks like log_checkpoint() is at the very least doing busy work (writing useless redo log records), and maybe at worst doing something wrong. In a worse scenario, this shares a common root cause with MDEV-13080 .

Marko Mäkelä added a comment - 2019-05-02 14:20 I believe that the log_checkpoint() parameter write_always is unnecessary and should be removed.

Marko Mäkelä added a comment - 2019-05-03 17:32 The assertion failure was fixed by removing the unnecessary parameter write_always and changing the code to behave as if it never held. Also, I changed some crash injection code to flush redo log instead of performing log checkpoint. This should improve the crash test coverage, as was already demonstrated by MDEV-19344 .