[MDEV-30657] [ERROR] InnoDB: Not applying UNDO_APPEND due to corruption during Recovery Created: 2023-02-15  Updated: 2023-02-21  Resolved: 2023-02-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: N/A
Fix Version/s: 10.11.3, 11.0.1, 10.5.20, 10.6.13, 10.7.8, 10.8.8, 10.9.6, 10.10.4

Type: Bug Priority: Blocker
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression

Attachments: File data.tar.xz    
Issue Links:
Problem/Incident
is caused by MDEV-30479 OPT_PAGE_CHECKSUM mismatch during rec... Closed
Relates

 Description    

origin/10.5 690fcfbd2954f9470047ce754c2a5c2fdfd15cf3 2023-02-14T16:27:21+00:00
 
Build with RelWithDebInfo+ASAN
 
 
 
Scenario:
 
1. Start the server, one session generate some initial data
 
2. Several sessions run concurrent DML only
 
3. During 2. is ongoing SIGKILL the server intentionally
 
4. Restart attempt
 
The last ends with
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 3889]2023-02-15 12:35:46 0 [Note] InnoDB: Opened 3 undo tablespaces
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 3893]2023-02-15 12:35:46 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=151914371,159538155
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 4003]2023-02-15 12:35:47 0 [Note] InnoDB: Starting a batch to recover 396 pages from redo log.
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 5466]2023-02-15 12:35:47 0 [ERROR] InnoDB: Not applying UNDO_APPEND due to corruption on [page id: space=2, page number=390]
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 5470]2023-02-15 12:35:47 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 5657]2023-02-15 12:35:47 0 [ERROR] [FATAL] InnoDB: Trying to write 8192 bytes at 5242880 outside the bounds of the file: .//undo002
 
# 2023-02-15T12:37:23 [3163608] | [rr 3292492 5678]230215 12:35:47 [rr 3292492 5680][ERROR] mysqld got signal 6 ;
 
 
 
pluto:/data/results/1676463901/TBR-1795$ _RR_TRACE_DIR=./1/rr/ rr replay --mark-stdio mysqld-1
 
    # Fate of the server till SIGKILL
 
pluto:/data/results/1676463901/TBR-1795$ _RR_TRACE_DIR=./1/rr/ rr replay --mark-stdio mysqld-2
 
    # Fate of the server during the restart failing around recovery
 
pluto:/data/results/1676463901/TBR-1795/1/fbackup
 
    # Backup of the data directory after SIGKILL and before the restart
 
 
 
RQG
 
# git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG
 
#
 
# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD b82f03cf948740e0040c4d6cb4ac52e46b66c3b2 2023-02-14T12:49:41+01:00
 
# rqg.pl  : Version 4.2.1 (2022-12)
 
#
 
# $RQG_HOME/rqg.pl \
 
# --grammar=conf/engines/many_indexes.yy \
 
# --gendata=conf/engines/many_indexes.zz \
 
# --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
 
# --mysqld=--loose-idle_write_transaction_timeout=0 \
 
# --mysqld=--loose-idle_transaction_timeout=0 \
 
# --mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
# --mysqld=--connect_timeout=60 \
 
# --mysqld=--interactive_timeout=28800 \
 
# --mysqld=--slave_net_timeout=60 \
 
# --mysqld=--net_read_timeout=30 \
 
# --mysqld=--net_write_timeout=60 \
 
# --mysqld=--loose-table_lock_wait_timeout=50 \
 
# --mysqld=--wait_timeout=28800 \
 
# --mysqld=--lock-wait-timeout=86400 \
 
# --mysqld=--innodb-lock-wait-timeout=50 \
 
# --no-mask \
 
# --queries=10000000 \
 
# --seed=random \
 
# --reporters=Backtrace \
 
# --reporters=ErrorLog \
 
# --reporters=Deadlock \
 
# --validators=None \
 
# --mysqld=--log_output=none \
 
# --mysqld=--log_bin_trust_function_creators=1 \
 
