[MDEV-24848] Assertion `rlen < llen' failed in log_phys_t::apply_status log_phys_t::apply upon MariaBackup prepare Created: 2021-02-11  Updated: 2021-02-17  Resolved: 2021-02-17

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.5, 10.6
Fix Version/s: 10.5.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-12353 Efficient InnoDB redo log record format Closed

 Description   

--source include/have_innodb.inc
 
CREATE TABLE t1 (pk INT PRIMARY KEY, a YEAR) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
INSERT INTO t1 VALUES (1,2021);
UPDATE t1 SET a = NULL;
--exec $XTRABACKUP --backup --target-dir=$MYSQLTEST_VARDIR/mbackup_backup --protocol=tcp --port=$MASTER_MYPORT --user=root
--exec $XTRABACKUP --prepare --target-dir=$MYSQLTEST_VARDIR/mbackup_backup
 
# Cleanup
DROP TABLE t1;

10.5 b3df194e

mariabackup: /data/src/10.5/storage/innobase/log/log0recv.cc:493: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `rlen < llen' failed.
210214 18:48:09 [ERROR] mysqld got signal 6 ;
 
#6  0x00007f45bba53f36 in __GI___assert_fail (assertion=0x55cf22c804d8 "rlen < llen", file=0x55cf22c80040 "/data/src/10.5/storage/innobase/log/log0recv.cc", line=493, function=0x55cf22c801c0 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101
#7  0x000055cf224e77ff in log_phys_t::apply (this=0x7f45ade293d0, block=..., last_offset=@0x55cf252daa64: 152) at /data/src/10.5/storage/innobase/log/log0recv.cc:493
#8  0x000055cf224de6b8 in recv_recover_page (block=0x7f45adc01ab8, mtr=..., p=Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer': 
..., space=0x55cf252c7e08, init=0x55cf252daac0) at /data/src/10.5/storage/innobase/log/log0recv.cc:2330
#9  0x000055cf224ea65e in recv_sys_t::recover_low (this=0x55cf23312400 <recv_sys>, page_id=..., p=Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer': 
..., mtr=..., b=0x7f45adc01ab8) at /data/src/10.5/storage/innobase/log/log0recv.cc:2577
#10 0x000055cf224dfd88 in recv_sys_t::apply (this=0x55cf23312400 <recv_sys>, last_batch=true) at /data/src/10.5/storage/innobase/log/log0recv.cc:2680
#11 0x000055cf22624d40 in srv_start (create_new_db=false) at /data/src/10.5/storage/innobase/srv/srv0start.cc:1491
#12 0x000055cf2198ed2b in innodb_init () at /data/src/10.5/extra/mariabackup/xtrabackup.cc:2198
#13 0x000055cf21999c11 in xtrabackup_prepare_func (argv=0x55cf24d5c998) at /data/src/10.5/extra/mariabackup/xtrabackup.cc:5776
#14 0x000055cf2199c5ea in main_low (argv=0x55cf24d5c998) at /data/src/10.5/extra/mariabackup/xtrabackup.cc:6681
#15 0x000055cf2199bdfd in main (argc=3, argv=0x7fffaadc3678) at /data/src/10.5/extra/mariabackup/xtrabackup.cc:6473

The test case appears to be deterministic, at least for the time being.
Reproducible on 10.5, 10.6.
10.4 does not seem to have this assertion.
No obvious immediate problem on a non-debug build (prepare works, server can start on the prepared datadir, and the table is functonal).

Can also be reproduced with rr. Test case for running with rr (to store mariabackup profiles in addition to the server one, which is done automatically):

--source include/have_innodb.inc
 
CREATE TABLE t1 (pk INT PRIMARY KEY, a YEAR) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
INSERT INTO t1 VALUES (1,2021);
UPDATE t1 SET a = NULL;
--exec rr record --output-trace-dir=$MYSQLTEST_VARDIR/rr.1/rr-mbackup-backup $XTRABACKUP --backup --target-dir=$MYSQLTEST_VARDIR/mbackup_backup --protocol=tcp --port=$MASTER_MYPORT --user=root
--exec rr record --output-trace-dir=$MYSQLTEST_VARDIR/rr.1/rr-mbackup-prepare $XTRABACKUP --prepare --target-dir=$MYSQLTEST_VARDIR/mbackup_backup
 
# Cleanup
DROP TABLE t1;



 Comments   
Comment by Marko Mäkelä [ 2021-02-15 ]

elenst, thank you. I think that the assertion could be only complaining that a MEMSET record is unnecessarily being used instead of a more compact WRITE record. For a memset() of 1 byte, a WRITE record would use less space.

Now that we have GA releases that are writing such inefficient records, I think that we must relax the debug assertion, to avoid false positives on upgrades.

Apart from btr_cur_upd_rec_in_place(), such single-byte memset() may be written in a number of places where the length parameter is not a constant. I think that we can live with the 1-byte extra overhead in most of these places.

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