[MDEV-29519] InnoDB: Failing assertion: rec in storage/innobase/lock/lock0lock.cc line 5052 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Won't Fix
Affects Version/s: 10.4.27
Fix Version/s: 10.7.4, 10.6.8, 10.8.3, 10.9.1
Component/s: Storage Engine - InnoDB
Labels:
- rr-profile-analyzed

Description

origin/bb-10.4-MDEV-23801 bc5145982fda084901e4f924e6ad563067649842 2022-09-12T14:08:54+03:00

Per Marko the bug is not related to modifications in his tree.

[rr 1615002 114191]2022-09-12 13:16:43 0x7f6d3f822300[rr 1615002 114194]  InnoDB: Assertion failure in file /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc line 5052

[rr 1615002 114196]InnoDB: Failing assertion: rec

Query (0x62b000292228): SHOW ENGINE INNODB STATUS

Status: NOT_KILLED

# 2022-09-12T13:20:18 [1608334] | Thread 3 (Thread 1615002.1626879):

# 2022-09-12T13:20:18 [1608334] | #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

# 2022-09-12T13:20:18 [1608334] | #1  0x00007f6d72444859 in __GI_abort () at abort.c:79

# 2022-09-12T13:20:18 [1608334] | #2  0x000055a5b9f453d8 in ut_dbg_assertion_failed (expr=0x55a5babe2000 "rec", file=0x55a5babe55c0 "/data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc", line=5052) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/ut/ut0dbg.cc:60

# 2022-09-12T13:20:18 [1608334] | #3  0x000055a5b9bb5f8e in lock_rec_validate_page (block=0x7f6d65a03898) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5052

# 2022-09-12T13:20:18 [1608334] | #4  0x000055a5b9bb6940 in lock_rec_block_validate (space_id=0, page_no=1089) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5162

# 2022-09-12T13:20:18 [1608334] | #5  0x000055a5b9bb723e in lock_validate () at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5236

# 2022-09-12T13:20:18 [1608334] | #6  0x000055a5b9bb34df in lock_print_info_all_transactions (file=0x615000002380) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:4738

# 2022-09-12T13:20:18 [1608334] | #7  0x000055a5b9e6dab5 in srv_printf_innodb_monitor (file=0x615000002380, nowait=0, trx_start_pos=0x7f6d3f81ec40, trx_end=0x7f6d3f81ec60) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/srv/srv0srv.cc:1233

# 2022-09-12T13:20:18 [1608334] | #8  0x000055a5b9a69934 in innodb_show_status (hton=0x614000001848, thd=0x62b00028b208, stat_print=0x55a5b91ae6a2 <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/handler/ha_innodb.cc:15873

# 2022-09-12T13:20:18 [1608334] | #9  0x000055a5b9a6af16 in innobase_show_status (hton=0x614000001848, thd=0x62b00028b208, stat_print=0x55a5b91ae6a2 <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>, stat_type=HA_ENGINE_STATUS) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/handler/ha_innodb.cc:16286

# 2022-09-12T13:20:18 [1608334] | #10 0x000055a5b91aef14 in ha_show_status (thd=0x62b00028b208, db_type=0x614000001848, stat=HA_ENGINE_STATUS) at /data/Server/bb-10.4-MDEV-23801/sql/handler.cc:6281

# 2022-09-12T13:20:18 [1608334] | #11 0x000055a5b8a81f4c in mysql_execute_command (thd=0x62b00028b208) at /data/Server/bb-10.4-MDEV-23801/sql/sql_parse.cc:4203

pluto:/data/results/1662985267/TBR-1432--TBR-810--TBR-801$ _RR_TRACE_DIR=./1/rr/ rr replay

# 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_nocopy1.yy \

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

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

# --reporters=Mariabackup_linux \

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

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

# --mysqld=--innodb_stats_persistent=on \

# --mysqld=--innodb_adaptive_hash_index=on \

# --mysqld=--log-bin \

# --mysqld=--sync-binlog=1 \

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

# --mysqld=--loose_innodb_change_buffering=purges \

# --vardir_type=slow \

# --mysqld=--innodb_page_size=4K \

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

# <local settings>

Attachments

Issue Links

is blocked by

MDEV-15250 UPSERT during ALTER-TABLE results in 'Duplicate entry' error for alter

Closed

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2022-09-13 10:25

The assertion fails because a record lock bitmap points to a BLOB page instead of a B-tree page. At the time the record lock was acquired, the page belonged to an uncommitted UNIQUE INDEX that had been constructed, but the ALTER TABLE…ADD UNIQUE INDEX was waiting for an exclusive metadata lock so that the change could be committed. What happened was that the ALTER TABLE was rolled back due to the duplicate key error. As part of this, the secondary index tree was freed, but the related record locks were not discarded.

While the rr replay trace of the failure involved a table that had been created without an .ibd file (innodb_file_per_table=0), I think that this scenario is perfectly possible with normal .ibd files as well. All we should need is some later reuse of the pages that had been allocated for the uncommitted secondary index, before the lock-holding transaction is committed.

Here is some analysis from the trace:

ssh pluto

rr replay /data/results/1662985267/TBR-1432--TBR-810--TBR-801/1/rr/latest-trace

continue

watch -l -lock_sys.rec_hash.array[6209]

frame 3

print lock->trx->id

reverse-continue

reverse-continue

continue

frame 3

print thr->graph->trx->id

watch -l *(char*)0x7f6d65ac921e

continue

backtrace

bb-10.4-MDEV-23801 bc5145982fda084901e4f924e6ad563067649842
…
(rr) frame 3
#3 0x000055a5b9bb5f8e in lock_rec_validate_page (block=0x7f6d65a03898)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5052
5052 ut_a(rec);
(rr) p lock->trx->id
$1 = 1262
…
(rr) continue
Continuing.

Thread 57 hit Hardware watchpoint 1: -location lock_sys.rec_hash.array[6209]

Old value = {node = 0x0}
New value = {node = 0x7f6d65f5e460}
0x000055a5b9ba0092 in lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=3,
space=0, page_no=1089, page=0x7f6d65b57000 "", heap_no=7,
index=0x6170002b5808, trx=0x7f6d65f5ddd8, holds_trx_mutex=false)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:1492
1492 HASH_INSERT(lock_t, hash, lock_hash_get(type_mode),
(rr) frame 3
#3 0x000055a5b9bbb02d in lock_sec_rec_read_check_and_lock (flags=0,
block=0x7f6d65a03898, rec=0x7f6d65b570e8 "\200", index=0x6170002b5808,
offsets=0x7f6d3ed4b890, mode=LOCK_X, gap_mode=0, thr=0x621000d6f8d8)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5823
(rr) print thr->graph->trx->id
$2 = 1262
(rr) backtrace
…
#4 0x000055a5b9d43648 in row_ins_set_exclusive_rec_lock (type=0,
block=0x7f6d65a03898, rec=0x7f6d65b570e8 "\200", index=0x6170002b5808,
offsets=0x7f6d3ed4b890, thr=0x621000d6f8d8)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/row/row0ins.cc:1439
#5 0x000055a5b9d46539 in row_ins_scan_sec_index_for_duplicate (flags=0,
index=0x6170002b5808, entry=0x61a0006032e0, thr=0x621000d6f8d8,
s_latch=true, mtr=0x7f6d3ed4c000, offsets_heap=0x619000d6f180)
…
#18 0x000055a5b8a9b6fc in mysql_parse (thd=0x62b0002ae208,
rawbuf=0x62b0002b5228 "REPLACE INTO t1 (col1,col2, col_int, col_string, col_text) VALUES /* 7 */ (7,7,7,REPEAT(SUBSTR(CAST( 7 AS CHAR),1,1), 10),REPEAT(SUBSTR(CAST( 7 AS CHAR),1,1), @fill_amount) ), (7,7,7,REPEAT(SUBSTR(CAS"...,
…
(rr) watch -l (char)0x7f6d65ac921e
Hardware watchpoint 2: -location (char)0x7f6d65ac921e
(rr) continue
Continuing.
[Switching to Thread 1615002.1627206]

