[MDEV-17289] Multi-pass recovery fails to apply some redo log records Created: 2018-09-25  Updated: 2020-11-19  Resolved: 2018-10-05

Status: Closed
Project: MariaDB Server
Component/s: Backup, Storage Engine - InnoDB
Affects Version/s: 10.2.15, 10.2.17, 10.3.6
Fix Version/s: 10.3.11, 10.2.19

Type: Bug Priority: Major
Reporter: Thirunarayanan Balathandayuthapani Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 1
Labels: None

Attachments: File l1.patch    
Issue Links:
Problem/Incident
is caused by MDEV-15325 Incomplete validation of missing tabl... Closed
Relates
relates to MDEV-24197 Prepare step of backup failing on lar... Closed

 Description   

The following commands can able to repeat the scenario:

 ./mtr gcol.gcol_update gcol.innodb_virtual_fk gcol.innodb_virtual_rebuild innodb.log_file_name_debug --mem --big-test --no-reorder

It fails with the following stack trace:

 
 
#6  0x00007ff0a36a7bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5598cd18bccb "!page || page_type == 2", file=file@entry=0x5598cd18ae40 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc", line=line@entry=1519, function=function@entry=0x5598cd18e720 <recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*)::__PRETTY_FUNCTION__> "byte* recv_parse_or_apply_log_rec_body(mlog_id_t, byte*, byte*, ulint, ulint, bool, buf_block_t*, mtr_t*)") at assert.c:92
 
#7  0x00007ff0a36a7c82 in __GI___assert_fail (assertion=0x5598cd18bccb "!page || page_type == 2", file=0x5598cd18ae40 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc", line=1519, function=0x5598cd18e720 <recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*)::__PRETTY_FUNCTION__> "byte* recv_parse_or_apply_log_rec_body(mlog_id_t, byte*, byte*, ulint, ulint, bool, buf_block_t*, mtr_t*)") at assert.c:101
 
#8  0x00005598ccbbb784 in recv_parse_or_apply_log_rec_body (type=MLOG_UNDO_HDR_CREATE, ptr=0x7ff09cfc92f8 "", end_ptr=0x7ff09cfc92fd "", space_id=0, page_no=511, apply=true, block=0x7ff09cdc87f0, mtr=0x7ffdf9f38d90) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc:1519
 
#9  0x00005598ccbbcb59 in recv_recover_page (just_read_in=true, block=0x7ff09cdc87f0) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc:1964
 
#10 0x00005598ccd98b27 in buf_page_io_complete (bpage=0x7ff09cdc87f0, dblwr=false, evict=false) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0buf.cc:6194
 
#11 0x00005598ccdbddda in buf_read_page_low (err=0x7ffdf9f39764, sync=true, type=0, mode=132, page_id=..., page_size=..., unzip=false, ignore_missing_space=false) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0rea.cc:225
 
#12 0x00005598ccdbe765 in buf_read_page (page_id=..., page_size=...) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0rea.cc:460
 
#13 0x00005598ccd93a6e in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10, file=0x5598cd216b80 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/trx0undo.ic", line=164, mtr=0x7ffdf9f39d50, err=0x0) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0buf.cc:4468
 
#14 0x00005598ccd29771 in trx_undo_page_get (page_id=..., mtr=0x7ffdf9f39d50) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/trx0undo.ic:163
 
#15 0x00005598ccd2be4d in trx_undo_mem_create_at_db_start (rseg=0x5598cfd83400, id=1, page_no=511, mtr=0x7ffdf9f39d50) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0undo.cc:1148
 
#16 0x00005598ccd2c52b in trx_undo_lists_init (rseg=0x5598cfd83400) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0undo.cc:1273
 
#17 0x00005598ccd12e05 in trx_rseg_mem_restore (rseg=0x5598cfd83400, mtr=0x7ffdf9f3a330) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0rseg.cc:198
 
#18 0x00005598ccd13188 in trx_rseg_array_init () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0rseg.cc:258
 
#19 0x00005598ccd1bd31 in trx_lists_init_at_db_start () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0trx.cc:915
 
#20 0x00005598ccd1640c in trx_sys_init_at_db_start () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/trx/trx0sys.cc:504
 
#21 0x00005598cccd3ed3 in innobase_start_or_create_for_mysql () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/srv/srv0start.cc:2252
 
