[MDEV-30100] Assertion `purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()' - Jira

dongjian created issue - 2022-11-26 02:25

dongjian made changes - 2022-11-26 02:25

Field	Original Value	New Value
Description	The process exits during mysqld execution, and an error occurs after restarting. lead to: {code:c++} InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no() InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/ InnoDB: about forcing recovery. 220914 18:23:30 [ERROR] mysqld got signal 6 ;	The process exits during mysqld execution, and an error occurs after restarting. lead to:InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no() InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/ InnoDB: about forcing recovery. 220914 18:23:30 [ERROR] mysqld got signal 6 ; {code:c++}

dongjian made changes - 2022-11-26 02:25

Description

The process exits during mysqld execution, and an error occurs after restarting.

lead to:InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;
{code:c++}

The process exits during mysqld execution, and an error occurs after restarting.

lead to:
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;
{code:c++}

dongjian made changes - 2022-11-26 02:25

Description

The process exits during mysqld execution, and an error occurs after restarting.

lead to:
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;
{code:c++}

The process exits during mysqld execution, and an error occurs after restarting.

lead to:
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;

dongjian made changes - 2022-11-26 02:25

Description

The process exits during mysqld execution, and an error occurs after restarting.

lead to:
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;

The process exits during mysqld execution, and an error occurs after restarting.

lead to: assertion
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;

dongjian made changes - 2022-11-26 02:26

Description

The process exits during mysqld execution, and an error occurs after restarting.

lead to: assertion
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;

The process exits during mysqld execution, and an error occurs after restarting.

lead to:

{code:c++}
InnoDB: Failing assertion: purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
220914 18:23:30 [ERROR] mysqld got signal 6 ;
{code}

Daniel Black made changes - 2022-12-18 22:09

Link

This issue duplicates ~~MDEV-30261~~ [ ~~MDEV-30261~~ ]

Daniel Black added a comment - 2022-12-18 22:13

dongjian do you know what SQL was being executed at the time of this fault?

Daniel Black added a comment - 2022-12-18 22:13 dongjian do you know what SQL was being executed at the time of this fault?

Marko Mäkelä added a comment - 2022-12-19 08:00

What is the history of this database? With which version of MySQL or MariaDB was it originally created, and which versions of MariaDB were used for upgrading it to 10.3 or later? This bug might have been fixed in ~~MDEV-27800~~.

Marko Mäkelä added a comment - 2022-12-19 08:00 What is the history of this database? With which version of MySQL or MariaDB was it originally created, and which versions of MariaDB were used for upgrading it to 10.3 or later? This bug might have been fixed in MDEV-27800 .

dongjian added a comment - 2022-12-19 13:13

Thank you. I just kill the process during statement execution, then the service cannot start. I'm not sure which statement executed when i kill the process.

dongjian added a comment - 2022-12-19 13:13 Thank you. I just kill the process during statement execution, then the service cannot start. I'm not sure which statement executed when i kill the process.

Matthias Leich added a comment - 2023-07-28 09:14 - edited

origin/11.2, 11.2 e81fa345020ec6a067583db6a7019d6404b26f93 2023-07-26T15:49:24+03:00 + some patch

Scenario:

1. mariabackup --backup to location A

2. mariabackup --prepare on location A

3. Attempt to start a DB server on location A

[rr 3350991 70073]2023-07-27 20:31:07 0x7fb7baaf8700[rr 3350991 70076]  InnoDB: Assertion failure in file /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc line 132

[rr 3350991 70078]InnoDB: Failing assertion: purge_sys.tail.trx_no <= last_trx_no

(rr) bt

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#1  0x00007f6702f00859 in __GI_abort () at abort.c:79

#2  0x00005568b74821bf in ut_dbg_assertion_failed (expr=expr@entry=0x5568b7fb26d8 "purge_sys.tail.trx_no <= last_trx_no",

    file=file@entry=0x5568b7fb25c8 "/data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc", line=line@entry=132) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/ut/ut0dbg.cc:60

#3  0x00005568b747eb9c in TrxUndoRsegsIterator::set_next (this=0x5568b8f63900 <purge_sys+256>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:132

#4  trx_purge_choose_next_log () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:964

#5  0x00005568b7b4c5c9 in trx_purge_get_next_rec (heap=0x5568b9d191f0, n_pages_handled=0x7fb7baaf78a8) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1001

#6  trx_purge_fetch_next_rec (heap=0x5568b9d191f0, n_pages_handled=0x7fb7baaf78a8, roll_ptr=<synthetic pointer>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1104

#7  trx_purge_attach_undo_recs (n_purge_threads=1) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1174

#8  0x00005568b74d32b3 in trx_purge (n_tasks=1, history_size=history_size@entry=3041) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1278

#9  0x00005568b7b45a3f in purge_coordinator_state::do_purge (this=0x5568b8f629a0 <purge_state>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/srv/srv0srv.cc:1479

#10 purge_coordinator_callback () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/srv/srv0srv.cc:1639

#11 0x00005568b7c1de11 in tpool::task_group::execute (this=0x5568b8f62820 <purge_coordinator_task_group>, t=0x5568b8f62780 <purge_coordinator_task>) at /data/Server/11.2-with_MDEV-31354patch/tpool/task_group.cc:70

#12 0x00005568b7c1bce7 in tpool::thread_pool_generic::worker_main (this=0x5568b9c4a090, thread_var=0x5568b9c4a3c0) at /data/Server/11.2-with_MDEV-31354patch/tpool/tpool_generic.cc:580

#13 0x00007fb7bb456de4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6

#14 0x000062b8216cb609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#15 0x00007f6702ffd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

pluto:/data/results/1690469510/TBR-2016-MDEV-30100$ _RR_TRACE_DIR=./1_clone/rr/ rr replay --mark-stdio

RQG

====

# git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG

# GIT_SHOW: HEAD -> master 35f638e7889c9ac71b0ec7c746dbd4532301d6af 2023-07-25T21:28:15+02:00

# rqg.pl  : Version 4.3.0 (2023-06)

# $RQG_HOME/rqg.pl \

# --grammar=conf/mariadb/table_stress_innodb_dml.yy \

# --gendata=conf/mariadb/table_stress.zz \

# --gendata_sql=conf/mariadb/table_stress.sql \

# --reporters=Mariabackup_linux \

# --mysqld=--loose-innodb-log-file-size=200M \

# --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 \

# --no_mask \

# --queries=10000000 \

# --seed=random \

# --reporters=None \

# --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=240 \

# --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 \

# --mysqld=--loose-innodb_compression_level=1 \

# --duration=300 \

# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

# --mysqld=--lock-wait-timeout=15 \

# --mysqld=--innodb-lock-wait-timeout=10 \

# --mysqld=--innodb_file_per_table=1 \

# --mysqld=--loose-innodb_read_only_compressed=OFF \

# --mysqld=--loose-innodb-sync-debug \

# --mysqld=--innodb_stats_persistent=on \

# --mysqld=--innodb_adaptive_hash_index=off \

# --mysqld=--innodb_random_read_ahead=OFF \

# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \

# --mysqld=--loose-max-statement-time=30 \

# --threads=33 \

# --mysqld=--innodb-use-native-aio=0 \

# --mysqld=--loose-gdb \

# --mysqld=--loose-debug-gdb \

# --rr=Extended \

# --rr_options=--chaos --wait \

# --mysqld=--innodb_undo_log_truncate=OFF \

# --mysqld=--loose_innodb_change_buffering=purges \

# --mysqld=--innodb_undo_tablespaces=3 \

# --mysqld=--innodb_rollback_on_timeout=ON \

# --mysqld=--innodb_page_size=8K \

# --mysqld=--innodb-buffer-pool-size=8M \

#  <local settings>

Matthias Leich added a comment - 2023-07-28 09:14 - edited origin/11.2, 11.2 e81fa345020ec6a067583db6a7019d6404b26f93 2023-07-26T15:49:24+03:00 + some patch Scenario: 1. mariabackup --backup to location A 2. mariabackup --prepare on location A 3. Attempt to start a DB server on location A [rr 3350991 70073]2023-07-27 20:31:07 0x7fb7baaf8700[rr 3350991 70076] InnoDB: Assertion failure in file /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc line 132 [rr 3350991 70078]InnoDB: Failing assertion: purge_sys.tail.trx_no <= last_trx_no (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f6702f00859 in __GI_abort () at abort.c:79 #2 0x00005568b74821bf in ut_dbg_assertion_failed (expr=expr@entry=0x5568b7fb26d8 "purge_sys.tail.trx_no <= last_trx_no", file=file@entry=0x5568b7fb25c8 "/data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc", line=line@entry=132) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/ut/ut0dbg.cc:60 #3 0x00005568b747eb9c in TrxUndoRsegsIterator::set_next (this=0x5568b8f63900 <purge_sys+256>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:132 #4 trx_purge_choose_next_log () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:964 #5 0x00005568b7b4c5c9 in trx_purge_get_next_rec (heap=0x5568b9d191f0, n_pages_handled=0x7fb7baaf78a8) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1001 #6 trx_purge_fetch_next_rec (heap=0x5568b9d191f0, n_pages_handled=0x7fb7baaf78a8, roll_ptr=<synthetic pointer>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1104 #7 trx_purge_attach_undo_recs (n_purge_threads=1) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1174 #8 0x00005568b74d32b3 in trx_purge (n_tasks=1, history_size=history_size@entry=3041) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:1278 #9 0x00005568b7b45a3f in purge_coordinator_state::do_purge (this=0x5568b8f629a0 <purge_state>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/srv/srv0srv.cc:1479 #10 purge_coordinator_callback () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/srv/srv0srv.cc:1639 #11 0x00005568b7c1de11 in tpool::task_group::execute (this=0x5568b8f62820 <purge_coordinator_task_group>, t=0x5568b8f62780 <purge_coordinator_task>) at /data/Server/11.2-with_MDEV-31354patch/tpool/task_group.cc:70 #12 0x00005568b7c1bce7 in tpool::thread_pool_generic::worker_main (this=0x5568b9c4a090, thread_var=0x5568b9c4a3c0) at /data/Server/11.2-with_MDEV-31354patch/tpool/tpool_generic.cc:580 #13 0x00007fb7bb456de4 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6 #14 0x000062b8216cb609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #15 0x00007f6702ffd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (rr) pluto:/data/results/1690469510/TBR-2016-MDEV-30100$ _RR_TRACE_DIR=./1_clone/rr/ rr replay --mark-stdio RQG ==== # git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG # # GIT_SHOW: HEAD -> master 35f638e7889c9ac71b0ec7c746dbd4532301d6af 2023-07-25T21:28:15+02:00 # rqg.pl : Version 4.3.0 (2023-06) # # $RQG_HOME/rqg.pl \ # --grammar=conf/mariadb/table_stress_innodb_dml.yy \ # --gendata=conf/mariadb/table_stress.zz \ # --gendata_sql=conf/mariadb/table_stress.sql \ # --reporters=Mariabackup_linux \ # --mysqld=--loose-innodb-log-file-size=200M \ # --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 \ # --no_mask \ # --queries=10000000 \ # --seed=random \ # --reporters=None \ # --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=240 \ # --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 \ # --mysqld=--loose-innodb_compression_level=1 \ # --duration=300 \ # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ # --mysqld=--lock-wait-timeout=15 \ # --mysqld=--innodb-lock-wait-timeout=10 \ # --mysqld=--innodb_file_per_table=1 \ # --mysqld=--loose-innodb_read_only_compressed=OFF \ # --mysqld=--loose-innodb-sync-debug \ # --mysqld=--innodb_stats_persistent=on \ # --mysqld=--innodb_adaptive_hash_index=off \ # --mysqld=--innodb_random_read_ahead=OFF \ # --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \ # --mysqld=--loose-max-statement-time=30 \ # --threads=33 \ # --mysqld=--innodb-use-native-aio=0 \ # --mysqld=--loose-gdb \ # --mysqld=--loose-debug-gdb \ # --rr=Extended \ # --rr_options=--chaos --wait \ # --mysqld=--innodb_undo_log_truncate=OFF \ # --mysqld=--loose_innodb_change_buffering=purges \ # --mysqld=--innodb_undo_tablespaces=3 \ # --mysqld=--innodb_rollback_on_timeout=ON \ # --mysqld=--innodb_page_size=8K \ # --mysqld=--innodb-buffer-pool-size=8M \ # <local settings>

Matthias Leich made changes - 2023-07-28 09:16

Fix Version/s		11.2 [ 28603 ]
Affects Version/s		11.2.0 [ 29033 ]

Marko Mäkelä made changes - 2023-07-28 09:22

Assignee

Marko Mäkelä [ marko ]

Marko Mäkelä made changes - 2023-07-28 09:23

Labels

rr-profile

Marko Mäkelä made changes - 2023-07-28 14:35

Priority

Major [ 3 ]

Critical [ 2 ]

Marko Mäkelä made changes - 2023-08-03 08:30

Attachment

data.tar.xz [ 71323 ]

Marko Mäkelä added a comment - 2023-08-03 08:41 - edited

I am analyzing the rr replay traces. mleich provided traces of the server that was backed up, the backup run, and the crashing server that was started up on the backed up data:

132		ut_a(purge_sys.tail.trx_no <= last_trx_no);

(rr) p purge_sys.tail

$1 = {trx_no = 16924, undo_no = 0}

(rr) p purge_sys.head

$2 = {trx_no = 16923, undo_no = 0}

The purge_sys.tail.trx_no was last read from purge_sys.rseg->last_commit_and_offset, which in turn was read from the undo log page 3:0x6f, at byte offset 0x10fe+8
(prev_log_addr.boffset + TRX_UNDO_TRX_NO). Those bytes were last modified by the rollback of an incomplete transaction:

#0  mtr_t::write<8u, (mtr_t::write_type)1, Atomic_counter<unsigned long> > (val=..., ptr=0x7fb7bae67106, block=..., this=0xb4649e9a5b0)

    at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/include/mtr0log.h:213

#1  trx_purge_add_undo_to_history (trx=trx@entry=0x80530dc8c80, undo=@0x80530dc95c0: 0x0, mtr=mtr@entry=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:360

#2  0x00005568b7b625a2 in trx_write_serialisation_history (trx=<optimized out>, mtr=<optimized out>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1057

#3  0x00005568b74d45d4 in trx_t::commit_low (this=0x80530dc8c80, mtr=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1418

#4  0x00005568b7b62ea2 in trx_t::commit_persist (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1463

#5  0x00005568b7b62f0d in trx_t::commit (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1472

#6  0x00005568b7480180 in trx_t::rollback_finish (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:65

#7  trx_rollback_active (trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:617

#8  0x00005568b7b57258 in trx_rollback_recovered (all=true) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:750

#9  0x00005568b74805a4 in trx_rollback_all_recovered () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:796

The value that was written (one less than the purge_sys.tail.trx_no at the time of the crash) had been assigned a little earlier, simply from trx_sys.m_max_trx_id:

#1  Atomic_counter<unsigned long>::operator= (val=16923, this=0x5568b9d36300) at /data/Server/11.2-with_MDEV-31354patch/include/my_counter.h:47

#2  trx_sys_t::assign_new_trx_no (this=<optimized out>, trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/include/trx0sys.h:994

#3  trx_serialise (trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:989

#4  trx_write_serialisation_history (trx=0x80530dc8c80, mtr=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1055

By design, on transaction commit, InnoDB will assign a transaction "end" identifier from the same sequence as the "start" identifier (DB_TRX_ID). The "end" identifier will only be written to an undo log header. A transaction rollback will end in a commit of an empty transaction log. I do not immediately see a reason why we should assign an "end" identifier to an empty transaction; all traces of the transaction other than the allocation of a "start" identifier should simply disappear from the system. At the start of the log output we see this:

2023-07-27 20:30:53 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 35 row operations to undo

2023-07-27 20:30:53 0 [Note] InnoDB: Trx id counter is 16921

Due to how the code currently works, I would expect the identifier to grow from 16921 to 16921+4 = 16955. The assertion failed already at 16923 or 16924.

The attached file data.tar.xz is a copy of /data/results/1690469510/TBR-2016-MDEV-30100/1_clone/fbackup/data. If I start a server on that (I suppose that mleich invoked mariadb-backup --prepare first, before starting the server on the logically empty log), I can reproduce this failure but also something interesting:

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

11.2 e81fa345020ec6a067583db6a7019d6404b26f93
…
2023-08-03 11:35:01 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2023-08-03 11:35:01 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=46554143
2023-08-03 11:35:01 0 [Note] InnoDB: End of log at LSN=51638168
2023-08-03 11:35:01 0 [ERROR] InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size; last checkpoint LSN=46554143, current LSN=51638295. Shutdown is in progress.
2023-08-03 11:35:01 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 35 row operations to undo
2023-08-03 11:35:01 0 [Note] InnoDB: Trx id counter is 16921
2023-08-03 11:35:01 0 [Note] InnoDB: To recover: 716 pages
2023-08-03 11:35:01 0 [Note] InnoDB: Resizing redo log from 4.860MiB to 5.000MiB; LSN=51638295
2023-08-03 11:35:01 0 [Note] InnoDB: Crash recovery was broken between LSN=51638295 and checkpoint LSN=51638295.
2023-08-03 11:35:01 0 [Warning] InnoDB: Cannot change innodb_undo_tablespaces=0 because previous shutdown was not with innodb_fast_shutdown=0
2023-08-03 11:35:01 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
2023-08-03 11:35:01 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
2023-08-03 11:35:01 0 [Note] InnoDB: Setting O_DIRECT on file ./ibtmp1 failed
2023-08-03 11:35:01 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16865
2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16891
2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16859
2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16195
2023-08-03 11:35:01 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2023-08-03 11:35:01 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-08-03 11:35:01 0 [Note] InnoDB: log sequence number 51638168 (memory-mapped); transaction id 16926
2023-08-03 11:35:01 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/data/ib_buffer_pool
2023-08-03 11:35:01 0 [Note] InnoDB: Cannot open '/dev/shm/data/ib_buffer_pool' for reading: No such file or directory
2023-08-03 11:35:01 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-08-03 11:35:01 0 [Note] Plugin 'wsrep-provider' is disabled.
2023-08-03 11:35:01 0 [Warning] 11/sql/mariadbd: unknown option '--loose-enable-named-pipe'
2023-08-03 11:35:01 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-08-03 11:35:01 0 [Note] Server socket created on IP: '::'.
2023-08-03 11:35:01 0 [Note] mariadbd: Event Scheduler: Loaded 0 events
2023-08-03 11:35:01 0 [Note] 11/sql/mariadbd: ready for connections.
Version: '11.2.0-MariaDB-debug' socket: '/dev/shm/mariadb.sock' port: 3306 Source distribution
mariadbd: /mariadb/11/storage/innobase/trx/trx0purge.cc:89: bool TrxUndoRsegsIterator::set_next(): Assertion `purge_sys.purge_queue.empty() \|\| purge_sys.purge_queue.top() != m_rsegs' failed.
230803 11:35:04 [ERROR] mysqld got signal 6 ;