# --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
# --engine=InnoDB \
 
# --restart_timeout=360 \
 
# --mysqld=--plugin-load-add=file_key_management.so \
 
# --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
 
# --mysqld=--plugin-load-add=provider_lzo.so \
 
# --mysqld=--plugin-load-add=provider_bzip2.so \
 
# --mysqld=--plugin-load-add=provider_lzma.so \
 
# --mysqld=--plugin-load-add=provider_snappy.so \
 
# --mysqld=--plugin-load-add=provider_lz4.so \
 
# --duration=300 \
 
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
# --mysqld=--loose-innodb_read_only_compressed=OFF \
 
# --reporters=CrashRecovery \
 
# --duration=300 \
 
# --mysqld=--innodb_stats_persistent=on \
 
# --mysqld=--innodb_adaptive_hash_index=on \
 
# --mysqld=--innodb_sort_buffer_size=65536 \
 
# --redefine=conf/mariadb/redefine_checks_off.yy \
 
# --mysqld=--log-bin \
 
# --mysqld=--sync-binlog=1 \
 
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
 
# --mysqld=--loose-max-statement-time=30 \
 
# --threads=9 \
 
# --mysqld=--innodb-use-native-aio=0 \
 
# --mysqld=--loose-gdb \
 
# --mysqld=--loose-debug-gdb \
 
# --rr=Extended \
 
# --rr_options=--chaos --wait \
 
# --mysqld=--innodb_undo_log_truncate=ON \
 
# --mysqld=--innodb_undo_tablespaces=3 \
 
# --mysqld=--innodb_rollback_on_timeout=ON \
 
# --mysqld=--innodb_page_size=8K \
 
# --mysqld=--innodb-buffer-pool-size=8M \
 
# <local settings>



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

During recovery, the frame of the undo log page 2:0x186 is completely filled with NUL bytes. The LSN is as follows:

#3  0x0000558068012852 in log_phys_t::apply (this=0x3087344da178, block=..., 
    last_offset=@0x60600005746c: 0)
 
    at /data/Server/10.5/storage/innobase/log/log0recv.cc:310
 
310	          if (undo_append(block, ++l, --rlen) && !srv_force_recovery)
 
(rr) p *this
 
$3 = {<log_rec_t> = {next = 0x3087344da938, lsn = 151916320}, start_lsn = 151914684}

Applying the log fails on the very first record, whose length is 1587 bytes. The LSN difference is 49 bytes more, but that could be explained by the terminating NUL byte and 3*(12+4) bytes of framing for three 512-byte log blocks. So, it looks like there is only 1 record in that mini-transaction.

In the rr replay trace of the killed server, we should be able to find when this log record was written and what happened to the undo log page between that time and the server kill. It is somewhere between these times:

1: log_sys.lsn._M_i = 143624406
 
(rr) when
 
Current event: 886248
 
(rr) c
 
Continuing.
 
…
 
Thread 22 stopped.
 
[Switching to Thread 3166493.3176833]
 
0x0000773201a12288 in do_breakpoint (value=182)
 
    at /home/roc/rr/rr/src/preload/syscallbuf.c:1085
 
1085	/home/roc/rr/rr/src/preload/syscallbuf.c: No such file or directory.
 
1: log_sys.lsn._M_i = 154782176
 
(rr) when
 
Current event: 940406

Comment by Marko Mäkelä [ 2023-02-15 ]

The problematic log record was written in

10.5 690fcfbd2954f9470047ce754c2a5c2fdfd15cf3

 
1: log_sys.lsn._M_i = 151916239
 
Current event: 931133
 
(rr) bt
 
…
 
#7  0x0000560c1e02c787 in mtr_t::commit (this=0x759b4e933010)
 
    at /data/Server/10.5/storage/innobase/mtr/mtr0mtr.cc:442
 