Thread 58 hit Hardware watchpoint 2: -location (char)0x7f6d65ac921e

Old value = -22 '\352'
New value = -18 '\356'
mach_write_to_1 (b=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>, n=238)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/include/mach0data.inl:44
44 }
(rr) backtrace
#0 mach_write_to_1 (b=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>,
n=238)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/include/mach0data.inl:44
#1 0x000055a5b9c20b63 in mlog_write_ulint (
ptr=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>, val=238,
type=MLOG_1BYTE, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/mtr/mtr0log.cc:260
#2 0x000055a5ba18d5fe in xdes_set_bit (descr=0x7f6d65ac91f6 "", bit=0,
offset=65, val=1, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:211
#3 0x000055a5ba19498c in fsp_free_page (space=0x614000001a40, offset=1089,
log=true, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:1340
#4 0x000055a5ba19bf35 in fseg_free_page_low (seg_inode=0x7f6d65b1e6f2 "",
space=0x614000001a40, offset=1089, log=true, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:2739
#5 0x000055a5ba19dae3 in fseg_free_step (header=0x7f6d65b57054 "",
mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:2984
#6 0x000055a5b9f5e49c in btr_free_root (block=0x7f6d65a03898,
mtr=0x7f6d3e989de0, invalidate=true)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/btr/btr0btr.cc:1018
#7 0x000055a5b9f5f6e9 in btr_free_if_exists (page_id=..., zip_size=0,
index_id=48, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/btr/btr0btr.cc:1288
#8 0x000055a5ba0ab4fc in dict_drop_index_tree (rec=0x7f6d65b5bb21 "",
pcur=0x6280000011e0, trx=0x7f6d65f5bbe8, mtr=0x7f6d3e989de0)
at /data/Server/bb-10.4-MDEV-23801/storage/innobase/dict/dict0crea.cc:955
…
#21 0x000055a5b91a45d0 in handler::ha_commit_inplace_alter_table (this=0x61d001647ca8, altered_table=0x7f6d3e98dd70, ha_alter_info=0x7f6d3e98c5c0, commit=false) at /data/Server/bb-10.4-MDEV-23801/sql/handler.cc:4672
#22 0x000055a5b8cb664b in mysql_inplace_alter_table (thd=0x62b0002bc208, table_list=0x62b0002c3468, table=0x6200001ad088, altered_table=0x7f6d3e98dd70, ha_alter_info=0x7f6d3e98c5c0, target_mdl_request=0x7f6d3e98c6a0, alter_ctx=0x7f6d3e98d280) at /data/Server/bb-10.4-MDEV-23801/sql/sql_table.cc:7996

Furthermore, we can observe that at the time SHOW ENGINE INNODB STATUS executed lock_validate(), transaction 1292 was still active, waiting for a page latch while continuing to executing the same REPLACE statement. After the index page 1089 was freed, it was reallocated for a BLOB page, and the record locks of transaction 1292 would point to a non-index page, causing the assertion failure.