#22 0x00005598ccb1a266 in innobase_init (p=0x5598cf600250) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/handler/ha_innodb.cc:4360
 
#23 0x00005598cc791bf9 in ha_initialize_handlerton (plugin=0x5598cf5ccd90) at /home/thiru/mariarepo/dev-14398/10.2/sql/handler.cc:521
 
#24 0x00005598cc533742 in plugin_initialize (tmp_root=0x7ffdf9f438e0, plugin=0x5598cf5ccd90, argc=0x5598cdb11868 <remaining_argc>, argv=0x5598cf484140, options_only=false) at /home/thiru/mariarepo/dev-14398/10.2/sql/sql_plugin.cc:1416
 
#25 0x00005598cc53436f in plugin_init (argc=0x5598cdb11868 <remaining_argc>, argv=0x5598cf484140, flags=2) at /home/thiru/mariarepo/dev-14398/10.2/sql/sql_plugin.cc:1697
 
#26 0x00005598cc43c487 in init_server_components () at /home/thiru/mariarepo/dev-14398/10.2/sql/mysqld.cc:5285
 
#27 0x00005598cc43d564 in mysqld_main (argc=147, argv=0x5598cf484140) at /home/thiru/mariarepo/dev-14398/10.2/sql/mysqld.cc:5881
 
#28 0x00005598cc432550 in main (argc=25, argv=0x7ffdf9f44678) at /home/thiru/mariarepo/dev-14398/10.2/sql/main.cc:25



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2018-09-25 ]

It repeats the one more scenario too:

#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x0000564b8fcc7f56 in my_write_core (sig=6) at /home/thiru/mariarepo/dev-14398/10.2/mysys/stacktrace.c:477
 
#2  0x0000564b8f55ff2f in handle_fatal_signal (sig=6) at /home/thiru/mariarepo/dev-14398/10.2/sql/signal_handler.cc:305
 
#3  <signal handler called>
 
#4  0x00007f1ebfd28428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
 
#5  0x00007f1ebfd2a02a in __GI_abort () at abort.c:89
 
#6  0x00007f1ebfd20bd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x564b8ff7f249 "ret > 0", file=file@entry=0x564b8ff7f110 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/rem0rec.ic", line=line@entry=436, function=function@entry=0x564b8ff806c0 <_ZZL20rec_get_n_fields_oldPKhE19__PRETTY_FUNCTION__> "ulint rec_get_n_fields_old(const rec_t*)") at assert.c:92
 
#7  0x00007f1ebfd20c82 in __GI___assert_fail (assertion=0x564b8ff7f249 "ret > 0", file=0x564b8ff7f110 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/rem0rec.ic", line=436, function=0x564b8ff806c0 <_ZZL20rec_get_n_fields_oldPKhE19__PRETTY_FUNCTION__> "ulint rec_get_n_fields_old(const rec_t*)") at assert.c:101
 
#8  0x0000564b8f9e7502 in rec_get_n_fields_old (rec=0x7f1eb95a960b "") at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/rem0rec.ic:436
 
#9  0x0000564b8f9e9671 in rec_get_offsets_func (rec=0x7f1eb95a960b "", index=0x564b91bb1b68, offsets=0x7ffc46396dd0, leaf=true, n_fields=18446744073709551615, file=0x564b8ff6a738 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/page/page0cur.cc", line=1148, heap=0x7ffc46396d70) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/rem/rem0rec.cc:584
 
#10 0x0000564b8f9b64ce in page_cur_parse_insert_rec (is_short=0, ptr=0x7f1eb9495627 "@<840,\035\026\020\b", end_ptr=0x7f1eb9495677 "", block=0x7f1eb9434f20, index=0x564b91bb1b68, mtr=0x7ffc46397bb0) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/page/page0cur.cc:1148
 
#11 0x0000564b8f98af21 in recv_parse_or_apply_log_rec_body (type=MLOG_REC_INSERT, ptr=0x7f1eb9495620 "\026\v\200\241", end_ptr=0x7f1eb9495677 "", space_id=0, page_no=11, apply=true, block=0x7f1eb9434f20, mtr=0x7ffc46397bb0) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc:1412
 
#12 0x0000564b8f98cb59 in recv_recover_page (just_read_in=true, block=0x7f1eb9434f20) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/log/log0recv.cc:1964
 