#8  0x0000560c1e1f53ea in trx_undo_report_row_operation (thr=0x62300014bf38, 
    index=0x61600005a9f0, clust_entry=0x0, update=0x62300014b9c8, cmpl_info=0, 
    rec=0x49d07cfdccb9 "\200", offsets=0x759b4e933a80, roll_ptr=0x759b4e9336a0)
 
    at /data/Server/10.5/storage/innobase/trx/trx0rec.cc:1900

At this point of time, the undo page pretty much exists in the buffer pool:

(rr) p *(mtr_memo_slot_t*)m_memo.m_first_block.m_data@2
 
$3 = {{object = 0x49d07c8f0800, type = MTR_MEMO_PAGE_X_MODIFY}, {
 
    object = 0x7732010f2410 <__asan_unpoison_memory_region+496>, type = 0}}
 
(rr) set $b=(buf_block_t*)0x49d07c8f0800
 
(rr) p/x $b.page.id_
 
$4 = {m_id = 0x200000186}
 
(rr) p/x *$b.frame@srv_page_size
 
$5 = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0x86, 0xff, 0xff, 0xff, 0xff, 0xff, 
  0xff, 0xff, 0xff, 0x0, 0x0, 0x0, 0x0, 0x9, 0xe, 0x7, 0x83, 0x0, 0x2, 
  0x0 <repeats 11 times>, 0x2, 0x0, 0x0, 0x0, 0x38, 0x1f, 0x28, 0x0, 0x0, 0x1, 
  0x85, 0x0, 0x2c, 0xff, 0xff, 0xff, 0xff, 0x0, 0x0, 0x6, 0x68, 0xc, 0x81, 
  0x3b, 0x14, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xe0, 0x80, 0x0, 0x0, 0x0, 0x0, 
  0x0, 0x0, 0x4, 0x80, 0x0, 0x2, 0x73, 0x1, 0x5, 0x80, 0xff, 
  0xb <repeats 150 times>, 0x20 <repeats 105 times>, 0x5, 0x12, 0x3, 0x81, 
  0xfe, 0x0, 0x68, 0x0, 0x65, 0x0, 0x79, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 
  0x20, 0x0, 0x20, 0x0, 0x20, 0x0, 0x20, 0x0...}

We will need to find out what happened to it after this point of time.

Comment by Marko Mäkelä [ 2023-02-15 ]

The page was marked clean during undo tablespace truncation:

Thread 28 hit Hardware watchpoint 4: -location $b.page.oldest_modification_.m._M_i
 
 
 
Old value = 151901595
 
New value = 1
 
0x0000560c1dee14b6 in std::__atomic_base<unsigned long>::store (
 
    __m=std::memory_order_release, __i=1, this=0x49d07c8f0810)
 
    at /usr/include/c++/9/bits/atomic_base.h:397
 
397		__atomic_store_n(&_M_i, __i, int(__m));
 
1: log_sys.lsn._M_i = 158029383
 
(rr) bt
 
#0  0x0000560c1dee14b6 in std::__atomic_base<unsigned long>::store (
 
    __m=std::memory_order_release, __i=1, this=0x49d07c8f0810)
 
    at /usr/include/c++/9/bits/atomic_base.h:397
 
#1  Atomic_relaxed<unsigned long>::store (this=0x49d07c8f0810, i=1, 
    o=std::memory_order_release)
 
    at /data/Server/10.5/include/my_atomic_wrapper.h:47
 
#2  0x0000560c1e02f85c in buf_page_t::clear_oldest_modification (
 
    this=0x49d07c8f0800, temporary=false)
 
    at /data/Server/10.5/storage/innobase/include/buf0buf.h:2250
 
#3  0x0000560c1e1d1d87 in trx_purge_truncate_history ()
 
    at /data/Server/10.5/storage/innobase/trx/trx0purge.cc:704
 
…
 
(rr) finish
 
Run till exit from #3  0x0000560c1e1d1d87 in trx_purge_truncate_history ()
 
    at /data/Server/10.5/storage/innobase/trx/trx0purge.cc:704
 
 
 
Thread 28 hit Breakpoint 5, mtr_t::commit_shrink (this=0x34b27c4d4d00, 
    space=...) at /data/Server/10.5/storage/innobase/mtr/mtr0mtr.cc:564
 
