Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-19346

Assertion `recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn' failed in recv_parse_log_recs during mariabackup --prepare

Details

    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]
       
      
      

      Attachments

        1. backup.tar.bz2
          1.69 MB
        2. mtr.prt
          26 kB
        3. PRT
          218 kB
        4. table_stress1.test
          272 kB

        Issue Links

          Activity

            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.
            

            mleich Matthias Leich added a comment - 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 Marko Mäkelä added a comment - - 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 Marko Mäkelä added a comment - - 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; }

            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 Marko Mäkelä added a comment - mleich , I reported and fixed MDEV-19356 . I hope that you can now more easily create a test case for the original assertion failure.

            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 Marko Mäkelä added a comment - 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

            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 Marko Mäkelä added a comment - 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?

            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 Marko Mäkelä added a comment - 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 .

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

            marko Marko Mäkelä added a comment - I believe that the log_checkpoint() parameter write_always is unnecessary and should be removed.

            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.

            marko Marko Mäkelä added a comment - 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 .

            People

              marko Marko Mäkelä
              mleich Matthias Leich
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.