Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
N/A
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>
|
|
Attachments
Issue Links
- is caused by
-
-
- Closed
-
Activity
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.
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.
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.
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
|
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.
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.
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:310310 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) whenCurrent event: 886248(rr) cContinuing.…Thread 22 stopped.[Switching to Thread 3166493.3176833]0x0000773201a12288 in do_breakpoint (value=182)at /home/roc/rr/rr/src/preload/syscallbuf.c:10851085 /home/roc/rr/rr/src/preload/syscallbuf.c: No such file or directory.1: log_sys.lsn._M_i = 154782176(rr) whenCurrent event: 940406