[MDEV-31803] InnoDB aborts during recovery when immediate_scrub_data_uncompressed is enabled Created: 2023-07-31  Updated: 2023-07-31  Resolved: 2023-07-31

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.9
Fix Version/s: 10.9.8, 10.10.6, 10.11.5, 11.1.2, 11.2.1

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


 Description   

This issue happens during recovery when immedidate_scrub_data_uncompressed is enabled.

[rr 3682863 5629]2023-07-30 12:21:21 0 [ERROR] [FATAL] InnoDB: Trying to write 65536 bytes at 3211264 outside the bounds of the file: test/t6.ibd
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00007f9a4e8e4859 in __GI_abort () at abort.c:79
 
#2  0x0000561e5f259fc1 in fil_invalid_page_access_msg (name=<optimized out>, offset=offset@entry=3211264, len=len@entry=65536, is_read=<optimized out>)
 
    at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/fil/fil0fil.cc:2775
 
#3  0x0000561e5f271d6c in fil_space_t::io (this=this@entry=0x612000024dc0, type=..., offset=3211264, len=<optimized out>, buf=buf@entry=0x0, bpage=bpage@entry=0x0)
 
    at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/include/os0file.h:210
 
#4  0x0000561e5f199f8c in fil_space_t::flush_freed (this=this@entry=0x612000024dc0, writable=writable@entry=true) at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/include/os0file.h:206
 
#5  0x0000561e5f19a6c2 in buf_flush_space (id=id@entry=38) at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/buf/buf0flu.cc:1157
 
#6  0x0000561e5f1a70e1 in buf_do_flush_list_batch (max_n=max_n@entry=2000, lsn=lsn@entry=356470250) at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/buf/buf0flu.cc:1429
 
#7  0x0000561e5f1a839c in buf_flush_list_holding_mutex (max_n=max_n@entry=2000, lsn=lsn@entry=356470250) at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/buf/buf0flu.cc:1527
 
#8  0x0000561e5f1ad2c4 in buf_flush_page_cleaner () at /data/Server/bb-11.2-MDEV-14795A/storage/innobase/buf/buf0flu.cc:2504
 
#9  0x0000561e5da64e47 in std::__invoke_impl<void, void (*)()> (__f=<optimized out>) at /usr/include/c++/9/bits/invoke.h:89
 
#10 std::__invoke<void (*)()> (__fn=<optimized out>) at /usr/include/c++/9/bits/invoke.h:95
 
#11 std::thread::_Invoker<std::tuple<void (*)()> >::_M_invoke<0ul> (this=<optimized out>) at /usr/include/c++/9/thread:244
 
#12 std::thread::_Invoker<std::tuple<void (*)()> >::operator() (this=<optimized out>) at /usr/include/c++/9/thread:251
 
#13 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)()> > >::_M_run (this=<optimized out>) at /usr/include/c++/9/thread:195
 
#14 0x00007f9a4ecf3de4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
 
#15 0x00007f9a4ee0e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#16 0x00007f9a4e9e1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Problem is that InnoDB scans the complete redo log to ensure that there is no corruption
and to find the end of the log. During this scan, InnoDB saves all the freed ranges,
but it doesn't save recovered size.

Later, InnoDB recovery applies partial redo logs and IO thread tries to flush
the all freed ranges which was noted during previous complete scan of redo logs.

Patch to fix the issue:

diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
 
index ec3960999df..a64403b5c67 100644
 
--- a/storage/innobase/log/log0recv.cc
 
+++ b/storage/innobase/log/log0recv.cc
 
@@ -2656,7 +2656,8 @@ recv_sys_t::parse_mtr_result recv_sys_t::parse(source &l, bool if_exists)
 
       case INIT_PAGE:
 
         last_offset= FIL_PAGE_TYPE;
 
       free_or_init_page:
 
-        store_freed_or_init_rec(id, (b & 0x70) == FREE_PAGE);
 
+        if (store)
 
+         store_freed_or_init_rec(id, (b & 0x70) == FREE_PAGE);
 
         if (UNIV_UNLIKELY(rlen != 0))
 
           goto record_corrupted;
 
         break;



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2023-07-31 ]

Patch is in st-10.9-MDEV-31803

Comment by Marko Mäkelä [ 2023-07-31 ]

Thank you, thiru!

I was wondering if this could have been caused by my MDEV-29911, but it looks like this may have been broken ever since your MDEV-8139 follow-up to MDEV-15528.

The 10.9 version looks OK to me. For 10.5 and 10.6, I suspect that we may need an equivalent change. If you can reproduce this in 10.6 or 10.5 (both use the same log format), please test and push a fix to 10.5 as well. The following might be the correct fix for them:

diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
 
index 1b62b1fe111..f2277480a2e 100644
 
--- a/storage/innobase/log/log0recv.cc
 
+++ b/storage/innobase/log/log0recv.cc
 
@@ -1931,7 +1931,8 @@ bool recv_sys_t::parse(lsn_t checkpoint_lsn, store_t *store, bool apply)
 
       case INIT_PAGE:
 
         last_offset= FIL_PAGE_TYPE;
 
       free_or_init_page:
 
-        store_freed_or_init_rec(id, (b & 0x70) == FREE_PAGE);
 
+        if (*store != STORE_NO)
 
+          store_freed_or_init_rec(id, (b & 0x70) == FREE_PAGE);
 
         if (UNIV_UNLIKELY(rlen != 0))
 
           goto record_corrupted;
 
         break;

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