The database may be corrupted because some log was missed during the backup.

I will check further files if mariadb-backup failed to return any error code for this. Also, I will try to see if simplifying the rollback would prevent this crash. Last, I will try to determine what was in the missed section of the redo log; I can do that because we also have an rr replay trace of the server that had been backed up.

The message "Shutdown is in progress" seems to be misleading too.

Marko Mäkelä added a comment - 2023-08-03 08:41 - edited I am analyzing the rr replay traces. mleich provided traces of the server that was backed up, the backup run, and the crashing server that was started up on the backed up data: 132 ut_a(purge_sys.tail.trx_no <= last_trx_no); (rr) p purge_sys.tail $1 = {trx_no = 16924, undo_no = 0} (rr) p purge_sys.head $2 = {trx_no = 16923, undo_no = 0} The purge_sys.tail.trx_no was last read from purge_sys.rseg->last_commit_and_offset , which in turn was read from the undo log page 3:0x6f, at byte offset 0x10fe+8 ( prev_log_addr.boffset + TRX_UNDO_TRX_NO ). Those bytes were last modified by the rollback of an incomplete transaction: #0 mtr_t::write<8u, (mtr_t::write_type)1, Atomic_counter<unsigned long> > (val=..., ptr=0x7fb7bae67106, block=..., this=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/include/mtr0log.h:213 #1 trx_purge_add_undo_to_history (trx=trx@entry=0x80530dc8c80, undo=@0x80530dc95c0: 0x0, mtr=mtr@entry=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0purge.cc:360 #2 0x00005568b7b625a2 in trx_write_serialisation_history (trx=<optimized out>, mtr=<optimized out>) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1057 #3 0x00005568b74d45d4 in trx_t::commit_low (this=0x80530dc8c80, mtr=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1418 #4 0x00005568b7b62ea2 in trx_t::commit_persist (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1463 #5 0x00005568b7b62f0d in trx_t::commit (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1472 #6 0x00005568b7480180 in trx_t::rollback_finish (this=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:65 #7 trx_rollback_active (trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:617 #8 0x00005568b7b57258 in trx_rollback_recovered (all=true) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:750 #9 0x00005568b74805a4 in trx_rollback_all_recovered () at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0roll.cc:796 The value that was written (one less than the purge_sys.tail.trx_no at the time of the crash) had been assigned a little earlier, simply from trx_sys.m_max_trx_id : #1 Atomic_counter<unsigned long>::operator= (val=16923, this=0x5568b9d36300) at /data/Server/11.2-with_MDEV-31354patch/include/my_counter.h:47 #2 trx_sys_t::assign_new_trx_no (this=<optimized out>, trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/include/trx0sys.h:994 #3 trx_serialise (trx=0x80530dc8c80) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:989 #4 trx_write_serialisation_history (trx=0x80530dc8c80, mtr=0xb4649e9a5b0) at /data/Server/11.2-with_MDEV-31354patch/storage/innobase/trx/trx0trx.cc:1055 By design, on transaction commit, InnoDB will assign a transaction "end" identifier from the same sequence as the "start" identifier ( DB_TRX_ID ). The "end" identifier will only be written to an undo log header. A transaction rollback will end in a commit of an empty transaction log. I do not immediately see a reason why we should assign an "end" identifier to an empty transaction; all traces of the transaction other than the allocation of a "start" identifier should simply disappear from the system. At the start of the log output we see this: 2023-07-27 20:30:53 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 35 row operations to undo 2023-07-27 20:30:53 0 [Note] InnoDB: Trx id counter is 16921 Due to how the code currently works, I would expect the identifier to grow from 16921 to 16921+4 = 16955. The assertion failed already at 16923 or 16924. The attached file data.tar.xz is a copy of /data/results/1690469510/TBR-2016- MDEV-30100 /1_clone/fbackup/data . If I start a server on that (I suppose that mleich invoked mariadb-backup --prepare first, before starting the server on the logically empty log), I can reproduce this failure but also something interesting: sql/mariadbd --datadir /dev/shm/data --innodb-log-file-size=5m --innodb-page-size=8k 11.2 e81fa345020ec6a067583db6a7019d6404b26f93 … 2023-08-03 11:35:01 0 [Note] InnoDB: Buffered log writes (block size=512 bytes) 2023-08-03 11:35:01 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=46554143 2023-08-03 11:35:01 0 [Note] InnoDB: End of log at LSN=51638168 2023-08-03 11:35:01 0 [ERROR] InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size; last checkpoint LSN=46554143, current LSN=51638295. Shutdown is in progress. 2023-08-03 11:35:01 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 35 row operations to undo 2023-08-03 11:35:01 0 [Note] InnoDB: Trx id counter is 16921 2023-08-03 11:35:01 0 [Note] InnoDB: To recover: 716 pages 2023-08-03 11:35:01 0 [Note] InnoDB: Resizing redo log from 4.860MiB to 5.000MiB; LSN=51638295 2023-08-03 11:35:01 0 [Note] InnoDB: Crash recovery was broken between LSN=51638295 and checkpoint LSN=51638295. 2023-08-03 11:35:01 0 [Warning] InnoDB: Cannot change innodb_undo_tablespaces=0 because previous shutdown was not with innodb_fast_shutdown=0 2023-08-03 11:35:01 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active. 2023-08-03 11:35:01 0 [Note] InnoDB: Starting in background the rollback of recovered transactions 2023-08-03 11:35:01 0 [Note] InnoDB: Setting O_DIRECT on file ./ibtmp1 failed 2023-08-03 11:35:01 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ... 2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16865 2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16891 2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16859 2023-08-03 11:35:01 0 [Note] InnoDB: Rolled back recovered transaction 16195 2023-08-03 11:35:01 0 [Note] InnoDB: Rollback of non-prepared transactions completed 2023-08-03 11:35:01 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2023-08-03 11:35:01 0 [Note] InnoDB: log sequence number 51638168 (memory-mapped); transaction id 16926 2023-08-03 11:35:01 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/data/ib_buffer_pool 2023-08-03 11:35:01 0 [Note] InnoDB: Cannot open '/dev/shm/data/ib_buffer_pool' for reading: No such file or directory 2023-08-03 11:35:01 0 [Note] Plugin 'FEEDBACK' is disabled. 2023-08-03 11:35:01 0 [Note] Plugin 'wsrep-provider' is disabled. 2023-08-03 11:35:01 0 [Warning] 11/sql/mariadbd: unknown option '--loose-enable-named-pipe' 2023-08-03 11:35:01 0 [Note] Server socket created on IP: '0.0.0.0'. 2023-08-03 11:35:01 0 [Note] Server socket created on IP: '::'. 2023-08-03 11:35:01 0 [Note] mariadbd: Event Scheduler: Loaded 0 events 2023-08-03 11:35:01 0 [Note] 11/sql/mariadbd: ready for connections. Version: '11.2.0-MariaDB-debug' socket: '/dev/shm/mariadb.sock' port: 3306 Source distribution mariadbd: /mariadb/11/storage/innobase/trx/trx0purge.cc:89: bool TrxUndoRsegsIterator::set_next(): Assertion `purge_sys.purge_queue.empty() || purge_sys.purge_queue.top() != m_rsegs' failed. 230803 11:35:04 [ERROR] mysqld got signal 6 ; The database may be corrupted because some log was missed during the backup. I will check further files if mariadb-backup failed to return any error code for this. Also, I will try to see if simplifying the rollback would prevent this crash. Last, I will try to determine what was in the missed section of the redo log; I can do that because we also have an rr replay trace of the server that had been backed up. The message "Shutdown is in progress" seems to be misleading too.