#13 0x0000564b8fb68b27 in buf_page_io_complete (bpage=0x7f1eb9434f20, dblwr=false, evict=false) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0buf.cc:6194
 
#14 0x0000564b8fb8ddda in buf_read_page_low (err=0x7ffc46398584, sync=true, type=0, mode=132, page_id=..., page_size=..., unzip=false, ignore_missing_space=false) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0rea.cc:225
 
#15 0x0000564b8fb8e765 in buf_read_page (page_id=..., page_size=...) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0rea.cc:460
 
#16 0x0000564b8fb63a6e in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x564b90033268 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc", line=2438, mtr=0x7ffc4639aa70, err=0x7ffc46398a20) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/buf/buf0buf.cc:4468
 
#17 0x0000564b8fb2af88 in btr_cur_search_to_nth_level (index=0x564b91bade38, level=0, tuple=0x564b91bb0b08, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7ffc46399bf0, has_search_latch=0, file=0x564b90033268 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc", line=2438, mtr=0x7ffc4639aa70, autoinc=0) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/btr/btr0cur.cc:1218
 
#18 0x0000564b8fb3e6d5 in btr_pcur_open_low (index=0x564b91bade38, level=0, tuple=0x564b91bb0b08, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7ffc46399bf0, file=0x564b90033268 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc", line=2438, autoinc=0, mtr=0x7ffc4639aa70) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/include/btr0pcur.ic:483
 
#19 0x0000564b8fb3ff40 in btr_pcur_open_on_user_rec_func (index=0x564b91bade38, tuple=0x564b91bb0b08, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7ffc46399bf0, file=0x564b90033268 "/home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc", line=2438, mtr=0x7ffc4639aa70) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/btr/btr0pcur.cc:599
 
#20 0x0000564b8fbc4894 in dict_load_indexes (table=0x564b91b7fd68, heap=0x564b91bb0a80, ignore_err=DICT_ERR_IGNORE_NONE) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc:2438
 
#21 0x0000564b8fbc6ffc in dict_load_sys_table (table=0x564b91b7fd68) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0load.cc:3247
 
#22 0x0000564b8fb97e77 in dict_boot () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/dict/dict0boot.cc:514
 
#23 0x0000564b8faa3e93 in innobase_start_or_create_for_mysql () at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/srv/srv0start.cc:2246
 
#24 0x0000564b8f8ea266 in innobase_init (p=0x564b91430250) at /home/thiru/mariarepo/dev-14398/10.2/storage/innobase/handler/ha_innodb.cc:4360
 
#25 0x0000564b8f561bf9 in ha_initialize_handlerton (plugin=0x564b913fcd90) at /home/thiru/mariarepo/dev-14398/10.2/sql/handler.cc:521
 
#26 0x0000564b8f303742 in plugin_initialize (tmp_root=0x7ffc463a4000, plugin=0x564b913fcd90, argc=0x564b908e1868 <remaining_argc>, argv=0x564b912b4140, options_only=false) at /home/thiru/mariarepo/dev-14398/10.2/sql/sql_plugin.cc:1416
 
#27 0x0000564b8f30436f in plugin_init (argc=0x564b908e1868 <remaining_argc>, argv=0x564b912b4140, flags=2) at /home/thiru/mariarepo/dev-14398/10.2/sql/sql_plugin.cc:1697
 
#28 0x0000564b8f20c487 in init_server_components () at /home/thiru/mariarepo/dev-14398/10.2/sql/mysqld.cc:5285
 
#29 0x0000564b8f20d564 in mysqld_main (argc=148, argv=0x564b912b4140) at /home/thiru/mariarepo/dev-14398/10.2/sql/mysqld.cc:5881
 
#30 0x0000564b8f202550 in main (argc=26, argv=0x7ffc463a4d98) at /home/thiru/mariarepo/dev-14398/10.2/sql/main.cc:25

Basically it tries to apply the redo log record for the old page.

Comment by Thirunarayanan Balathandayuthapani [ 2018-10-04 ]

l1.patch

Patch also does recovers from old checkpoint lsn. Still it can able to repeat the crash.So suspecting there could be page flush missing during checkpoint.

Comment by Marko Mäkelä [ 2018-10-09 ]

In the end, it turned out that there was no missing page flush.
As noted in the commit message, it was the recovery that wrongly ignored some redo log records.

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