[MDEV-29519] InnoDB: Failing assertion: rec in storage/innobase/lock/lock0lock.cc line 5052 Created: 2022-09-12  Updated: 2022-09-14  Resolved: 2022-09-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.27
Fix Version/s: 10.6.8, 10.7.4, 10.8.3, 10.9.1

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Won't Fix Votes: 0
Labels: rr-profile-analyzed

Issue Links:
Blocks
is blocked by MDEV-15250 UPSERT during ALTER-TABLE results in ... Closed

 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>
 
 



 Comments   
Comment by Marko Mäkelä [ 2022-09-13 ]

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.

Comment by Marko Mäkelä [ 2022-09-13 ]

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).

Comment by Marko Mäkelä [ 2022-09-14 ]

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.

Comment by Marko Mäkelä [ 2022-09-14 ]

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.

Comment by Marko Mäkelä [ 2022-09-14 ]

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

Generated at Thu Feb 08 10:09:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.