Marko Mäkelä added a comment - 2023-08-03 09:03

The mariadb-backup --prepare had not reported any error:

ssh pluto

rr replay /data/results/1690469510/TBR-2016-MDEV-30100/1_clone/rr/mariadb-backup-0/

2023-07-27 20:30:47 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF

2023-07-27 20:30:47 0 [Note] InnoDB: Initializing buffer pool, total size = 100.000MiB, chunk size = 100.000MiB

2023-07-27 20:30:47 0 [Note] InnoDB: Completed initialization of buffer pool

2023-07-27 20:30:47 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)

2023-07-27 20:30:47 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=46554143

2023-07-27 20:30:48 0 [Note] InnoDB: End of log at LSN=51638168

2023-07-27 20:30:48 0 [Note] InnoDB: To recover: 859 pages

[00] 2023-07-27 20:30:51 Last binlog file , position 0

[00] 2023-07-27 20:30:51 completed OK!

Marko Mäkelä added a comment - 2023-08-03 09:03 The mariadb-backup --prepare had not reported any error: ssh pluto rr replay /data/results/1690469510/TBR-2016-MDEV-30100/1_clone/rr/mariadb-backup-0/ 2023-07-27 20:30:47 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF 2023-07-27 20:30:47 0 [Note] InnoDB: Initializing buffer pool, total size = 100.000MiB, chunk size = 100.000MiB 2023-07-27 20:30:47 0 [Note] InnoDB: Completed initialization of buffer pool 2023-07-27 20:30:47 0 [Note] InnoDB: Buffered log writes (block size=512 bytes) 2023-07-27 20:30:47 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=46554143 2023-07-27 20:30:48 0 [Note] InnoDB: End of log at LSN=51638168 2023-07-27 20:30:48 0 [Note] InnoDB: To recover: 859 pages [00] 2023-07-27 20:30:51 Last binlog file , position 0 [00] 2023-07-27 20:30:51 completed OK!

Marko Mäkelä added a comment - 2023-08-03 10:55

The log overwrite warning was issued due to operator error on my part (starting a server on the backup, instead of running mariadb-backup --prepare first), here:

11.2 e81fa345020ec6a067583db6a7019d6404b26f93
#0 sql_print_error (
format=format@entry=0x562d78db8788 "InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size; last checkpoint LSN=%lu, current LSN=%lu%s.") at /mariadb/11/sql/log.cc:9448
#1 0x0000562d79bd881d in log_overwrite_warning (lsn=lsn@entry=51638295)
at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:863
#2 0x0000562d79bd88ca in log_close (lsn=51638295)
at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:957
#3 0x0000562d79bd94fc in mtr_t::finish_write (this=this@entry=0x7fffab04d7b0,
len=len@entry=127) at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:1273
#4 0x0000562d79bda6de in mtr_t::commit_files (this=this@entry=0x7fffab04d7b0,
checkpoint_lsn=checkpoint_lsn@entry=46554143)
at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:754
#5 0x0000562d79ad0341 in fil_names_clear (lsn=46554143)
at /mariadb/11/storage/innobase/fil/fil0fil.cc:3185
#6 0x0000562d79bc6e0c in recv_recovery_from_checkpoint_start ()
at /mariadb/11/storage/innobase/log/log0recv.cc:4566
#7 0x0000562d79ca31b4 in srv_start (create_new_db=<optimized out>)
at /mariadb/11/storage/innobase/srv/srv0start.cc:1513
#8 0x0000562d79a67140 in innodb_init (p=<optimized out>)
at /mariadb/11/storage/innobase/handler/ha_innodb.cc:4171

At this point, we are dealing with a special append-only log file that was produced by mariadb-backup --backup (which would skip the fil_names_clear() call here). We can ignore this.
I can reproduce the crash also after executing the correct steps:

tar xJf data.tar.xz

extra/mariabackup/mariadb-backup --prepare --target-dir "$(pwd)"/data

sql/mariadbd --innodb-page-size=8k --innodb-log-file-size=5m --datadir "$(pwd)"/data

Marko Mäkelä added a comment - 2023-08-03 10:55 The log overwrite warning was issued due to operator error on my part (starting a server on the backup, instead of running mariadb-backup --prepare first), here: 11.2 e81fa345020ec6a067583db6a7019d6404b26f93 #0 sql_print_error ( format=format@entry=0x562d78db8788 "InnoDB: Crash recovery is broken due to insufficient innodb_log_file_size; last checkpoint LSN=%lu, current LSN=%lu%s.") at /mariadb/11/sql/log.cc:9448 #1 0x0000562d79bd881d in log_overwrite_warning (lsn=lsn@entry=51638295) at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:863 #2 0x0000562d79bd88ca in log_close (lsn=51638295) at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:957 #3 0x0000562d79bd94fc in mtr_t::finish_write (this=this@entry=0x7fffab04d7b0, len=len@entry=127) at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:1273 #4 0x0000562d79bda6de in mtr_t::commit_files (this=this@entry=0x7fffab04d7b0, checkpoint_lsn=checkpoint_lsn@entry=46554143) at /mariadb/11/storage/innobase/mtr/mtr0mtr.cc:754 #5 0x0000562d79ad0341 in fil_names_clear (lsn=46554143) at /mariadb/11/storage/innobase/fil/fil0fil.cc:3185 #6 0x0000562d79bc6e0c in recv_recovery_from_checkpoint_start () at /mariadb/11/storage/innobase/log/log0recv.cc:4566 #7 0x0000562d79ca31b4 in srv_start (create_new_db=<optimized out>) at /mariadb/11/storage/innobase/srv/srv0start.cc:1513 #8 0x0000562d79a67140 in innodb_init (p=<optimized out>) at /mariadb/11/storage/innobase/handler/ha_innodb.cc:4171 At this point, we are dealing with a special append-only log file that was produced by mariadb-backup --backup (which would skip the fil_names_clear() call here). We can ignore this. I can reproduce the crash also after executing the correct steps: tar xJf data.tar.xz extra/mariabackup/mariadb-backup --prepare --target-dir "$(pwd)"/data sql/mariadbd --innodb-page-size=8k --innodb-log-file-size=5m --datadir "$(pwd)"/data

Marko Mäkelä added a comment - 2023-08-03 13:54

To fix this, we need a special case in trx_write_serialisation_history() for empty undo logs:

Do not invoke trx_sys.assign_new_trx_no(trx); or touch purge_sys
Possibly adjust the undo page somehow, and invoke UT_LIST_ADD_FIRST(rseg->undo_cached, undo)

The impact on the undo log pages in the buffer pool must be compatible with how purge would treat such undo log pages. We would basically only avoid accessing purge_sys, and avoid updating any TRX_UNDO_TRX_NO field.

Marko Mäkelä added a comment - 2023-08-03 13:54 To fix this, we need a special case in trx_write_serialisation_history() for empty undo logs: Do not invoke trx_sys.assign_new_trx_no(trx); or touch purge_sys Possibly adjust the undo page somehow, and invoke UT_LIST_ADD_FIRST(rseg->undo_cached, undo) The impact on the undo log pages in the buffer pool must be compatible with how purge would treat such undo log pages. We would basically only avoid accessing purge_sys , and avoid updating any TRX_UNDO_TRX_NO field.

Marko Mäkelä made changes - 2023-08-03 13:54

Status

Open [ 1 ]

In Progress [ 3 ]

Marko Mäkelä made changes - 2023-08-04 08:43

Link

This issue relates to ~~MDEV-29401~~ [ ~~MDEV-29401~~ ]

Marko Mäkelä added a comment - 2023-08-04 14:49

I do not know about the case of dongjian, but I was able to prevent a crash on data.tar.xz by optimizing transaction rollback: simply move the undo page to "cached" and do not touch any of purge_sys. It turns out that we have to increment the trx_sys.m_max_trx_id, because otherwise the test innodb.instant_alter in 10.6 would hang because 1 rolled back transaction would never be purged.

My patch is also simplifying transaction commit. I think that the performance needs to be tested as well.

Marko Mäkelä added a comment - 2023-08-04 14:49 I do not know about the case of dongjian , but I was able to prevent a crash on data.tar.xz by optimizing transaction rollback: simply move the undo page to "cached" and do not touch any of purge_sys . It turns out that we have to increment the trx_sys.m_max_trx_id , because otherwise the test innodb.instant_alter in 10.6 would hang because 1 rolled back transaction would never be purged. My patch is also simplifying transaction commit. I think that the performance needs to be tested as well.

Marko Mäkelä made changes - 2023-08-04 14:49

Assignee	Marko Mäkelä [ marko ]	Vladislav Lesin [ vlad.lesin ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Marko Mäkelä added a comment - 2023-08-08 12:20

mleich produced an rr replay trace where frequent ROLLBACK leads to the space on the undo page being exhausted. When we commit an empty undo page, we must also discard the last undo log header in order to prevent that from happening. I am currently working on that.

Marko Mäkelä added a comment - 2023-08-08 12:20 mleich produced an rr replay trace where frequent ROLLBACK leads to the space on the undo page being exhausted. When we commit an empty undo page, we must also discard the last undo log header in order to prevent that from happening. I am currently working on that.

Marko Mäkelä added a comment - 2023-08-10 13:11

I updated the branch with one where trx_t::commit_empty() will free the last (non-first) record from the undo page.

Marko Mäkelä added a comment - 2023-08-10 13:11 I updated the branch with one where trx_t::commit_empty() will free the last (non-first) record from the undo page .

Marko Mäkelä made changes - 2023-08-10 13:12

Fix Version/s		10.6 [ 24028 ]
Fix Version/s		10.10 [ 27530 ]
Fix Version/s		10.11 [ 27614 ]
Fix Version/s		11.0 [ 28320 ]
Fix Version/s		11.1 [ 28549 ]
Affects Version/s		10.5 [ 23123 ]
Affects Version/s		10.6 [ 24028 ]
Affects Version/s		10.7 [ 24805 ]
Affects Version/s		10.8 [ 26121 ]
Affects Version/s		10.9 [ 26905 ]
Affects Version/s		10.10 [ 27530 ]
Affects Version/s		10.11 [ 27614 ]
Affects Version/s		11.0 [ 28320 ]
Affects Version/s		11.1 [ 28549 ]
Affects Version/s		11.2 [ 28603 ]

Marko Mäkelä added a comment - 2023-08-10 13:35

In case you wonder why the only undo log header in a cached undo log page can’t be removed:

2023-08-10 16:31:47 0 [ERROR] InnoDB: invalid undo header offset 0

2023-08-10 16:31:47 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1484] with error Data structure corruption

Touching this check in trx_undo_mem_create_at_db_start() would constitute a file format change.

Marko Mäkelä added a comment - 2023-08-10 13:35 In case you wonder why the only undo log header in a cached undo log page can’t be removed: 2023-08-10 16:31:47 0 [ERROR] InnoDB: invalid undo header offset 0 2023-08-10 16:31:47 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1484] with error Data structure corruption Touching this check in trx_undo_mem_create_at_db_start() would constitute a file format change.

Matthias Leich added a comment - 2023-08-15 19:14 - edited

Some result of RQg testing on origin/bb-10.6-MDEV-30100 f4c1784c343c1693f545f7cf925b0021499ef301 2023-08-11T11:33:48+03:00

The server is under concurrent DDL/DMl load and some

 SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM n /*!50610 PARTITION (p3) */ WHERE `col_int_nokey` <= 7

 failed: 1696 , errstr: Failed to read from the .par file          RQG reacts with crashing the server.

sdp:/data1/results/1692100908/TBR-2037-partition$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio

Matthias Leich added a comment - 2023-08-15 19:14 - edited Some result of RQg testing on origin/bb-10.6-MDEV-30100 f4c1784c343c1693f545f7cf925b0021499ef301 2023-08-11T11:33:48+03:00 The server is under concurrent DDL/DMl load and some SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM n /*!50610 PARTITION (p3) */ WHERE `col_int_nokey` <= 7 failed: 1696 , errstr: Failed to read from the .par file RQG reacts with crashing the server. sdp:/data1/results/1692100908/TBR-2037-partition$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio

Marko Mäkelä added a comment - 2023-08-16 06:01

mleich, the error that you reproduced looks like MDEV-29566 and should have nothing to do with any recent changes:

bb-10.6-MDEV-30100 f4c1784c343c1693f545f7cf925b0021499ef301
Thread 38 hit Breakpoint 5, ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639
13639 if (err != DB_SUCCESS && skip_wait)
1: table.mdl_name = {m_name = 0x4791580b8950 "test/n#P#p1"}
2: err = DB_LOCK_WAIT_TIMEOUT
(rr) when
Current event: 313814
(rr) backtrace
#0 ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639
#1 0x000055e5e6748790 in ha_partition::del_ren_table (this=0x2c5f60011560, from=0x468107cb79e0 "./test/n", to=0x0) at /data/Server/bb-10.6-MDEV-30100/sql/ha_partition.cc:2509
#2 0x000055e5e6510d55 in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:573
#3 0x000055e5e65161c9 in ha_delete_table (thd=thd@entry=0x2c5f60000fd8, hton=hton@entry=0x55e5e83e67b8, path=path@entry=0x468107cb79e0 "./test/n", db=db@entry=0x468107cb77d0, alias=alias@entry=0x468107cb77e0,
generate_warning=generate_warning@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:3163
#4 0x000055e5e6382fdf in mysql_rm_table_no_locks (thd=0x2c5f60000fd8, tables=<optimized out>, current_db=<optimized out>, ddl_log_state=<optimized out>, if_exists=<optimized out>,
drop_temporary=<optimized out>, drop_view=<optimized out>, drop_sequence=<optimized out>, dont_log_query=<optimized out>, dont_free_locks=<optimized out>)
at /data/Server/bb-10.6-MDEV-30100/sql/sql_table.cc:1466
#5 0x000055e5e6384208 in mysql_rm_table (thd=thd@entry=0x2c5f60000fd8, tables=tables@entry=0x2c5f60010c00, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>,
dont_log_query=dont_log_query@entry=false) at /data/Server/bb-10.6-MDEV-30100/sql/sql_table.cc:1043
#6 0x000055e5e62eeb8f in mysql_execute_command (thd=0x2c5f60000fd8, is_called_from_prepared_stmt=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:4976
#7 0x000055e5e62f2d34 in mysql_parse (thd=0x2c5f60000fd8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:8053
#8 0x000055e5e62f4b72 in dispatch_command (command=COM_QUERY, thd=0x2c5f60000fd8, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>)
at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:1993
#9 0x000055e5e62f5fb1 in do_command (thd=0x2c5f60000fd8, blocking=blocking@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:1409
#10 0x000055e5e63f317f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e5e84cdf48, put_in_cache=put_in_cache@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/sql_connect.cc:1416
#11 0x000055e5e63f347d in handle_one_connection (arg=0x55e5e84cdf48) at /data/Server/bb-10.6-MDEV-30100/sql/sql_connect.cc:1318
#12 0x000053c859795b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#13 0x000053c859826bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
(rr) finish
Run till exit from #0 ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639
2023-08-15 8:11:55 0 [Warning] Aborted connection 35 to db: 'test' user: 'root' host: 'localhost' (KILLED)
2023-08-15 8:11:56 0 [Warning] Aborted connection 20 to db: 'test' user: 'root' host: 'localhost' (KILLED)
2023-08-15 8:11:57 0 [Warning] Aborted connection 21 to db: 'test' user: 'root' host: 'localhost' (KILLED)
0x000055e5e6748790 in ha_partition::del_ren_table (this=0x2c5f60011560, from=0x468107cb79e0 "./test/n", to=0x0) at /data/Server/bb-10.6-MDEV-30100/sql/ha_partition.cc:2511
2511 name_buffer_ptr= strend(name_buffer_ptr) + 1;
Value returned is $8 = 146
(rr) frame 2
#2 0x000055e5e65161c9 in ha_delete_table (thd=thd@entry=0x2c5f60000fd8, hton=hton@entry=0x55e5e83e67b8, path=path@entry=0x468107cb79e0 "./test/n", db=db@entry=0x468107cb77d0, alias=alias@entry=0x468107cb77e0,
generate_warning=generate_warning@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:3163
3163 error= hton->drop_table(hton, path);
(rr) p thd.query_string
$9 = {string = {str = 0x2c5f60010af0 "DROP TABLE IF EXISTS n /* E_R Thread25 QNO 233 CON_ID 39 */", length = 59}, cs = 0x55e5e7252520 <my_charset_latin1>}

Here, DROP TABLE IF EXISTS n failed to drop the partition p1 of table n, but it had already dropped partition p0 in a previously completed DDL transaction. This should confuse the SQL layer as to whether the table exists. The API needs to be fixed so that DDL statements on partitioned tables can be executed in a single transaction.

After this miscarried DDL statement, the first invocation of my_error() with nr=ER_FAILED_READ_FROM_PAR_FILE=1696 will be issued for the following statement:

EXPLAIN SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM n /*!50610 PARTITION (p3) */ WHERE `col_int_nokey` <= 7 /* E_R Thread8 QNO 219 CON_ID 22 */;

Marko Mäkelä added a comment - 2023-08-16 06:01 mleich , the error that you reproduced looks like MDEV-29566 and should have nothing to do with any recent changes: bb-10.6-MDEV-30100 f4c1784c343c1693f545f7cf925b0021499ef301 Thread 38 hit Breakpoint 5, ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639 13639 if (err != DB_SUCCESS && skip_wait) 1: table.mdl_name = {m_name = 0x4791580b8950 "test/n#P#p1"} 2: err = DB_LOCK_WAIT_TIMEOUT (rr) when Current event: 313814 (rr) backtrace #0 ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639 #1 0x000055e5e6748790 in ha_partition::del_ren_table (this=0x2c5f60011560, from=0x468107cb79e0 "./test/n", to=0x0) at /data/Server/bb-10.6-MDEV-30100/sql/ha_partition.cc:2509 #2 0x000055e5e6510d55 in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:573 #3 0x000055e5e65161c9 in ha_delete_table (thd=thd@entry=0x2c5f60000fd8, hton=hton@entry=0x55e5e83e67b8, path=path@entry=0x468107cb79e0 "./test/n", db=db@entry=0x468107cb77d0, alias=alias@entry=0x468107cb77e0, generate_warning=generate_warning@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:3163 #4 0x000055e5e6382fdf in mysql_rm_table_no_locks (thd=0x2c5f60000fd8, tables=<optimized out>, current_db=<optimized out>, ddl_log_state=<optimized out>, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_view=<optimized out>, drop_sequence=<optimized out>, dont_log_query=<optimized out>, dont_free_locks=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_table.cc:1466 #5 0x000055e5e6384208 in mysql_rm_table (thd=thd@entry=0x2c5f60000fd8, tables=tables@entry=0x2c5f60010c00, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>, dont_log_query=dont_log_query@entry=false) at /data/Server/bb-10.6-MDEV-30100/sql/sql_table.cc:1043 #6 0x000055e5e62eeb8f in mysql_execute_command (thd=0x2c5f60000fd8, is_called_from_prepared_stmt=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:4976 #7 0x000055e5e62f2d34 in mysql_parse (thd=0x2c5f60000fd8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:8053 #8 0x000055e5e62f4b72 in dispatch_command (command=COM_QUERY, thd=0x2c5f60000fd8, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:1993 #9 0x000055e5e62f5fb1 in do_command (thd=0x2c5f60000fd8, blocking=blocking@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/sql_parse.cc:1409 #10 0x000055e5e63f317f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e5e84cdf48, put_in_cache=put_in_cache@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/sql_connect.cc:1416 #11 0x000055e5e63f347d in handle_one_connection (arg=0x55e5e84cdf48) at /data/Server/bb-10.6-MDEV-30100/sql/sql_connect.cc:1318 #12 0x000053c859795b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442 #13 0x000053c859826bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100 (rr) finish Run till exit from #0 ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:13639 2023-08-15 8:11:55 0 [Warning] Aborted connection 35 to db: 'test' user: 'root' host: 'localhost' (KILLED) 2023-08-15 8:11:56 0 [Warning] Aborted connection 20 to db: 'test' user: 'root' host: 'localhost' (KILLED) 2023-08-15 8:11:57 0 [Warning] Aborted connection 21 to db: 'test' user: 'root' host: 'localhost' (KILLED) 0x000055e5e6748790 in ha_partition::del_ren_table (this=0x2c5f60011560, from=0x468107cb79e0 "./test/n", to=0x0) at /data/Server/bb-10.6-MDEV-30100/sql/ha_partition.cc:2511 2511 name_buffer_ptr= strend(name_buffer_ptr) + 1; Value returned is $8 = 146 (rr) frame 2 #2 0x000055e5e65161c9 in ha_delete_table (thd=thd@entry=0x2c5f60000fd8, hton=hton@entry=0x55e5e83e67b8, path=path@entry=0x468107cb79e0 "./test/n", db=db@entry=0x468107cb77d0, alias=alias@entry=0x468107cb77e0, generate_warning=generate_warning@entry=true) at /data/Server/bb-10.6-MDEV-30100/sql/handler.cc:3163 3163 error= hton->drop_table(hton, path); (rr) p thd.query_string $9 = {string = {str = 0x2c5f60010af0 "DROP TABLE IF EXISTS n /* E_R Thread25 QNO 233 CON_ID 39 */", length = 59}, cs = 0x55e5e7252520 <my_charset_latin1>} Here, DROP TABLE IF EXISTS n failed to drop the partition p1 of table n , but it had already dropped partition p0 in a previously completed DDL transaction. This should confuse the SQL layer as to whether the table exists. The API needs to be fixed so that DDL statements on partitioned tables can be executed in a single transaction. After this miscarried DDL statement, the first invocation of my_error() with nr=ER_FAILED_READ_FROM_PAR_FILE=1696 will be issued for the following statement: EXPLAIN SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM n /*!50610 PARTITION (p3) */ WHERE `col_int_nokey` <= 7 /* E_R Thread8 QNO 219 CON_ID 22 */ ;

Matthias Leich added a comment - 2023-08-16 13:24

CHECK TABLE t2 EXTENDED  /* E_R Thread2 QNO 21546 CON_ID 267 */ ' passed but has a result set line 'test.t2 check Warning InnoDB: The B-tree of index idx2 is corrupted.

sdp:/data1/results/1692126141/Corrupt$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio

There are masses of failures with the following scheme

1. Server start, create some initial data

2. Have concurrent DDL/DML load, partitioned tables are involved

Variant 2)

    3. The load phase of the test ends and some checking of data follows.

    ALTER TABLE `test` . `t19` FORCE<- failed with 1292 : Incorrect datetime value or similar failures

    Up till now I cannot exclude that such tests play around with the SQL mode and maybe that is the reason for this effect.

    There is also the open MDEV-29566.

Variant 2)

   3. During 2. is ongoing kill the server

   4. Server start with success + is connectable + no error messages in server error log

   3. Check the data and there some Executing OPTIMIZE TABLE `test`.`table0_innodb_key_pk_parts_2_int_autoinc` harvests

    Table does not support optimize, doing recreate + analyze instead  # ok, a property of the storage engine

    'error', 'Invalid default value for \'t\'      #  The data dictionary seems to be rotten.

    RQG reacts with crashing the server.

    sdp:/data1/results/1692126141/TBR-2038$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio

    Given the problems in Variant 1) I am aware that they could be also the reason for the problems here.

But in general it looks like the MDEV-30100 fix makes hitting these problems serious more likely.

Hence I need to run the same tests on some fresh 10.6 for comparison.

Matthias Leich added a comment - 2023-08-16 13:24 CHECK TABLE t2 EXTENDED /* E_R Thread2 QNO 21546 CON_ID 267 */ ' passed but has a result set line 'test.t2 check Warning InnoDB: The B-tree of index idx2 is corrupted. sdp:/data1/results/1692126141/Corrupt$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio There are masses of failures with the following scheme 1. Server start, create some initial data 2. Have concurrent DDL/DML load, partitioned tables are involved Variant 2) 3. The load phase of the test ends and some checking of data follows. ALTER TABLE `test` . `t19` FORCE<- failed with 1292 : Incorrect datetime value or similar failures Up till now I cannot exclude that such tests play around with the SQL mode and maybe that is the reason for this effect. There is also the open MDEV-29566. Variant 2) 3. During 2. is ongoing kill the server 4. Server start with success + is connectable + no error messages in server error log 3. Check the data and there some Executing OPTIMIZE TABLE `test`.`table0_innodb_key_pk_parts_2_int_autoinc` harvests Table does not support optimize, doing recreate + analyze instead # ok, a property of the storage engine 'error', 'Invalid default value for \'t\' # The data dictionary seems to be rotten. RQG reacts with crashing the server. sdp:/data1/results/1692126141/TBR-2038$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio Given the problems in Variant 1) I am aware that they could be also the reason for the problems here. But in general it looks like the MDEV-30100 fix makes hitting these problems serious more likely. Hence I need to run the same tests on some fresh 10.6 for comparison.

Marko Mäkelä added a comment - 2023-08-17 06:48

mleich, thank you for the update. I expect the problem related to malformed default values in .frm files should be unrelated to these changes. There were some changes to the handling of .frm files or the ddl_recovery.log in June or July. Furthermore, I have the impression that DDL on partitioned tables was never tested to be crash safe. That said, this case does not in any way look related to crash recovery. The error ER_INVALID_DEFAULT is being reported after a server restart when opening the partitioned table table0_innodb_key_pk_parts_2_int_autoinc. Some time before the server had been intentionally killed, the following SQL statement was executed:

ALTER ONLINE IGNORE TABLE `table100_innodb_key_pk_parts_2_int_autoinc` /*!100301 */ ADD IF NOT EXISTS ( k INT DEFAULT NULL /*!100303 INVISIBLE */ ), ALGORITHM=INPLACE, LOCK=DEFAULT  /* E_R Thread1 QNO 761 CON_ID 16 */;

I found it a little strange to see a call to ha_innobase::commit_inplace_alter_table() for this, because InnoDB should not support IGNORE in the native ALTER TABLE. Maybe that only applies to a table rebuild or the creation of indexes. In the ha_alter_info->handler_flags the flags ALTER_ADD_STORED_BASE_COLUMN and ALTER_PARTITIONED are set. InnoDB ignores the latter flag (it is listed in INNOBASE_INPLACE_IGNORE). This looks like an instant ADD COLUMN, atomically committed on the 2 partitions of the table. The statement completed successfully, and the same connection will invoke mysql_execute_command() on the several further SQL statements before the server is killed. This does not look like a recovery bug, but something more deterministic.

Perhaps, if you executed a sequence of statements that ends as follows, you could reproduce this bug without any server restart:

ALTER ONLINE IGNORE TABLE `table100_innodb_key_pk_parts_2_int_autoinc` /*!100301 */ ADD IF NOT EXISTS ( k INT DEFAULT NULL /*!100303 INVISIBLE */ ), ALGORITHM=INPLACE, LOCK=DEFAULT;

FLUSH TABLES;

OPTIMIZE TABLE table100_innodb_key_pk_parts_2_int_autoinc;

There was an error message related to the corrupted INDEX(col_text(9)):

2023-08-15 15:02:58 267 [ERROR] InnoDB: index records in a wrong order in `idx2` of table `test`.`t2`: TUPLE (info_bits=0, 2 fields): {[9]222222222(0x323232323232323232),[4]   i(0x80000969)}, COMPACT RECORD(info_bits=0, 2 fields): {[9]222222222(0x323232323232323232),[4]    (0x8000011A)}

This workload was executed straight after a server bootstrap. This is a TEXT column using the default collation latin1_swedish_ci. The error is being flagged because the (col_text,col1) are in the wrong order (the PRIMARY KEY(col1) should be ascending). I will investigate this deeper to find the actual root cause.

Marko Mäkelä added a comment - 2023-08-17 06:48 mleich , thank you for the update. I expect the problem related to malformed default values in .frm files should be unrelated to these changes. There were some changes to the handling of .frm files or the ddl_recovery.log in June or July. Furthermore, I have the impression that DDL on partitioned tables was never tested to be crash safe. That said, this case does not in any way look related to crash recovery. The error ER_INVALID_DEFAULT is being reported after a server restart when opening the partitioned table table0_innodb_key_pk_parts_2_int_autoinc . Some time before the server had been intentionally killed, the following SQL statement was executed: ALTER ONLINE IGNORE TABLE `table100_innodb_key_pk_parts_2_int_autoinc` /*!100301 */ ADD IF NOT EXISTS ( k INT DEFAULT NULL /*!100303 INVISIBLE */ ), ALGORITHM=INPLACE, LOCK= DEFAULT /* E_R Thread1 QNO 761 CON_ID 16 */ ; I found it a little strange to see a call to ha_innobase::commit_inplace_alter_table() for this, because InnoDB should not support IGNORE in the native ALTER TABLE . Maybe that only applies to a table rebuild or the creation of indexes. In the ha_alter_info->handler_flags the flags ALTER_ADD_STORED_BASE_COLUMN and ALTER_PARTITIONED are set. InnoDB ignores the latter flag (it is listed in INNOBASE_INPLACE_IGNORE ). This looks like an instant ADD COLUMN , atomically committed on the 2 partitions of the table. The statement completed successfully, and the same connection will invoke mysql_execute_command() on the several further SQL statements before the server is killed. This does not look like a recovery bug, but something more deterministic. Perhaps, if you executed a sequence of statements that ends as follows, you could reproduce this bug without any server restart: ALTER ONLINE IGNORE TABLE `table100_innodb_key_pk_parts_2_int_autoinc` /*!100301 */ ADD IF NOT EXISTS ( k INT DEFAULT NULL /*!100303 INVISIBLE */ ), ALGORITHM=INPLACE, LOCK= DEFAULT ; FLUSH TABLES; OPTIMIZE TABLE table100_innodb_key_pk_parts_2_int_autoinc; There was an error message related to the corrupted INDEX(col_text(9)) : 2023-08-15 15:02:58 267 [ERROR] InnoDB: index records in a wrong order in `idx2` of table `test`.`t2`: TUPLE (info_bits=0, 2 fields): {[9]222222222(0x323232323232323232),[4] i(0x80000969)}, COMPACT RECORD(info_bits=0, 2 fields): {[9]222222222(0x323232323232323232),[4] (0x8000011A)} This workload was executed straight after a server bootstrap. This is a TEXT column using the default collation latin1_swedish_ci . The error is being flagged because the (col_text,col1) are in the wrong order (the PRIMARY KEY(col1) should be ascending). I will investigate this deeper to find the actual root cause.

Marko Mäkelä added a comment - 2023-08-17 10:12

In MDEV-25340, mleich posted an rr replay trace that proves that my removal of trx_t::must_flush_log_later made DDL operations crash-unsafe when using innodb_flush_log_at_trx_commit=0. I have updated the branch to hopefully fix that.

For the index records in a wrong order, the previous record (with col1=0x969) is at the very end of the page 0x19, whose successor is 0xe. The record with col1=0x11a was inserted to the end of page 0xe and linked as the successor of the page infimum (as the smallest record in that page). The previous page 0x19 was not latched or modified by other threads between the time CHECK TABLE moved to page 0xe and reported the error. This is somewhat complicated to diagnose, because we are dealing with a ROW_FORMAT_COMPRESSED table with innodb_page_size=4k and KEY_BLOCK_SIZE=2. We have known open bugs on ROW_FORMAT=COMPRESSED tables, such as ~~MDEV-31574~~ (even with a test case). When testing ROW_FORMAT=COMPRESSED tables, it might be better to compile with cmake -DWITH_INNODB_EXTRA_DEBUG=ON so that page_zip_validate() could catch any inconsistency earlier. It took some effort to find the relevant insert into the page 0xe. The last insert (with col_text(9)='333333333') was by the same thread where CHECK TABLE later failed. The second-last insert is the one with the misplaced record with (col_text(9),col1)=('222222222',0x11a). It came from a change buffer merge during a rollback (which will always trigger a change buffer merge, as noted in ~~MDEV-11634~~):

#0  page_cur_insert_rec_zip (cursor=<optimized out>, rec=<optimized out>, offsets=<optimized out>, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/page/page0cur.cc:2072

#1  0x0000556cae399893 in ibuf_insert_to_index_page_low (page_cur=0x7f8b10098dd0, mtr=0x7f8b100991b0, heap=<optimized out>, offsets=0x7f8b10098c78, entry=0x12222402cf28)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3540

#2  ibuf_insert_to_index_page (mtr=0x7f8b100991b0, index=<optimized out>, block=0x795d33954cc0, entry=0x12222402cf28) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3711

#3  ibuf_merge_or_delete_for_page (block=block@entry=0x795d33954cc0, page_id=<optimized out>, page_id@entry={m_id = 103079215118}, zip_size=<optimized out>)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:4243

#4  0x0000556caddf493a in buf_page_get_low (page_id={m_id = 103079215118}, zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, mtr=<optimized out>,

    err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/buf/buf0buf.cc:2834

#5  0x0000556cae4499e8 in btr_cur_t::search_leaf (this=this@entry=0x7f8b10099c90, tuple=tuple@entry=0x3ec06c03a328, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=0,

    mtr=mtr@entry=0x7f8b10099ef0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/btr/btr0cur.cc:1180

#6  0x0000556cae40378f in btr_pcur_open (mtr=0x7f8b10099ef0, cursor=0x7f8b10099c90, latch_mode=<optimized out>, mode=PAGE_CUR_LE, tuple=0x3ec06c03a328)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0pcur.h:431

#7  row_search_index_entry (entry=entry@entry=0x3ec06c03a328, mode=mode@entry=BTR_MODIFY_LEAF, pcur=pcur@entry=0x7f8b10099c90, mtr=mtr@entry=0x7f8b10099ef0)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0row.cc:1281

#8  0x0000556cae4c8cb8 in row_undo_mod_del_unmark_sec_and_undo_update (mode=BTR_MODIFY_LEAF, thr=0x55593401b620, index=0x12222402ac38, entry=0x3ec06c03a328)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:707

#9  0x0000556cae4c93e0 in row_undo_mod_del_mark_sec (thr=0x55593401b620, node=0x3ec06c02d0d8) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:929

#10 row_undo_mod (node=node@entry=0x3ec06c02d0d8, thr=thr@entry=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:1238

#11 0x0000556cae410267 in row_undo (thr=0x55593401b620, node=0x3ec06c02d0d8) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0undo.cc:405

#12 row_undo_step (thr=thr@entry=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0undo.cc:452

#13 0x0000556cae3d3ef2 in que_thr_step (thr=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:586

#14 que_run_threads_low (thr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:644

#15 que_run_threads (thr=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:664

#16 0x0000556cae42a547 in trx_t::rollback_low (this=this@entry=0x1d9a12a7bb80, savept=savept@entry=0x7f8b1009a9f0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:125

#17 0x0000556cae429788 in trx_t::rollback (savept=0x7f8b1009a9f0, this=0x1d9a12a7bb80) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:176

#18 trx_t::rollback (this=this@entry=0x1d9a12a7bb80, savept=savept@entry=0x7f8b1009a9f0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:163

#19 0x0000556cae3f5d20 in row_mysql_handle_errors (new_err=0x7f8b1009a9ec, trx=0x1d9a12a7bb80, thr=<optimized out>, savept=0x7f8b1009a9f0)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:675

#20 0x0000556cae3f62cd in row_update_for_mysql (prebuilt=0x25bf4c0c9678) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:1704

#21 0x0000556cae366dd6 in ha_innobase::update_row (this=0x25bf4c0c6950, old_row=0x25bf4c187350 "\b\376'", new_row=0x25bf4c187100 "\b\376\003")

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:8694

This was a different connection. The statement was

INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( 39, 39, 39, REPEAT(SUBSTR(CAST( 39 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 39 AS CHAR),1,1), @fill_amount) ) ON DUPLICATE KEY UPDATE col1 = 4 - 1  /* E_R Thread1 QNO 22607 CON_ID 262 */;

I didn’t check further where the insert was buffered. This is definitely unrelated to ~~MDEV-30100~~. There could be something wrong with the change buffer when in connection with ROW_FORMAT=COMPRESSED tables; the "free space" estimate is different from uncompressed tables.

Marko Mäkelä added a comment - 2023-08-17 10:12 In MDEV-25340 , mleich posted an rr replay trace that proves that my removal of trx_t::must_flush_log_later made DDL operations crash-unsafe when using innodb_flush_log_at_trx_commit=0 . I have updated the branch to hopefully fix that. For the index records in a wrong order , the previous record (with col1=0x969) is at the very end of the page 0x19, whose successor is 0xe. The record with col1=0x11a was inserted to the end of page 0xe and linked as the successor of the page infimum (as the smallest record in that page). The previous page 0x19 was not latched or modified by other threads between the time CHECK TABLE moved to page 0xe and reported the error. This is somewhat complicated to diagnose, because we are dealing with a ROW_FORMAT_COMPRESSED table with innodb_page_size=4k and KEY_BLOCK_SIZE=2 . We have known open bugs on ROW_FORMAT=COMPRESSED tables, such as MDEV-31574 (even with a test case). When testing ROW_FORMAT=COMPRESSED tables, it might be better to compile with cmake -DWITH_INNODB_EXTRA_DEBUG=ON so that page_zip_validate() could catch any inconsistency earlier. It took some effort to find the relevant insert into the page 0xe. The last insert (with col_text(9)='333333333') was by the same thread where CHECK TABLE later failed. The second-last insert is the one with the misplaced record with (col_text(9),col1)=('222222222',0x11a). It came from a change buffer merge during a rollback (which will always trigger a change buffer merge, as noted in MDEV-11634 ): #0 page_cur_insert_rec_zip (cursor=<optimized out>, rec=<optimized out>, offsets=<optimized out>, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/page/page0cur.cc:2072 #1 0x0000556cae399893 in ibuf_insert_to_index_page_low (page_cur=0x7f8b10098dd0, mtr=0x7f8b100991b0, heap=<optimized out>, offsets=0x7f8b10098c78, entry=0x12222402cf28) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3540 #2 ibuf_insert_to_index_page (mtr=0x7f8b100991b0, index=<optimized out>, block=0x795d33954cc0, entry=0x12222402cf28) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3711 #3 ibuf_merge_or_delete_for_page (block=block@entry=0x795d33954cc0, page_id=<optimized out>, page_id@entry={m_id = 103079215118}, zip_size=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:4243 #4 0x0000556caddf493a in buf_page_get_low (page_id={m_id = 103079215118}, zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, mtr=<optimized out>, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/buf/buf0buf.cc:2834 #5 0x0000556cae4499e8 in btr_cur_t::search_leaf (this=this@entry=0x7f8b10099c90, tuple=tuple@entry=0x3ec06c03a328, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=0, mtr=mtr@entry=0x7f8b10099ef0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/btr/btr0cur.cc:1180 #6 0x0000556cae40378f in btr_pcur_open (mtr=0x7f8b10099ef0, cursor=0x7f8b10099c90, latch_mode=<optimized out>, mode=PAGE_CUR_LE, tuple=0x3ec06c03a328) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0pcur.h:431 #7 row_search_index_entry (entry=entry@entry=0x3ec06c03a328, mode=mode@entry=BTR_MODIFY_LEAF, pcur=pcur@entry=0x7f8b10099c90, mtr=mtr@entry=0x7f8b10099ef0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0row.cc:1281 #8 0x0000556cae4c8cb8 in row_undo_mod_del_unmark_sec_and_undo_update (mode=BTR_MODIFY_LEAF, thr=0x55593401b620, index=0x12222402ac38, entry=0x3ec06c03a328) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:707 #9 0x0000556cae4c93e0 in row_undo_mod_del_mark_sec (thr=0x55593401b620, node=0x3ec06c02d0d8) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:929 #10 row_undo_mod (node=node@entry=0x3ec06c02d0d8, thr=thr@entry=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0umod.cc:1238 #11 0x0000556cae410267 in row_undo (thr=0x55593401b620, node=0x3ec06c02d0d8) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0undo.cc:405 #12 row_undo_step (thr=thr@entry=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0undo.cc:452 #13 0x0000556cae3d3ef2 in que_thr_step (thr=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:586 #14 que_run_threads_low (thr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:644 #15 que_run_threads (thr=0x55593401b620) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/que/que0que.cc:664 #16 0x0000556cae42a547 in trx_t::rollback_low (this=this@entry=0x1d9a12a7bb80, savept=savept@entry=0x7f8b1009a9f0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:125 #17 0x0000556cae429788 in trx_t::rollback (savept=0x7f8b1009a9f0, this=0x1d9a12a7bb80) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:176 #18 trx_t::rollback (this=this@entry=0x1d9a12a7bb80, savept=savept@entry=0x7f8b1009a9f0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/trx/trx0roll.cc:163 #19 0x0000556cae3f5d20 in row_mysql_handle_errors (new_err=0x7f8b1009a9ec, trx=0x1d9a12a7bb80, thr=<optimized out>, savept=0x7f8b1009a9f0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:675 #20 0x0000556cae3f62cd in row_update_for_mysql (prebuilt=0x25bf4c0c9678) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:1704 #21 0x0000556cae366dd6 in ha_innobase::update_row (this=0x25bf4c0c6950, old_row=0x25bf4c187350 "\b\376'", new_row=0x25bf4c187100 "\b\376\003") at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:8694 This was a different connection. The statement was INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( 39, 39, 39, REPEAT(SUBSTR( CAST ( 39 AS CHAR ),1,1), 10), REPEAT(SUBSTR( CAST ( 39 AS CHAR ),1,1), @fill_amount) ) ON DUPLICATE KEY UPDATE col1 = 4 - 1 /* E_R Thread1 QNO 22607 CON_ID 262 */ ; I didn’t check further where the insert was buffered. This is definitely unrelated to MDEV-30100 . There could be something wrong with the change buffer when in connection with ROW_FORMAT=COMPRESSED tables; the "free space" estimate is different from uncompressed tables.

Marko Mäkelä added a comment - 2023-08-17 12:29

I tried but failed to find the exact root cause of this.

break ibuf0ibuf.cc:3509

cond 1 index==0x12222402ac38 && *(char*)entry.fields[0].data=='2'

break ibuf_merge_or_delete_for_page

cond 2 page_id.m_id==0x50000000e

continue

The first breakpoint is being hit exactly once in the entire trace, for a different primary key, col1=0x81c (2076) and not col1=0x11a. I think that in order to find and fix the cause of this corruption, we might need some test case simplification.

Marko Mäkelä added a comment - 2023-08-17 12:29 I tried but failed to find the exact root cause of this. break ibuf0ibuf.cc:3509 cond 1 index==0x12222402ac38 && *(char*)entry.fields[0].data=='2' break ibuf_merge_or_delete_for_page cond 2 page_id.m_id==0x50000000e continue The first breakpoint is being hit exactly once in the entire trace, for a different primary key, col1=0x81c (2076) and not col1=0x11a. I think that in order to find and fix the cause of this corruption, we might need some test case simplification.

Marko Mäkelä added a comment - 2023-08-18 09:29

I just spent 4 hours analyzing the root cause of another failure:

# 2023-08-17T13:18:56 [33159] ERROR: checkDatabaseIntegrity  server[1]:  Query ->ALTER TABLE test . t5 FORCE<- failed with 1062 : Duplicate entry '1900-01-01' for key 'col_date'

Yes, there was a duplicate value 0x8ed821 for that unique column, with the PRIMARY KEY values pk=0x875 and pk=0x876. It took me some effort to find the original INSERT statement. At that point, the unique key did exist, but the constraint was violated because innodb_change_buffering was enabled and unique_checks=0 was in effect. The problematic INSERT only inserted that single row. In the clustered index page at that time, we got:

#1  page_cur_insert_rec_low (cur=cur@entry=0x79f71d2ada20, rec=rec@entry=0x1b2d141183be "\200", offsets=<optimized out>, mtr=mtr@entry=0x79f71d2adfc0)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/page/page0cur.cc:1569

1569	    mach_write_to_2(cur->rec - REC_NEXT,

(rr) p/x *rec@30

$44 = {0x80, 0x0, 0x8, 0x76, 0x0, 0x0, 0x0, 0x0, 0x80, 0x12, 0x92, 0x0, 0x0, 0x4, 0x66, 0xc, 0x10, 0x8e, 0xd8, 0x21, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}

(rr) p/x *cur.rec@30

$46 = {0x80, 0x0, 0x8, 0x75, 0x0, 0x0, 0x0, 0x0, 0x80, 0x4, 0x89, 0x0, 0x0, 0x4, 0x65, 0xa, 0x88, 0x8e, 0xd8, 0x21, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}

That is, pk=0x875 was inserted by DB_TRX_ID=0x8004, and the current transaction is inserting pk=0x876,DB_TRX_ID=0x8012. In both records right after the 7-byte DB_ROLL_PTR, we see the duplicate col_date value 0x8ed821. This is still OK; the duplicate should be detected when we attempt to insert that key to the unique index. After that point, this last insert should be rolled back. However, the duplicate key was not noticed due to the following:

Thread 29 hit Breakpoint 19, ibuf_insert_low (mode=BTR_MODIFY_PREV, op=IBUF_OP_INSERT, no_counter=1, entry=0x1b2d140aaee8, entry_size=12, index=0x1b2d1409e898, page_id={m_id = 38654705818}, zip_size=0,

    thr=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3111

3111	{

5: x/i $pc

=> 0x555a1593cd90 <ibuf_insert_low(btr_latch_mode, ibuf_op_t, ulint, dtuple_t const*, ulint, dict_index_t*, page_id_t, ulint, que_thr_t*)>:	push   %rbp

(rr) p index.name

$54 = {m_name = 0x1b2d1409ea28 "col_date"}

(rr) fin

Run till exit from #0  ibuf_insert_low (mode=BTR_MODIFY_PREV, op=IBUF_OP_INSERT, no_counter=1, entry=0x1b2d140aaee8, entry_size=12, index=0x1b2d1409e898, page_id={m_id = 38654705818}, zip_size=0,

    thr=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3111

ibuf_insert (op=op@entry=IBUF_OP_INSERT, entry=entry@entry=0x1b2d140aaee8, index=0x1b2d1409e898, page_id=page_id@entry={m_id = 38654705818}, zip_size=zip_size@entry=0, thr=<optimized out>)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3512

3512		if (err == DB_FAIL) {

5: x/i $pc

=> 0x555a1593ead5 <ibuf_insert(ibuf_op_t, dtuple_t const*, dict_index_t*, page_id_t, unsigned long, que_thr_t*)+533>:	add    $0x20,%rsp

Value returned is $55 = DB_SUCCESS

(rr)

Run till exit from #0  ibuf_insert (op=op@entry=IBUF_OP_INSERT, entry=entry@entry=0x1b2d140aaee8, index=0x1b2d1409e898, page_id=page_id@entry={m_id = 38654705818}, zip_size=zip_size@entry=0,

    thr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3512

0x0000555a15fc0f8a in btr_cur_t::search_leaf (this=this@entry=0x79f71d2ad760, tuple=tuple@entry=0x1b2d140aaee8, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=2114,

    mtr=mtr@entry=0x79f71d2adfb0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0cur.h:744

744	  dict_index_t *index() const { return page_cur.index; }

5: x/i $pc

=> 0x555a15fc0f8a <btr_cur_t::search_leaf(dtuple_t const*, page_cur_mode_t, btr_latch_mode, mtr_t*)+2026>:	mov    -0x538(%rbp),%r10

Value returned is $56 = true

(rr) bt

#0  0x0000555a15fc0f8a in btr_cur_t::search_leaf (this=this@entry=0x79f71d2ad760, tuple=tuple@entry=0x1b2d140aaee8, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=2114,

    mtr=mtr@entry=0x79f71d2adfb0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0cur.h:744

#1  0x0000555a15f4ac05 in row_ins_sec_index_entry_low (flags=0, mode=BTR_MODIFY_LEAF, index=0x1b2d1409e898, offsets_heap=<optimized out>, heap=0x1b2d14256430, entry=0x1b2d140aaee8, trx_id=0, thr=0x1b2d1411f890)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3015

#2  0x0000555a15f4e312 in row_ins_sec_index_entry (index=0x1b2d1409e898, entry=0x1b2d140aaee8, thr=0x1b2d1411f890, check_foreign=<optimized out>)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3322

#3  0x0000555a15f4e7ec in row_ins_index_entry (thr=0x1b2d1411f890, entry=<optimized out>, index=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3370

#4  row_ins_index_entry_step (thr=0x1b2d1411f890, node=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3536

#5  row_ins (thr=0x1b2d1411f890, node=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3661

#6  row_ins_step (thr=thr@entry=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3790

#7  0x0000555a15f5b227 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x1b2d140ac2c0 "\377", prebuilt=0x1b2d1412ed98, ins_mode=ROW_INS_NORMAL)

    at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:1315

#8  0x0000555a15eca90e in ha_innobase::write_row (this=0x1b2d140a8490, record=0x1b2d140ac2c0 "\377") at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:7905

This statement

INSERT IGNORE INTO `t5` ( `pk`, `col_char` ) VALUES ( NULL, 'l' ) /* E_R Thread1 QNO 63149 CON_ID 14 */;

was successfully autocommitted with that 1 invalid row inserted, because unique_checks=0 allowed the buffered insert into the unique index col_date to happen. Had it not been possible to use the change buffer, the uniqueness violation would have been noticed.

Marko Mäkelä added a comment - 2023-08-18 09:29 I just spent 4 hours analyzing the root cause of another failure: # 2023-08-17T13:18:56 [33159] ERROR: checkDatabaseIntegrity server[1]: Query ->ALTER TABLE test . t5 FORCE<- failed with 1062 : Duplicate entry '1900-01-01' for key 'col_date' Yes, there was a duplicate value 0x8ed821 for that unique column, with the PRIMARY KEY values pk=0x875 and pk=0x876. It took me some effort to find the original INSERT statement. At that point, the unique key did exist, but the constraint was violated because innodb_change_buffering was enabled and unique_checks=0 was in effect. The problematic INSERT only inserted that single row. In the clustered index page at that time, we got: #1 page_cur_insert_rec_low (cur=cur@entry=0x79f71d2ada20, rec=rec@entry=0x1b2d141183be "\200", offsets=<optimized out>, mtr=mtr@entry=0x79f71d2adfc0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/page/page0cur.cc:1569 1569 mach_write_to_2(cur->rec - REC_NEXT, (rr) p/x *rec@30 $44 = {0x80, 0x0, 0x8, 0x76, 0x0, 0x0, 0x0, 0x0, 0x80, 0x12, 0x92, 0x0, 0x0, 0x4, 0x66, 0xc, 0x10, 0x8e, 0xd8, 0x21, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0} (rr) p/x *cur.rec@30 $46 = {0x80, 0x0, 0x8, 0x75, 0x0, 0x0, 0x0, 0x0, 0x80, 0x4, 0x89, 0x0, 0x0, 0x4, 0x65, 0xa, 0x88, 0x8e, 0xd8, 0x21, 0x0, 0x0, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0} That is, pk=0x875 was inserted by DB_TRX_ID=0x8004, and the current transaction is inserting pk=0x876,DB_TRX_ID=0x8012. In both records right after the 7-byte DB_ROLL_PTR, we see the duplicate col_date value 0x8ed821. This is still OK; the duplicate should be detected when we attempt to insert that key to the unique index. After that point, this last insert should be rolled back. However, the duplicate key was not noticed due to the following: Thread 29 hit Breakpoint 19, ibuf_insert_low (mode=BTR_MODIFY_PREV, op=IBUF_OP_INSERT, no_counter=1, entry=0x1b2d140aaee8, entry_size=12, index=0x1b2d1409e898, page_id={m_id = 38654705818}, zip_size=0, thr=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3111 3111 { 5: x/i $pc => 0x555a1593cd90 <ibuf_insert_low(btr_latch_mode, ibuf_op_t, ulint, dtuple_t const*, ulint, dict_index_t*, page_id_t, ulint, que_thr_t*)>: push %rbp (rr) p index.name $54 = {m_name = 0x1b2d1409ea28 "col_date"} (rr) fin Run till exit from #0 ibuf_insert_low (mode=BTR_MODIFY_PREV, op=IBUF_OP_INSERT, no_counter=1, entry=0x1b2d140aaee8, entry_size=12, index=0x1b2d1409e898, page_id={m_id = 38654705818}, zip_size=0, thr=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3111 ibuf_insert (op=op@entry=IBUF_OP_INSERT, entry=entry@entry=0x1b2d140aaee8, index=0x1b2d1409e898, page_id=page_id@entry={m_id = 38654705818}, zip_size=zip_size@entry=0, thr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3512 3512 if (err == DB_FAIL) { 5: x/i $pc => 0x555a1593ead5 <ibuf_insert(ibuf_op_t, dtuple_t const*, dict_index_t*, page_id_t, unsigned long, que_thr_t*)+533>: add $0x20,%rsp Value returned is $55 = DB_SUCCESS (rr) Run till exit from #0 ibuf_insert (op=op@entry=IBUF_OP_INSERT, entry=entry@entry=0x1b2d140aaee8, index=0x1b2d1409e898, page_id=page_id@entry={m_id = 38654705818}, zip_size=zip_size@entry=0, thr=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/ibuf/ibuf0ibuf.cc:3512 0x0000555a15fc0f8a in btr_cur_t::search_leaf (this=this@entry=0x79f71d2ad760, tuple=tuple@entry=0x1b2d140aaee8, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=2114, mtr=mtr@entry=0x79f71d2adfb0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0cur.h:744 744 dict_index_t *index() const { return page_cur.index; } 5: x/i $pc => 0x555a15fc0f8a <btr_cur_t::search_leaf(dtuple_t const*, page_cur_mode_t, btr_latch_mode, mtr_t*)+2026>: mov -0x538(%rbp),%r10 Value returned is $56 = true (rr) bt #0 0x0000555a15fc0f8a in btr_cur_t::search_leaf (this=this@entry=0x79f71d2ad760, tuple=tuple@entry=0x1b2d140aaee8, mode=mode@entry=PAGE_CUR_LE, latch_mode=BTR_MODIFY_LEAF, latch_mode@entry=2114, mtr=mtr@entry=0x79f71d2adfb0) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/include/btr0cur.h:744 #1 0x0000555a15f4ac05 in row_ins_sec_index_entry_low (flags=0, mode=BTR_MODIFY_LEAF, index=0x1b2d1409e898, offsets_heap=<optimized out>, heap=0x1b2d14256430, entry=0x1b2d140aaee8, trx_id=0, thr=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3015 #2 0x0000555a15f4e312 in row_ins_sec_index_entry (index=0x1b2d1409e898, entry=0x1b2d140aaee8, thr=0x1b2d1411f890, check_foreign=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3322 #3 0x0000555a15f4e7ec in row_ins_index_entry (thr=0x1b2d1411f890, entry=<optimized out>, index=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3370 #4 row_ins_index_entry_step (thr=0x1b2d1411f890, node=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3536 #5 row_ins (thr=0x1b2d1411f890, node=<optimized out>) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3661 #6 row_ins_step (thr=thr@entry=0x1b2d1411f890) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0ins.cc:3790 #7 0x0000555a15f5b227 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x1b2d140ac2c0 "\377", prebuilt=0x1b2d1412ed98, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-MDEV-30100/storage/innobase/row/row0mysql.cc:1315 #8 0x0000555a15eca90e in ha_innobase::write_row (this=0x1b2d140a8490, record=0x1b2d140ac2c0 "\377") at /data/Server/bb-10.6-MDEV-30100/storage/innobase/handler/ha_innodb.cc:7905 This statement INSERT IGNORE INTO `t5` ( `pk`, `col_char` ) VALUES ( NULL , 'l' ) /* E_R Thread1 QNO 63149 CON_ID 14 */ ; was successfully autocommitted with that 1 invalid row inserted, because unique_checks=0 allowed the buffered insert into the unique index col_date to happen. Had it not been possible to use the change buffer, the uniqueness violation would have been noticed.

Matthias Leich added a comment - 2023-08-23 17:12

origin/bb-10.6-~~MDEV-30100~~ 562850823ba74e15ae638205aeacee9f678de393 2023-08-17T11:14:02+03:00
performed well in the last round of RQG testing. No new problems.

Matthias Leich added a comment - 2023-08-23 17:12 origin/bb-10.6- MDEV-30100 562850823ba74e15ae638205aeacee9f678de393 2023-08-17T11:14:02+03:00 performed well in the last round of RQG testing. No new problems.

Vladislav Lesin added a comment - 2023-08-25 10:08

The code looks correct to me. Thanks to marko for explaining some details.

Vladislav Lesin added a comment - 2023-08-25 10:08 The code looks correct to me. Thanks to marko for explaining some details.

Vladislav Lesin made changes - 2023-08-25 10:08

Status

In Review [ 10002 ]

Stalled [ 10000 ]

Marko Mäkelä added a comment - 2023-08-25 11:18

Thanks again to mleich for testing this, and vlad.lesin for the review. I added some comments to trx_t::commit_empty() to explain the logic.

Marko Mäkelä added a comment - 2023-08-25 11:18 Thanks again to mleich for testing this, and vlad.lesin for the review. I added some comments to trx_t::commit_empty() to explain the logic.

Marko Mäkelä made changes - 2023-08-25 11:18

issue.field.resolutiondate

2023-08-25 11:18:29.0

2023-08-25 11:18:29.403

Marko Mäkelä made changes - 2023-08-25 11:18

Fix Version/s		10.6.16 [ 29014 ]
Fix Version/s		10.10.7 [ 29018 ]
Fix Version/s		10.11.6 [ 29020 ]
Fix Version/s		11.0.4 [ 29021 ]
Fix Version/s		11.1.3 [ 29023 ]
Fix Version/s		11.2.2 [ 29035 ]
Fix Version/s	10.6 [ 24028 ]
Fix Version/s	10.10 [ 27530 ]
Fix Version/s	10.11 [ 27614 ]
Fix Version/s	11.0 [ 28320 ]
Fix Version/s	11.1 [ 28549 ]
Fix Version/s	11.2 [ 28603 ]
Assignee	Vladislav Lesin [ vlad.lesin ]	Marko Mäkelä [ marko ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Marko Mäkelä made changes - 2023-09-06 12:22

Link

This issue causes ~~MDEV-32103~~ [ ~~MDEV-32103~~ ]

Marko Mäkelä made changes - 2023-09-07 06:26

Link

This issue causes ~~MDEV-32103~~ [ ~~MDEV-32103~~ ]

Marko Mäkelä made changes - 2023-09-07 06:55

Link

This issue causes ~~MDEV-32103~~ [ ~~MDEV-32103~~ ]

MariaDB Server

Assertion `purge_sys.tail.trx_no <= purge_sys.rseg->last_trx_no()'

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration