[MDEV-19346] Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed in recv_parse_log_recs during mariabackup --prepare Created: 2019-04-26  Updated: 2019-05-06  Resolved: 2019-05-03

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

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: None
Environment:

Linux Ubuntu 17.10 but most probably unimportant

Attachments: HTML File PRT     File backup.tar.bz2     File mtr.prt     File table_stress1.test    
Issue Links:
Blocks
is blocked by MDEV-19356 Assertion 'space->free_limit == 0 || ... Closed
Relates
relates to MDEV-13080 [ERROR] InnoDB: Missing MLOG_CHECKPOI... Closed

 Description    

I found a problem (different assert but server setup differs somehow too) during
 
RQG testing.
 
The attempt to derive some MTR based test shows the assert reported here.
 
1. Load some data
 
2. mariabackup --backup (passes)
 
3. mariabackup --prepare (fails with core)
 
mariabackup: storage/innobase/log/log0recv.cc:2857: bool recv_parse_log_recs(lsn_t, store_t, bool): Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed.
 
190426 12:52:08 [ERROR] mysqld got signal 6 ;
 
...
 
#2  <signal handler called>
 
#3  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#4  0x00007fae1b888f5d in __GI_abort () at abort.c:90
 
#5  0x00007fae1b87ef17 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x561ff08fe288 "recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn", file=file@entry=0x561ff08fc698 "storage/innobase/log/log0recv.cc", line=line@entry=2857, function=function@entry=0x561ff0901360 <recv_parse_log_recs(unsigned long, store_t, bool)::__PRETTY_FUNCTION__> "bool recv_parse_log_recs(lsn_t, store_t, bool)") at assert.c:92
 
#6  0x00007fae1b87efc2 in __GI___assert_fail (assertion=0x561ff08fe288 "recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn", file=0x561ff08fc698 "storage/innobase/log/log0recv.cc", line=2857, function=0x561ff0901360 <recv_parse_log_recs(unsigned long, store_t, bool)::__PRETTY_FUNCTION__> "bool recv_parse_log_recs(lsn_t, store_t, bool)") at assert.c:101
 
#7  0x0000561ff02b0491 in recv_parse_log_recs (checkpoint_lsn=21762728, store=STORE_YES, apply=true) at storage/innobase/log/log0recv.cc:2857
 
#8  0x0000561ff02b14df in recv_scan_log_recs (available_memory=96468992, store_to_hash=0x7ffd2e245c54, log_block=0x7fae146f6200 '\245' <repeats 200 times>..., checkpoint_lsn=21762728, start_lsn=22614528, end_lsn=22680064, contiguous_lsn=0x7ffd2e245ce0, group_scanned_lsn=0x561ff30a7530) at storage/innobase/log/log0recv.cc:3329
 
#9  0x0000561ff02b19f0 in recv_group_scan_log_recs (group=0x561ff30a7500, checkpoint_lsn=21762728, contiguous_lsn=0x7ffd2e245ce0, last_phase=false) at storage/innobase/log/log0recv.cc:3427
 
#10 0x0000561ff02b2d2b in recv_recovery_from_checkpoint_start (flush_lsn=1633870) at storage/innobase/log/log0recv.cc:3751
 
#11 0x0000561ff03bfce7 in innobase_start_or_create_for_mysql () at storage/innobase/srv/srv0start.cc:2188
 
#12 0x0000561fefb88878 in innodb_init () at extra/mariabackup/xtrabackup.cc:1990
 
#13 0x0000561fefb92a1b in xtrabackup_prepare_func (argv=0x561ff2bcca90) at extra/mariabackup/xtrabackup.cc:5571
 
#14 0x0000561fefb94d40 in main_low (argv=0x561ff2bcca90) at extra/mariabackup/xtrabackup.cc:6398
 
#15 0x0000561fefb94552 in main (argc=7, argv=0x7ffd2e24a9f8) at extra/mariabackup/xtrabackup.cc:6191
 
 
 
10.2 commit 3dffdee667666df9ade9f2c458bf1ea495ffba02 2019-04-25
 
 
 
The assert seen during RQG testing (also during mariabackup --prepare) was
 
