Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.6.8, 10.7.4, 10.8.3, 10.9.1, 10.10.1
Description
I accidentally found this bug while trying to reproduce MDEV-29438.
In MDEV-27234, the data dictionary recovery was corrected to use the READ COMMITTED isolation level. However, the recovery of the instant ALTER TABLE metadata (MDEV-11369, MDEV-15562) was not adjusted.
Technically, also MariaDB Server 10.3, 10.4, 10.5 may be affected by this, but because they do not support crash-safe DDL operations such as MDEV-25180, it does not make sense to fix this bug before MariaDB Server 10.6.
Consider the following test case:
--source include/have_innodb.inc
|
--source include/not_embedded.inc
|
--source include/have_debug.inc
|
--source include/have_debug_sync.inc
|
|
|
CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB; |
INSERT INTO t1 SET a=1; |
CREATE TABLE t2(a INT UNSIGNED PRIMARY KEY) ENGINE=InnoDB; |
INSERT INTO t2 VALUES (1),(2),(3),(4),(5),(6); |
|
|
connect ddl, localhost, root; |
SET DEBUG_SYNC='innodb_alter_inplace_before_commit SIGNAL ddl WAIT_FOR ever'; |
--send
|
ALTER TABLE t2 ADD COLUMN b TINYINT UNSIGNED NOT NULL DEFAULT 42 FIRST; |
|
|
connection default; |
SET DEBUG_SYNC='now WAIT_FOR ddl'; |
SET GLOBAL innodb_flush_log_at_trx_commit=1; |
DELETE FROM t1; |
|
|
--source include/kill_mysqld.inc
|
disconnect ddl;
|
--source include/start_mysqld.inc
|
|
|
CHECK TABLE t2; |
DROP TABLE t1,t2; |
Thanks to MDEV-27234, the data dictionary information for the ALTER TABLE operation during which the server was killed was recovered correctly: the uncommitted newest version of the dictionary tables was ignored and the table recovered as if no ALTER TABLE operation had completed.
However, the recovery would crash a little bit later:
|
10.6 40aa94df356cfa000fc43c92ff0061212d1b161d |
2022-09-01 13:19:14 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=54849,54849
|
mariadbd: /mariadb/10.6/storage/innobase/rem/rem0rec.cc:304: void rec_init_offsets_comp_ordinary(const rec_t*, const dict_index_t*, rec_offs*, ulint, const dict_col_t::def_t*, rec_leaf_format) [with bool mblob = true; bool redundant_temp = false; rec_t = unsigned char; rec_offs = short unsigned int; ulint = long unsigned int]: Assertion `n_fields <= ulint(index->n_fields) + 1' failed.
|
The reason seems to be that we are reading the metadata record using the READ UNCOMMITTED isolation level. Here is an incomplete attempt to fix that:
diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.cc
|
index e9b4e2937b9..71d11e22597 100644
|
--- a/storage/innobase/btr/btr0cur.cc
|
+++ b/storage/innobase/btr/btr0cur.cc
|
@@ -384,6 +384,7 @@ static dberr_t btr_cur_instant_init_low(dict_index_t* index, mtr_t* mtr)
|
ut_ad(index->n_core_null_bytes != dict_index_t::NO_CORE_NULL_BYTES);
|
|
if (fil_page_get_type(root->page.frame) == FIL_PAGE_INDEX) {
|
+not_instant:
|
ut_ad(!index->is_instant());
|
return DB_SUCCESS;
|
}
|
@@ -445,9 +446,6 @@ static dberr_t btr_cur_instant_init_low(dict_index_t* index, mtr_t* mtr)
|
concurrent operations on the table, including table eviction
|
from the cache. */
|
|
- if (info_bits & REC_INFO_DELETED_FLAG) {
|
- /* This metadata record includes a BLOB that identifies
|
- any dropped or reordered columns. */
|
ulint trx_id_offset = index->trx_id_offset;
|
/* If !index->trx_id_offset, the PRIMARY KEY contains
|
variable-length columns. For the metadata record,
|
@@ -507,6 +505,9 @@ static dberr_t btr_cur_instant_init_low(dict_index_t* index, mtr_t* mtr)
|
const byte* ptr = rec + trx_id_offset
|
+ (DATA_TRX_ID_LEN + DATA_ROLL_PTR_LEN);
|
|
+ if (info_bits & REC_INFO_DELETED_FLAG) {
|
+ /* This metadata record includes a BLOB that identifies
|
+ any dropped or reordered columns. */
|
if (mach_read_from_4(ptr + BTR_EXTERN_LEN)) {
|
goto incompatible;
|
}
|
@@ -519,7 +520,22 @@ static dberr_t btr_cur_instant_init_low(dict_index_t* index, mtr_t* mtr)
|
!= space->id) {
|
goto incompatible;
|
}
|
+ }
|
+
|
+ if (const trx_id_t trx_id = trx_read_trx_id(rec + trx_id_offset)) {
|
+ if (!trx_sys.find(nullptr, trx_id, false)) {
|
+ /* The ALTER TABLE operation was committed. */
|
+ } else if (rec[trx_id_offset + DATA_TRX_ID_LEN] & 0x80) {
|
+ /* The first instant ALTER TABLE operation
|
+ was not completed. */
|
+ goto not_instant;
|
+ } else {
|
+ /* FIXME: retrieve an older version */
|
+ }
|
+ }
|
|
+ if (info_bits & REC_INFO_DELETED_FLAG) {
|
+ const uint len = mach_read_from_4(ptr + BTR_EXTERN_LEN + 4);
|
buf_block_t* block = buf_page_get(
|
page_id_t(space->id,
|
mach_read_from_4(ptr + BTR_EXTERN_PAGE_NO)), |
With that incomplete fix (we should fetch the last committed version of the metadata record it is not the first but some later instant ALTER TABLE that was aborted), we would crash in rollback a little later:
mariadbd: /mariadb/10.6/storage/innobase/rem/rem0rec.cc:938: rec_offs* rec_get_offsets_func(const rec_t*, const dict_index_t*, rec_offs*, ulint, ulint, const char*, unsigned int, mem_heap_t**): Assertion `index->table->instant' failed.
|
...
|
Thread 1 hit Breakpoint 1, rec_get_offsets_func (rec=rec@entry=0x7f16f1bf8102 "", index=index@entry=0x556ab210e418, offsets=offsets@entry=0x7ffd7392d190, n_core=3, n_fields=n_fields@entry=18446744073709551615, file=file@entry=0x556ab04ac448 "/mariadb/10.6/storage/innobase/row/row0undo.cc", line=190, heap=0x7ffd7392d188) at /mariadb/10.6/storage/innobase/rem/rem0rec.cc:938
|
938 ut_ad(index->table->instant);
|
(rr) bt
|
#0 rec_get_offsets_func (rec=rec@entry=0x7f16f1bf8102 "", index=index@entry=0x556ab210e418, offsets=offsets@entry=0x7ffd7392d190, n_core=3, n_fields=n_fields@entry=18446744073709551615,
|
file=file@entry=0x556ab04ac448 "/mariadb/10.6/storage/innobase/row/row0undo.cc", line=190, heap=0x7ffd7392d188) at /mariadb/10.6/storage/innobase/rem/rem0rec.cc:938
|
#1 0x0000556aaffe0186 in row_undo_search_clust_to_pcur (node=node@entry=0x556ab210f9e8) at /mariadb/10.6/storage/innobase/row/row0undo.cc:190
|
#2 0x0000556ab0117457 in row_undo_ins_parse_undo_rec (node=node@entry=0x556ab210f9e8, dict_locked=dict_locked@entry=true) at /mariadb/10.6/storage/innobase/row/row0uins.cc:468
|
#3 0x0000556ab011876d in row_undo_ins (node=node@entry=0x556ab210f9e8, thr=thr@entry=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/row/row0uins.cc:573
|
#4 0x0000556aaffe0c04 in row_undo (node=node@entry=0x556ab210f9e8, thr=thr@entry=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/row/row0undo.cc:401
|
#5 0x0000556aaffe0c97 in row_undo_step (thr=thr@entry=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/row/row0undo.cc:452
|
#6 0x0000556aaff6d9e1 in que_thr_step (thr=thr@entry=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/que/que0que.cc:651
|
#7 0x0000556aaff6dbd2 in que_run_threads_low (thr=thr@entry=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/que/que0que.cc:709
|
#8 0x0000556aaff6dc8f in que_run_threads (thr=0x556ab210f7f8) at /mariadb/10.6/storage/innobase/que/que0que.cc:729
|
#9 0x0000556ab001299d in trx_rollback_active (trx=trx@entry=0x7f16f215fb80) at /mariadb/10.6/storage/innobase/trx/trx0roll.cc:609
|
Attachments
Issue Links
- blocks
-
-
- Closed
-
- is caused by
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- relates to
-
MDEV-11369 Instant add column for InnoDB
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
(1 relates to)
Activity
In order to be able to roll back an instant ALTER TABLE operation, it seems that we must load the READ UNCOMMITTED metadata of the table. By the time innobase_instant_try() is inserting or updating the hidden metadata record, the data dictionary will already have been changed. Both changes would be committed a little later.
Possibly a simpler fix of this bug would be that when an instant ALTER TABLE operation was noticed (that is, dict_load_column_low() would need to reconstruct an earlier version of something uncommitted in SYS_COLUMNS), we would load a READ UNCOMMITTED definition of the table. This table definition would be evicted once the incomplete instant ALTER TABLE transaction is rolled back. Then, the correct (committed) table definition would be loaded for any handlerton::check_version check that would be invoked by ddl_log_execute_action().
The MDEV-27234 fix applies to those cases where a DDL operation would rebuild a table. If an ALTER TABLE operation involves instantly adding a column, it will always be compatible with ALGORITHM=NOCOPY and avoid rebuilding the table. The recovery of table-rebuilding DDL operations must keep using the READ COMMITTED isolation level.
Loading table metadata starts with dict_sys_tables_rec_read() processing a record of SYS_TABLES. In a table rebuild, the SYS_TABLES.ID would always change. Unfortunately, it is not the primary key of the table; SYS_TABLES.NAME is.
I am currently considering the following fix: dict_load_table_one() needs to check if the SYS_TABLES.ID of the latest (possibly uncommitted) version differs from the parsed table->id. If the SYS_TABLES.ID was updated, then any subsequent reads of the dictionary for this table (starting with dict_load_columns()) must use READ COMMITTED. Else, dict_load_columns() may decide that READ UNCOMMITTED must be used, that is, also the SYS_TABLES record must be re-read in READ UNCOMMITTED mode.
Preliminary results of RQG testing on origin/bb-10.6-MDEV-29440 1c730da666ec50b131ca96a916a024c216632c28 2022-09-06T12:44:58+03:00
|
|
|
Per server error log
|
[rr 2537046 143119]mysqld: /data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h:1027: void trx_t::assert_freed() const: Assertion `!lock.wait_thr' failed.
|
[rr 2537046 143139]220906 14:02:46 [rr 2537046 143142][ERROR] mysqld got signal 6 ;
|
....
|
[rr 2537046 164312]mysqld: /data/Server/bb-10.6-MDEV-29440/storage/innobase/lock/lock0lock.cc:5737: static dberr_t lock_sys_t::cancel(trx_t*, ib_lock_t*) [with bool check_victim = false]: Assertion `trx->state == TRX_STATE_ACTIVE' failed. <== This might be caused by the reaction of the system to the assertion above.
|
Both asserts were observed the first time when testing bb-10.6-MDEV-15250 March 2022.
|
But they did never show up since than.
|
|
|
pluto:/data/results/1662464247/TBR-1442-TBR-1443$ _RR_TRACE_DIR=./1/rr/ rr replay
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000027ba0dd3a859 in __GI_abort () at abort.c:79
|
#2 0x000027ba0dd3a729 in __assert_fail_base (fmt=0x27ba0ded0588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f6d9266a20 "!lock.wait_thr",
|
file=0x55f6d9266480 "/data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h", line=1027, function=<optimized out>) at assert.c:92
|
#3 0x000027ba0dd4bf36 in __GI___assert_fail (assertion=0x55f6d9266a20 "!lock.wait_thr", file=0x55f6d9266480 "/data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h", line=1027,
|
function=0x55f6d92667e0 "void trx_t::assert_freed() const") at assert.c:101
|
#4 0x000055f6d80dfd1c in trx_t::assert_freed (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/include/trx0trx.h:1027
|
#5 0x000055f6d80d87c1 in trx_t::commit_cleanup (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0trx.cc:1395
|
#6 0x000055f6d80db1e2 in trx_t::commit (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0trx.cc:1483
|
#7 0x000055f6d80bc04f in trx_t::rollback_finish (this=0x780c056f7e40) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:66
|
#8 0x000055f6d80bcdb6 in trx_t::rollback_low (this=0x780c056f7e40, savept=0x0) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:133
|
#9 0x000055f6d80b718f in trx_t::rollback (this=0x780c056f7e40, savept=0x0) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/trx/trx0roll.cc:176
|
#10 0x000055f6d7f946b3 in row_mysql_handle_errors (new_err=0x2d105d0e33f0, trx=0x780c056f7e40, thr=0x6210004030b0, savept=0x2d105d0e3400) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/row/row0mysql.cc:696
|
#11 0x000055f6d7f98927 in row_insert_for_mysql (mysql_rec=0x61a00032eeb8 "\377", prebuilt=0x621000402588, ins_mode=ROW_INS_NORMAL) at /data/Server/bb-10.6-MDEV-29440/storage/innobase/row/row0mysql.cc:1319
|
#12 0x000055f6d7c0ce83 in ha_innobase::write_row (this=0x61d0005848b8, record=0x61a00032eeb8 "\377") at /data/Server/bb-10.6-MDEV-29440/storage/innobase/handler/ha_innodb.cc:7935
|
#13 0x000055f6d732b678 in handler::ha_write_row (this=0x61d0005848b8, buf=0x61a00032eeb8 "\377") at /data/Server/bb-10.6-MDEV-29440/sql/handler.cc:7575
|
#14 0x000055f6d6a717ca in write_record (thd=0x62b00023e218, table=0x61900034e498, info=0x2d105d0e3de0, sink=0x0) at /data/Server/bb-10.6-MDEV-29440/sql/sql_insert.cc:2156
|
#15 0x000055f6d6a69e9f in mysql_insert (thd=0x62b00023e218, table_list=0x62b0002454c8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /data/Server/bb-10.6-MDEV-29440/sql/sql_insert.cc:1128
|
#16 0x000055f6d6b28221 in mysql_execute_command (thd=0x62b00023e218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:4565
|
#17 0x000055f6d6b3f4ef in mysql_parse (thd=0x62b00023e218,
|
rawbuf=0x62b000245238 "INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( NULL, NULL, NULL, REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), @fill_amount) ) /* E_R Thread2"..., length=221, parser_state=0x2d105d0e4a20) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:8030
|
#18 0x000055f6d6b17871 in dispatch_command (command=COM_QUERY, thd=0x62b00023e218,
|
packet=0x629000e9c219 " INSERT INTO t2 (col1,col2, col_int, col_string, col_text) VALUES ( NULL, NULL, NULL, REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( NULL AS CHAR),1,1), @fill_amount) ) /* E_R Thread"..., packet_length=223, blocking=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:1896
|
#19 0x000055f6d6b14c9a in do_command (thd=0x62b00023e218, blocking=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_parse.cc:1409
|
#20 0x000055f6d6f19623 in do_handle_one_connection (connect=0x608000003bb8, put_in_cache=true) at /data/Server/bb-10.6-MDEV-29440/sql/sql_connect.cc:1418
|
#21 0x000055f6d6f18eaf in handle_one_connection (arg=0x608000003bb8) at /data/Server/bb-10.6-MDEV-29440/sql/sql_connect.cc:1312
|
#22 0x00007f34e094a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#23 0x000027ba0de37293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
# git clone https://github.com/mleich1/rqg --branch experimental RQG
|
#
|
# GIT_SHOW: HEAD -> experimental, origin/experimental 870d6d8aa40c27a3b53e445e8fc86aae51cba19c 2022-08-30T20:57:51+02:00
|
# rqg.pl : Version 4.0.6 (2022-05)
|
#
|
# $RQG_HOME/rqg.pl \
|
# --grammar=conf/mariadb/table_stress_innodb.yy \
|
# --gendata=conf/mariadb/table_stress.zz \
|
# --gendata_sql=conf/mariadb/table_stress.sql \
|
# --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
|
# --mysqld=--loose-idle_write_transaction_timeout=0 \
|
# --mysqld=--loose-idle_transaction_timeout=0 \
|
# --mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
# --mysqld=--connect_timeout=60 \
|
# --mysqld=--interactive_timeout=28800 \
|
# --mysqld=--slave_net_timeout=60 \
|
# --mysqld=--net_read_timeout=30 \
|
# --mysqld=--net_write_timeout=60 \
|
# --mysqld=--loose-table_lock_wait_timeout=50 \
|
# --mysqld=--wait_timeout=28800 \
|
# --mysqld=--lock-wait-timeout=86400 \
|
# --mysqld=--innodb-lock-wait-timeout=50 \
|
# --no-mask \
|
# --queries=10000000 \
|
# --seed=random \
|
# --reporters=Backtrace \
|
# --reporters=ErrorLog \
|
# --reporters=Deadlock1 \
|
# --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 \
|
# --duration=300 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--innodb_file_per_table=1 \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--loose-innodb-sync-debug \
|
# --mysqld=--innodb_stats_persistent=off \
|
# --mysqld=--innodb_adaptive_hash_index=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=--loose_innodb_change_buffering=deletes \
|
# --mysqld=--innodb_rollback_on_timeout=ON \ <== Could that play some important role?
|
# --mysqld=--innodb_page_size=4K \
|
# --mysqld=--innodb-buffer-pool-size=5M \
|
# <local settings>
|
mleich, the rr replay trace looks unrelated to the changes to the data dictionary read interface. It reminds me of MDEV-27031 because it involves innodb_rollback_on_timeout=ON. The lock.wait_thr would be set in lock_rec_enqueue_waiting(), which would return DB_LOCK_WAIT all the way up to row_ins_step(), which would return a null pointer to row_insert_for_mysql(). Then, row_insert_for_mysql() would invoke row_mysql_handle_errors(), which would trigger a rollback of the transaction. I think that normally, rollback is only invoked on DB_DEADLOCK, in which case the waiting lock request should already have been removed. We will have to remove the waiting lock request when a transaction will be rolled back due to a lock wait timeout.
origin/bb-10.6-MDEV-29440 1c730da666ec50b131ca96a916a024c216632c28 2022-09-06T12:44:58+03:00
performed well in RQG testing. The problems observed are in main trees too.
A slightly different test case (I am trying to reproduce
MDEV-29438without hitting this bug):--source include/have_innodb.inc--source include/not_embedded.inc--source include/have_debug.inc--source include/have_debug_sync.incENGINE=InnoDB;--send--source include/kill_mysqld.incdisconnect ddl;--source include/start_mysqld.inc10.6 40aa94df356cfa000fc43c92ff0061212d1b161d
2022-09-01 14:55:27 0 [ERROR] InnoDB: Table `test`.`t2` contains unrecognizable instant ALTER metadatamariadbd: /mariadb/10.6/storage/innobase/dict/dict0load.cc:2464: dict_table_t* dict_load_table_one(const st_::span<const char>&, dict_err_ignore_t, dict_names_t&): Assertion `!table || (ignore_err & ~DICT_ERR_IGNORE_FK_NOKEY) || !table->is_readable() || !table->corrupted' failed.