564	{
 
1: log_sys.lsn._M_i = 158029383
 
(rr) finish
 
Run till exit from #0  mtr_t::commit_shrink (this=0x34b27c4d4d00, space=...)
 
    at /data/Server/10.5/storage/innobase/mtr/mtr0mtr.cc:564
 
trx_purge_truncate_history ()
 
    at /data/Server/10.5/storage/innobase/trx/trx0purge.cc:797
 
797	    export_vars.innodb_undo_truncations++;
 
1: log_sys.lsn._M_i = 158035982

The undo truncation mini-transaction ending at LSN=158035982 should have been parsed by recovery, because at the end of that trace we have log_sys.lsn._M_i=160484452 and the recovery started with the following:

2023-02-15 12:35:46 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=151914371,159538155

It looks like we could be dealing with a recovery-side bug similar to MDEV-30479. I will check the recovery trace in more detail.

Comment by Marko Mäkelä [ 2023-02-15 ]

Surprisingly, a copy of the data directory data.tar.xz recovers just fine on my 10.6 based server source code:

tar xJf data.tar.xz -C /dev/shm/
 
sql/mariadbd --innodb-page-size=8k --datadir /dev/shm/data

It could be that the recovery problem requires some luck with the timing, or that this problem only affects 10.5 and not 10.6, which uses a compatible ib_logfile0 format. I will check the rr replay trace of the failed recovery in more detail.

Comment by Marko Mäkelä [ 2023-02-15 ]

There is a clue in the log of the rr replay run:

2023-02-15 12:35:47 0 [Note] InnoDB: Starting a batch to recover 396 pages from redo log.
 
2023-02-15 12:35:47 0 [ERROR] InnoDB: Not applying UNDO_APPEND due to corruption on [page id: space=2, page number=390]

This could be a bug in multi-batch recovery of innodb_undo_log_truncate=ON. I can in fact reproduce this on my 10.6 branch when using a tiny buffer pool to force the recovery to be in multiple batches:

sql/mariadbd --innodb-buffer-pool-size=5m --innodb-page-size=8k --datadir /dev/shm/data


2023-02-15 17:26:04 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=151914371,159538155
 
2023-02-15 17:26:04 0 [Note] InnoDB: Starting a batch to recover 264 pages from redo log.
 
2023-02-15 17:26:04 0 [ERROR] InnoDB: Unable to apply log to corrupted page [page id: space=2, page number=390]; set innodb_force_recovery to ignore
 
2023-02-15 17:26:04 0 [Note] InnoDB: Set innodb_force_recovery=1 to ignore corrupted pages.
 
2023-02-15 17:26:04 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1453] with error Generic error
 
2023-02-15 17:26:04 0 [Note] InnoDB: Starting shutdown...
 
2023-02-15 17:26:04 0 [ERROR] [FATAL] InnoDB: Trying to write 8192 bytes at 5242880 outside the bounds of the file: .//undo002

Comment by Marko Mäkelä [ 2023-02-15 ]

I am sorry, this is a regression due to an incorrect optimization of memory usage that I had applied in addition to the fix of MDEV-30479.

If recovery happens in multiple batches, it is not sufficient to discard old redo log records for the truncated tablespace while parsing them. We must discard them on every log-applying batch.

Reverting that optimization fixes the recovery. What we can optimize is that we can remove any old log records already in recv_sys_t::parse(), to increase the chances that fewer recovery batches may be possible.

Comment by Marko Mäkelä [ 2023-02-16 ]

In multi-batch recovery, recv_sys_t::parse() may add obsolete records to recv_sys.pages, which are to be removed in recv_sys_t::apply(). I decided to not optimize that for now, because such an optimization would introduce a data structure lookup each time before a log record is to be buffered. For that, we would need to look up the array truncated_undo_spaces, preceded by 2 comparisons for checking the array bounds. Undo log truncation should be relatively rare.

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