mariabackup: storage/innobase/fil/fil0fil.cc:582: bool fil_node_t::read_page0(bool): Assertion `space->free_limit == 0 || space->free_limit == free_limit' failed.
 
...
 
# 2019-04-25T17:37:52 [228049] | mysys/stacktrace.c:267(my_print_stacktrace)[0x563bac73a344]
 
# 2019-04-25T17:37:52 [228049] | sql/signal_handler.cc:168(handle_fatal_signal)[0x563bac07401d]
 
# 2019-04-25T17:37:52 [228049] | /lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7fc6eb261670]
 
[228050] SELECT 13 /* E_R Thread1 QNO 19501 CON_ID 16 */ ;
 
# 2019-04-25T17:37:52 [228049] | linux/raise.c:58(__GI_raise)[0x7fc6e934477f]
 
# 2019-04-25T17:37:52 [228049] | stdlib/abort.c:91(__GI_abort)[0x7fc6e934637a]
 
# 2019-04-25T17:37:52 [228049] | assert/assert.c:92(__assert_fail_base)[0x7fc6e933cb47]
 
# 2019-04-25T17:37:52 [228049] | /lib/x86_64-linux-gnu/libc.so.6(+0x2dbf2)[0x7fc6e933cbf2]
 
# 2019-04-25T17:37:52 [228049] | fil/fil0fil.cc:583(fil_node_t::read_page0(bool))[0x563bac265965]
 
# 2019-04-25T17:37:52 [228049] | fil/fil0fil.cc:659(fil_node_open_file(fil_node_t*))[0x563bac265e7e]
 
# 2019-04-25T17:37:52 [228049] | fil/fil0fil.cc:4701(fil_node_prepare_for_io(fil_node_t*, fil_system_t*, fil_space_t*))[0x563bac272397]
 
# 2019-04-25T17:37:52 [228049] | fil/fil0fil.cc:4959(fil_io(IORequest const&, bool, page_id_t, page_size_t const&, unsigned long, unsigned long, void*, void*, bool))[0x563bac27303a]
 
[228050] SELECT 13 /* E_R Thread1 QNO 19502 CON_ID 16 */ ;
 
# 2019-04-25T17:37:52 [228049] | buf/buf0rea.cc:181(buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, page_id_t, page_size_t const&, bool, bool))[0x563bac2279c2]
 
# 2019-04-25T17:37:52 [228049] | buf/buf0rea.cc:942(buf_read_recv_pages(bool, unsigned long, unsigned long const*, unsigned long))[0x563bac229870]
 
# 2019-04-25T17:37:52 [228049] | log/log0recv.cc:2282(recv_read_in_area(page_id_t))[0x563bac36d8ff]
 
# 2019-04-25T17:37:52 [228049] | log/log0recv.cc:2388(recv_apply_hashed_log_recs(bool))[0x563bac36dee1]
 
# 2019-04-25T17:37:52 [228049] | srv/srv0start.cc:2226(innobase_start_or_create_for_mysql())[0x563bac47efda]
 
# 2019-04-25T17:37:52 [228049] | mariabackup/xtrabackup.cc:1990(innodb_init())[0x563babc491e9]
 
[228050] SELECT 13 /* E_R Thread1 QNO 19503 CON_ID 16 */ ;
 
# 2019-04-25T17:37:52 [228049] | mariabackup/xtrabackup.cc:5571(xtrabackup_prepare_func(char**))[0x563babc5340d]
 
# 2019-04-25T17:37:52 [228049] | mariabackup/xtrabackup.cc:6398(main_low(char**))[0x563babc55649]
 
# 2019-04-25T17:37:52 [228049] | mariabackup/xtrabackup.cc:6191(main)[0x563babc54e5b]
 
# 2019-04-25T17:37:52 [228049] | csu/libc-start.c:325(__libc_start_main)[0x7fc6e932f3f1]
 
# 2019-04-25T17:37:52 [228049] | /work/10.2_clean/bld_debug/extra/mariabackup/mariabackup(_start+0x2a)[0x563babc448fa]
 
 



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

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.

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

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;
 
 }

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

mleich, I reported and fixed MDEV-19356. I hope that you can now more easily create a test case for the original assertion failure.

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

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

Comment by Marko Mäkelä [ 2019-05-02 ]

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?

Comment by Marko Mäkelä [ 2019-05-02 ]

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.

Comment by Marko Mäkelä [ 2019-05-02 ]

I believe that the log_checkpoint() parameter write_always is unnecessary and should be removed.

Comment by Marko Mäkelä [ 2019-05-03 ]

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.

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