Marko Mäkelä added a comment - 2022-09-13 10:25 The assertion fails because a record lock bitmap points to a BLOB page instead of a B-tree page. At the time the record lock was acquired, the page belonged to an uncommitted UNIQUE INDEX that had been constructed, but the ALTER TABLE…ADD UNIQUE INDEX was waiting for an exclusive metadata lock so that the change could be committed. What happened was that the ALTER TABLE was rolled back due to the duplicate key error. As part of this, the secondary index tree was freed, but the related record locks were not discarded. While the rr replay trace of the failure involved a table that had been created without an .ibd file ( innodb_file_per_table=0 ), I think that this scenario is perfectly possible with normal .ibd files as well. All we should need is some later reuse of the pages that had been allocated for the uncommitted secondary index, before the lock-holding transaction is committed. Here is some analysis from the trace: ssh pluto rr replay /data/results/1662985267/TBR-1432--TBR-810--TBR-801/1/rr/latest-trace continue watch -l -lock_sys.rec_hash.array[6209] frame 3 print lock->trx->id reverse-continue reverse-continue continue frame 3 print thr->graph->trx->id watch -l *(char*)0x7f6d65ac921e continue backtrace bb-10.4-MDEV-23801 bc5145982fda084901e4f924e6ad563067649842 … (rr) frame 3 #3 0x000055a5b9bb5f8e in lock_rec_validate_page (block=0x7f6d65a03898) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5052 5052 ut_a(rec); (rr) p lock->trx->id $1 = 1262 … (rr) continue Continuing. Thread 57 hit Hardware watchpoint 1: -location lock_sys.rec_hash.array[6209] Old value = {node = 0x0} New value = {node = 0x7f6d65f5e460} 0x000055a5b9ba0092 in lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=3, space=0, page_no=1089, page=0x7f6d65b57000 "", heap_no=7, index=0x6170002b5808, trx=0x7f6d65f5ddd8, holds_trx_mutex=false) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:1492 1492 HASH_INSERT(lock_t, hash, lock_hash_get(type_mode), (rr) frame 3 #3 0x000055a5b9bbb02d in lock_sec_rec_read_check_and_lock (flags=0, block=0x7f6d65a03898, rec=0x7f6d65b570e8 "\200", index=0x6170002b5808, offsets=0x7f6d3ed4b890, mode=LOCK_X, gap_mode=0, thr=0x621000d6f8d8) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/lock/lock0lock.cc:5823 (rr) print thr->graph->trx->id $2 = 1262 (rr) backtrace … #4 0x000055a5b9d43648 in row_ins_set_exclusive_rec_lock (type=0, block=0x7f6d65a03898, rec=0x7f6d65b570e8 "\200", index=0x6170002b5808, offsets=0x7f6d3ed4b890, thr=0x621000d6f8d8) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/row/row0ins.cc:1439 #5 0x000055a5b9d46539 in row_ins_scan_sec_index_for_duplicate (flags=0, index=0x6170002b5808, entry=0x61a0006032e0, thr=0x621000d6f8d8, s_latch=true, mtr=0x7f6d3ed4c000, offsets_heap=0x619000d6f180) … #18 0x000055a5b8a9b6fc in mysql_parse (thd=0x62b0002ae208, rawbuf=0x62b0002b5228 "REPLACE INTO t1 (col1,col2, col_int, col_string, col_text) VALUES /* 7 */ (7,7,7,REPEAT(SUBSTR(CAST( 7 AS CHAR),1,1), 10),REPEAT(SUBSTR(CAST( 7 AS CHAR),1,1), @fill_amount) ), (7,7,7,REPEAT(SUBSTR(CAS"..., … (rr) watch -l *(char*)0x7f6d65ac921e Hardware watchpoint 2: -location *(char*)0x7f6d65ac921e (rr) continue Continuing. [Switching to Thread 1615002.1627206] Thread 58 hit Hardware watchpoint 2: -location *(char*)0x7f6d65ac921e Old value = -22 '\352' New value = -18 '\356' mach_write_to_1 (b=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>, n=238) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/include/mach0data.inl:44 44 } (rr) backtrace #0 mach_write_to_1 (b=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>, n=238) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/include/mach0data.inl:44 #1 0x000055a5b9c20b63 in mlog_write_ulint ( ptr=0x7f6d65ac921e "\356\373", '\377' <repeats 46 times>, val=238, type=MLOG_1BYTE, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/mtr/mtr0log.cc:260 #2 0x000055a5ba18d5fe in xdes_set_bit (descr=0x7f6d65ac91f6 "", bit=0, offset=65, val=1, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:211 #3 0x000055a5ba19498c in fsp_free_page (space=0x614000001a40, offset=1089, log=true, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:1340 #4 0x000055a5ba19bf35 in fseg_free_page_low (seg_inode=0x7f6d65b1e6f2 "", space=0x614000001a40, offset=1089, log=true, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:2739 #5 0x000055a5ba19dae3 in fseg_free_step (header=0x7f6d65b57054 "", mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/fsp/fsp0fsp.cc:2984 #6 0x000055a5b9f5e49c in btr_free_root (block=0x7f6d65a03898, mtr=0x7f6d3e989de0, invalidate=true) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/btr/btr0btr.cc:1018 #7 0x000055a5b9f5f6e9 in btr_free_if_exists (page_id=..., zip_size=0, index_id=48, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/btr/btr0btr.cc:1288 #8 0x000055a5ba0ab4fc in dict_drop_index_tree (rec=0x7f6d65b5bb21 "", pcur=0x6280000011e0, trx=0x7f6d65f5bbe8, mtr=0x7f6d3e989de0) at /data/Server/bb-10.4-MDEV-23801/storage/innobase/dict/dict0crea.cc:955 … #21 0x000055a5b91a45d0 in handler::ha_commit_inplace_alter_table (this=0x61d001647ca8, altered_table=0x7f6d3e98dd70, ha_alter_info=0x7f6d3e98c5c0, commit=false) at /data/Server/bb-10.4-MDEV-23801/sql/handler.cc:4672 #22 0x000055a5b8cb664b in mysql_inplace_alter_table (thd=0x62b0002bc208, table_list=0x62b0002c3468, table=0x6200001ad088, altered_table=0x7f6d3e98dd70, ha_alter_info=0x7f6d3e98c5c0, target_mdl_request=0x7f6d3e98c6a0, alter_ctx=0x7f6d3e98d280) at /data/Server/bb-10.4-MDEV-23801/sql/sql_table.cc:7996 Furthermore, we can observe that at the time SHOW ENGINE INNODB STATUS executed lock_validate() , transaction 1292 was still active, waiting for a page latch while continuing to executing the same REPLACE statement. After the index page 1089 was freed, it was reallocated for a BLOB page, and the record locks of transaction 1292 would point to a non-index page, causing the assertion failure.

Marko Mäkelä added a comment - 2022-09-13 10:55

I tried and so far failed to reproduce the crash with the following:

--source include/have_innodb.inc

--source include/have_debug.inc

--source include/have_debug_sync.inc

CREATE TABLE t1 (c1 INT PRIMARY KEY, c2 INT NOT NULL, c3 TEXT NOT NULL)

ENGINE=InnoDB STATS_PERSISTENT=0;

INSERT INTO t1 VALUES (1,1,'');

connect con1,localhost,root;

SET lock_wait_timeout=2;

SET DEBUG_SYNC='row_log_apply_after SIGNAL created WAIT_FOR dml_done';

--send

ALTER TABLE t1 ADD UNIQUE INDEX(c2);

connection default;

SET DEBUG_SYNC = 'now WAIT_FOR created';

BEGIN;

INSERT INTO t1 VALUES(2,2,'');

REPLACE t1 VALUES (1,2,'');

SET DEBUG_SYNC = 'now SIGNAL dml_done';

connection con1;

--error ER_LOCK_WAIT_TIMEOUT,ER_DUP_ENTRY

reap;

connection default;

SET DEBUG_SYNC=RESET;

UPDATE t1 SET c3=REPEAT('a quick brown fox jumped over a lazy dog',1000);

connection con1;

SHOW ENGINE INNODB STATUS;

disconnect con1;

connection default;

COMMIT;

DROP TABLE t1;

The function lock_rec_block_validate() was only invoked on page 3 of the tablespace (the clustered index root page), not on a secondary index page (page 4).

Marko Mäkelä added a comment - 2022-09-13 10:55 I tried and so far failed to reproduce the crash with the following: --source include/have_innodb.inc --source include/have_debug.inc --source include/have_debug_sync.inc CREATE TABLE t1 (c1 INT PRIMARY KEY , c2 INT NOT NULL , c3 TEXT NOT NULL ) ENGINE=InnoDB STATS_PERSISTENT=0; INSERT INTO t1 VALUES (1,1, '' ); connect con1,localhost,root; SET lock_wait_timeout=2; SET DEBUG_SYNC= 'row_log_apply_after SIGNAL created WAIT_FOR dml_done' ; --send ALTER TABLE t1 ADD UNIQUE INDEX (c2); connection default ; SET DEBUG_SYNC = 'now WAIT_FOR created' ; BEGIN ; INSERT INTO t1 VALUES (2,2, '' ); REPLACE t1 VALUES (1,2, '' ); SET DEBUG_SYNC = 'now SIGNAL dml_done' ; connection con1; --error ER_LOCK_WAIT_TIMEOUT,ER_DUP_ENTRY reap; connection default ; SET DEBUG_SYNC=RESET; UPDATE t1 SET c3=REPEAT( 'a quick brown fox jumped over a lazy dog' ,1000); connection con1; SHOW ENGINE INNODB STATUS; disconnect con1; connection default ; COMMIT ; DROP TABLE t1; The function lock_rec_block_validate() was only invoked on page 3 of the tablespace (the clustered index root page), not on a secondary index page (page 4).

Marko Mäkelä added a comment - 2022-09-14 10:51

It turns out that my above test crashes 10.4 just fine:

10.4 3e3cfa893481abe9524a1657c4246fa9f91d4826
#5 0x00007f2476836b02 in __GI___assert_fail (
assertion=0x5645b04bccef "field_value < srv_page_size",
file=0x5645b04cafb4 "/mariadb/10.4/storage/innobase/include/rem0rec.inl",
line=342,
function=0x5645b0557756 "ulint rec_get_next_offs(const rec_t *, ulint)")
at ./assert/assert.c:101
#6 0x00005645b14b9663 in rec_get_next_offs (rec=<optimized out>, comp=0)
at /mariadb/10.4/storage/innobase/include/rem0rec.inl:342
#7 page_find_rec_with_heap_no (page=0x7f246b930000 "",
heap_no=heap_no@entry=1)
at /mariadb/10.4/storage/innobase/page/page0page.cc:2813
--Type <RET> for more, q to quit, c to continue without paging--
#8 0x00005645b1457c90 in lock_rec_validate_page (block=0x7f246b42bc50)
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5051
#9 lock_rec_block_validate (space_id=<optimized out>, page_no=<optimized out>)
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5162
#10 lock_validate () at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5236
#11 lock_print_info_all_transactions (file=file@entry=0x5645b44624e0)
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:4738
#12 0x00005645b15b2763 in srv_printf_innodb_monitor (file=0x5645b44624e0,
nowait=nowait@entry=0, trx_start_pos=trx_start_pos@entry=0x7f24680abe50,
trx_end=trx_end@entry=0x7f24680abe48)
at /mariadb/10.4/storage/innobase/srv/srv0srv.cc:1233

I think that I was previously using 10.6 or a later branch.

Marko Mäkelä added a comment - 2022-09-14 10:51 It turns out that my above test crashes 10.4 just fine: 10.4 3e3cfa893481abe9524a1657c4246fa9f91d4826 #5 0x00007f2476836b02 in __GI___assert_fail ( assertion=0x5645b04bccef "field_value < srv_page_size", file=0x5645b04cafb4 "/mariadb/10.4/storage/innobase/include/rem0rec.inl", line=342, function=0x5645b0557756 "ulint rec_get_next_offs(const rec_t *, ulint)") at ./assert/assert.c:101 #6 0x00005645b14b9663 in rec_get_next_offs (rec=<optimized out>, comp=0) at /mariadb/10.4/storage/innobase/include/rem0rec.inl:342 #7 page_find_rec_with_heap_no (page=0x7f246b930000 "", heap_no=heap_no@entry=1) at /mariadb/10.4/storage/innobase/page/page0page.cc:2813 --Type <RET> for more, q to quit, c to continue without paging-- #8 0x00005645b1457c90 in lock_rec_validate_page (block=0x7f246b42bc50) at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5051 #9 lock_rec_block_validate (space_id=<optimized out>, page_no=<optimized out>) at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5162 #10 lock_validate () at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5236 #11 lock_print_info_all_transactions (file=file@entry=0x5645b44624e0) at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:4738 #12 0x00005645b15b2763 in srv_printf_innodb_monitor (file=0x5645b44624e0, nowait=nowait@entry=0, trx_start_pos=trx_start_pos@entry=0x7f24680abe50, trx_end=trx_end@entry=0x7f24680abe48) at /mariadb/10.4/storage/innobase/srv/srv0srv.cc:1233 I think that I was previously using 10.6 or a later branch.

Marko Mäkelä added a comment - 2022-09-14 11:30

In 10.4, REPLACE would acquire a lock on the secondary index page (page number 4):

10.4 3e3cfa893481abe9524a1657c4246fa9f91d4826
#0 lock_rec_create_low (c_lock=c_lock@entry=0x0, thr=0x0, type_mode=3,
space=5, page_no=4, page=0x7f246b930000 "", heap_no=139794206338048,
…
#4 0x00005645b151b142 in row_ins_set_exclusive_rec_lock (type=type@entry=0,
block=block@entry=0x7f246b42bc50, rec=rec@entry=0x7f246b93008a "\200",
index=index@entry=0x7f246002ac00, offsets=offsets@entry=0x7f24680f6870,
thr=thr@entry=0x7f245806b908)
at /mariadb/10.4/storage/innobase/row/row0ins.cc:1439
#5 0x00005645b1514b15 in row_ins_scan_sec_index_for_duplicate (flags=0,
flags@entry=139794206338048, index=index@entry=0x7f246002ac00,
entry=0x7f245806fae0, entry@entry=0x7f24680f7bd0, thr=0x7f245806b908,
s_latch=<optimized out>, mtr=0x7f24680f7558, mtr@entry=0x7f24680f7550,
offsets_heap=0x7f245806fef0)
at /mariadb/10.4/storage/innobase/row/row0ins.cc:2147

The reason why 10.6 does not crash is that ~~MDEV-15250~~ made row_upd() skip indexes that are not committed, so no lock on the secondary index page will ever be acquired. Any log for uncommitted indexes will be processed in UndorecApplier::log_insert() or UndorecApplier::log_update(), either by writing records to the online_log, or by applying the changes directly to the completed but uncommitted index. In other words, this bug was fixed by ~~MDEV-15250~~.

Marko Mäkelä added a comment - 2022-09-14 11:30 In 10.4, REPLACE would acquire a lock on the secondary index page (page number 4): 10.4 3e3cfa893481abe9524a1657c4246fa9f91d4826 #0 lock_rec_create_low (c_lock=c_lock@entry=0x0, thr=0x0, type_mode=3, space=5, page_no=4, page=0x7f246b930000 "", heap_no=139794206338048, … #4 0x00005645b151b142 in row_ins_set_exclusive_rec_lock (type=type@entry=0, block=block@entry=0x7f246b42bc50, rec=rec@entry=0x7f246b93008a "\200", index=index@entry=0x7f246002ac00, offsets=offsets@entry=0x7f24680f6870, thr=thr@entry=0x7f245806b908) at /mariadb/10.4/storage/innobase/row/row0ins.cc:1439 #5 0x00005645b1514b15 in row_ins_scan_sec_index_for_duplicate (flags=0, flags@entry=139794206338048, index=index@entry=0x7f246002ac00, entry=0x7f245806fae0, entry@entry=0x7f24680f7bd0, thr=0x7f245806b908, s_latch=<optimized out>, mtr=0x7f24680f7558, mtr@entry=0x7f24680f7550, offsets_heap=0x7f245806fef0) at /mariadb/10.4/storage/innobase/row/row0ins.cc:2147 The reason why 10.6 does not crash is that MDEV-15250 made row_upd() skip indexes that are not committed, so no lock on the secondary index page will ever be acquired. Any log for uncommitted indexes will be processed in UndorecApplier::log_insert() or UndorecApplier::log_update() , either by writing records to the online_log , or by applying the changes directly to the completed but uncommitted index. In other words, this bug was fixed by MDEV-15250 .

Marko Mäkelä added a comment - 2022-09-14 11:32

I do not think that it is feasible to fix this bug in earlier versions than MariaDB Server 10.6.

Marko Mäkelä added a comment - 2022-09-14 11:32 I do not think that it is feasible to fix this bug in earlier versions than MariaDB Server 10.6.

MariaDB Server

InnoDB: Failing assertion: rec in storage/innobase/lock/lock0lock.cc line 5052

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration