Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.5.16, 11.2.0, 10.5, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL)
-
centos 7.6
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 ; |
Attachments
Issue Links
- causes
-
-
- Closed
-
- duplicates
-
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
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.
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.
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>
|
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.
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!
|
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
|
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.
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.
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.
I updated the branch with one where trx_t::commit_empty() will free the last (non-first) record from the undo page.
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.
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
|
|
|
|
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 */; |
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.
|
|
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.
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.
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.
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.
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.
The code looks correct to me. Thanks to marko for explaining some details.
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.
dongjian do you know what SQL was being executed at the time of this fault?