Details
-
Bug
-
Status: In Progress (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.6, 10.11, 11.4, 11.8
-
Can result in hang or crash
Description
mleich produced an rr replay trace while testing MDEV-37244. I believe that this failure may affect any InnoDB version. Initially, I thought that this resembles MDEV-37659 but in fact this bug is a lot simpler.
ssh sdp
|
rr replay /data/results/1755521505/TBR-7321/1/rr/latest-trace
|
The scenario is that an INSERT INTO t2 statement (transaction 0x282e) in row_ins_scan_sec_index_for_duplicate() encounters a delete-marked secondary index record that it wants to lock. row_vers_impl_x_locked_low() is constructing older versions of the record in order to find out if the secondary index record could be implicitly locked, that is, point to a version of a PRIMARY KEY record whose DB_TRX_ID points to some active transaction.
Because the delete-marked secondary index record points to a (newer version) PRIMARY KEY entry that is implicitly (and exclusively) locked by the current transaction, we should be able to conclude that no other transaction can hold conflicting locks pointing to this PRIMARY KEY value in any index of the table. This is because any modification of the data must start from the clustered index (the PRIMARY KEY index). Would there be any conflicting explicit locks on any secondary indexes, the modification would be rolled back in every index.
It seems that we are doing quite a bit of busy work here:
|
11.4-MDEV-37244 87e2123ee42e6be2b5ec5e778c7f1f433f4b2051 |
mariadbd: /data/Server/11.4-MDEV-37244/storage/innobase/buf/buf0buf.cc:2259: buf_page_t* buf_page_get_zip(page_id_t): Assertion `state >= buf_page_t::UNFIXED' failed.
|
|
|
Thread 5 received signal SIGABRT, Aborted.
|
__pthread_kill_implementation (no_tid=0x0, signo=0x6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
|
warning: 44 ./nptl/pthread_kill.c: No such file or directory
|
(rr) set print frame-arguments none
|
(rr) bt
|
#0 __pthread_kill_implementation (no_tid=..., signo=..., threadid=...) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=..., threadid=...) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=..., signo=...) at ./nptl/pthread_kill.c:89
|
#3 0x0000782f5e64526e in __GI_raise (sig=...) at ../sysdeps/posix/raise.c:26
|
#4 0x0000782f5e6288ff in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x0000782f5e62881b in __assert_fail_base (fmt=..., assertion=..., file=..., line=..., function=...) at ./assert/assert.c:94
|
#6 0x0000782f5e63b507 in __assert_fail (assertion=..., file=..., line=..., function=...) at ./assert/assert.c:103
|
#7 0x00005d2c487cd2fc in buf_page_get_zip (page_id=...) at /data/Server/11.4-MDEV-37244/storage/innobase/buf/buf0buf.cc:2259
|
#8 0x00005d2c487b303f in btr_copy_zblob_prefix (buf=..., len=..., zip_size=..., id=..., offset=...) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:6568
|
#9 0x00005d2c487b3519 in btr_copy_externally_stored_field_prefix_low (buf=..., len=..., zip_size=..., id=..., offset=...) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:6682
|
#10 0x00005d2c487b366b in btr_copy_externally_stored_field_prefix (buf=..., len=..., zip_size=..., data=..., local_len=...) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:6734
|
#11 0x00005d2c4888635b in row_ext_cache_fill (ext=..., i=..., space=..., dfield=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ext.cc:78
|
#12 0x00005d2c48886596 in row_ext_create (n_ext=..., ext=..., table=..., tuple=..., heap=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ext.cc:128
|
#13 0x00005d2c4872546a in row_build_low (type=..., index=..., rec=..., offsets=..., col_table=..., defaults=..., add_v=..., col_map=..., ext=..., heap=...)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0row.cc:608
|
#14 0x00005d2c48725495 in row_build (type=..., index=..., rec=..., offsets=..., col_table=..., defaults=..., col_map=..., ext=..., heap=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0row.cc:667
|
#15 0x00005d2c4874b444 in row_vers_impl_x_locked_low (caller_trx=..., clust_rec=..., clust_index=..., rec=..., index=..., offsets=..., mtr=...)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0vers.cc:261
|
#16 0x00005d2c4874b5d1 in row_vers_impl_x_locked (caller_trx=..., rec=..., index=..., offsets=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0vers.cc:439
|
#17 0x00005d2c48630c4c in lock_sec_rec_some_has_impl (caller_trx=..., rec=..., index=..., offsets=...) at /data/Server/11.4-MDEV-37244/storage/innobase/lock/lock0lock.cc:1320
|
#18 0x00005d2c48637bd1 in lock_rec_convert_impl_to_expl<false> (caller_trx=..., block=..., rec=..., index=..., offsets=...) at /data/Server/11.4-MDEV-37244/storage/innobase/lock/lock0lock.cc:6229
|
#19 0x00005d2c4863a585 in lock_sec_rec_read_check_and_lock (flags=..., block=..., rec=..., index=..., offsets=..., mode=..., gap_mode=..., thr=...)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/lock/lock0lock.cc:6446
|
#20 0x00005d2c486e48e9 in row_ins_set_shared_rec_lock (type=..., block=..., rec=..., index=..., offsets=..., thr=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:1413
|
#21 0x00005d2c486eb6bb in row_ins_scan_sec_index_for_duplicate (flags=..., index=..., entry=..., thr=..., mtr=..., offsets_heap=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:2152
|
#22 0x00005d2c486ebe7a in row_ins_sec_index_entry_low (flags=..., mode=..., index=..., offsets_heap=..., heap=..., entry=..., trx_id=..., thr=...)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3134
|
#23 0x00005d2c486ec434 in row_ins_sec_index_entry (index=..., entry=..., thr=..., check_foreign=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3400
|
#24 0x00005d2c486edded in row_ins_index_entry (index=..., entry=..., thr=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3462
|
#25 0x00005d2c486ede9e in row_ins_index_entry_step (node=..., thr=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3626
|
#26 0x00005d2c486ee114 in row_ins (node=..., thr=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3743
|
#27 0x00005d2c486ee3ee in row_ins_step (thr=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3872
|
#28 0x00005d2c487066ae in row_insert_for_mysql (mysql_rec=..., prebuilt=..., ins_mode=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0mysql.cc:1300
|
#29 0x00005d2c485d7f7e in ha_innobase::write_row (this=..., record=...) at /data/Server/11.4-MDEV-37244/storage/innobase/handler/ha_innodb.cc:7823
|
...
|
(rr) frame 23
|
#23 0x00005d2c486ec434 in row_ins_sec_index_entry (index=..., entry=..., thr=..., check_foreign=...) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3400
|
3400 err = row_ins_sec_index_entry_low(
|
(rr) p/x thr.graph.trx.read_view
|
$18 = {<ReadViewBase> = {m_low_limit_id = 0x27bd, m_up_limit_id = 0x27ab, m_ids = std::__debug::vector of length 5, capacity 40 = {0x27ab, 0x27ae, 0x27b4, 0x27bb, 0x27bc}, m_low_limit_no = 0x27bd},
|
m_open = std::atomic<bool> = { 0x0 }, m_mutex = {lock = std::atomic<unsigned int> = { 0x0 }}, m_creator_trx_id = 0x0}
|
(rr) p/x purge_sys.view
|
$19 = {m_low_limit_id = 0x282b, m_up_limit_id = 0x280c, m_ids = std::__debug::vector of length 3, capacity 42 = {0x280c, 0x2815, 0x2825}, m_low_limit_no = 0x282b}
|
(rr) p/x purge_sys.end_view
|
$20 = {m_low_limit_id = 0x27f9, m_up_limit_id = 0x27d6, m_ids = std::__debug::vector of length 3, capacity 10 = {0x27d6, 0x27f3, 0x27f9}, m_low_limit_no = 0x27fa}
|
Above, we can see a further anomaly that the trx_t::read_view appears to be behind the purge_sys.view, which should be a clone of the latest active read view. Actually it turns out that ReadView::close() is merely clearing the m_open data member, which should take precedence over any "garbage" in the other fields. So, the read views are fine.
Let us see why we kept fetching older versions. It seems that in case the clust_rec belongs to the current transaction, row_vers_impl_x_locked_low() will unnecessarily and unsafely traverse the entire stack of versions. The following change ought to fix this:
diff --git a/storage/innobase/row/row0vers.cc b/storage/innobase/row/row0vers.cc
|
index b68f26576ab..bf0b73660ff 100644
|
--- a/storage/innobase/row/row0vers.cc
|
+++ b/storage/innobase/row/row0vers.cc
|
@@ -123,19 +123,20 @@ row_vers_impl_x_locked_low(
|
ULINT_UNDEFINED, &heap);
|
|
trx_id = row_get_rec_trx_id(clust_rec, clust_index, clust_offsets);
|
+ trx_t* trx = nullptr;
|
if (trx_id <= caller_trx->max_inactive_id) {
|
/* The transaction history was already purged. */
|
+ done:
|
mem_heap_free(heap);
|
- DBUG_RETURN(0);
|
+ DBUG_RETURN(trx);
|
}
|
|
ut_ad(!clust_index->table->is_temporary());
|
|
- trx_t* trx;
|
-
|
if (trx_id == caller_trx->id) {
|
trx = caller_trx;
|
trx->reference();
|
+ goto done;
|
} else {
|
trx = trx_sys.find(caller_trx, trx_id);
|
if (trx == 0) { |
All callers are prepared for this to return a pointer to the current transaction. The specific callers here are the following:
|
lock_rec_unlock_unmodified() |
trx_t *impl_trx=
|
lock_sec_rec_some_has_impl(lock->trx, rec, index, offsets);
|
/* row_vers_impl_x_locked_low() references trx in both cases, i.e. |
when caller trx is equal to trx, which modified the record, it
|
references the trx directly, otherwise it invokes trx_sys.find(),
|
which also references trx, so the trx must be released anyway. */
|
if (impl_trx) |
impl_trx->release_reference();
|
|
lock_rec_convert_impl_to_expl() |
trx = lock_sec_rec_some_has_impl(caller_trx, rec, index,
|
offsets);
|
if (trx == caller_trx) { |
trx->release_reference();
|
return trx; |
}
|
The latter function is part of the above crashing call stack. We would just be happy that no explicit lock needs to be created on behalf of another transaction. However, we would still create and attach a gap lock to the secondary index record, because lock_sec_rec_read_check_and_lock() was invoked with gap_mode=LOCK_ORDINARY.
Where did the purgeable record version come from?
The secondary index record had been delete-marked by a REPLACE INTO t2 statement that had been executed in an earlier transaction 0x2824 in another thread, using a different trx_t object. The history of that transaction had been purged while the later-crashing thread was still looking up the secondary index page:
|
11.4-MDEV-37244 87e2123ee42e6be2b5ec5e778c7f1f433f4b2051 |
Thread 17 hit Hardware watchpoint 1: -location $b.zip.fix.m._M_i
|
|
|
Old value = 0x4
|
New value = 0x3
|
buf_page_t::unfix (this=this@entry=0x782f3008b790) at /data/Server/11.4-MDEV-37244/storage/innobase/include/buf0buf.h:767
|
767 ut_ad(f > FREED);
|
(rr) bt
|
#0 buf_page_t::unfix (this=this@entry=0x782f3008b790) at /data/Server/11.4-MDEV-37244/storage/innobase/include/buf0buf.h:767
|
#1 0x00005d2c487e6596 in buf_LRU_free_page (bpage=bpage@entry=0x782f43814360, zip=zip@entry=0x0) at /data/Server/11.4-MDEV-37244/storage/innobase/buf/buf0lru.cc:937
|
#2 0x00005d2c487a6ba4 in btr_blob_free (block=block@entry=0x782f43814360, all=all@entry=0x1, mtr=mtr@entry=0x782f37dfefb0) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:5666
|
#3 0x00005d2c487b15c3 in btr_free_externally_stored_field (index=index@entry=0x782f180cbbc0, field_ref=0x782f43c9830e "", rec=rec@entry=0x0, offsets=offsets@entry=0x0, block=block@entry=0x782f4380e930,
|
i=i@entry=0x0, rollback=0x0, local_mtr=0x782f37dff3e0) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:6376
|
#4 0x00005d2c4871d3b4 in row_purge_upd_exist_or_extern_func (thr=thr@entry=0x5d2c4ae6bf68, node=node@entry=0x5d2c4ae6c008, undo_rec=undo_rec@entry=0x782f43c982e4 "\003>\215\004* ")
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0purge.cc:1225
|
#5 0x00005d2c4871d5b1 in row_purge_record_func (node=node@entry=0x5d2c4ae6c008, undo_rec=undo_rec@entry=0x782f43c982e4 "\003>\215\004* ", thr=thr@entry=0x5d2c4ae6bf68, updated_extern=0x1)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0purge.cc:1539
|
#6 0x00005d2c4871dace in row_purge (node=node@entry=0x5d2c4ae6c008, undo_rec=undo_rec@entry=0x782f43c982e4 "\003>\215\004* ", thr=thr@entry=0x5d2c4ae6bf68)
|
at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0purge.cc:1578
|
#7 0x00005d2c4871db2d in row_purge_step (thr=thr@entry=0x5d2c4ae6bf68) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0purge.cc:1641
|
#8 0x00005d2c486bb577 in que_thr_step (thr=thr@entry=0x5d2c4ae6bf68) at /data/Server/11.4-MDEV-37244/storage/innobase/que/que0que.cc:553
|
#9 0x00005d2c486bb758 in que_run_threads_low (thr=thr@entry=0x5d2c4ae6bf68) at /data/Server/11.4-MDEV-37244/storage/innobase/que/que0que.cc:609
|
#10 0x00005d2c486bb819 in que_run_threads (thr=thr@entry=0x5d2c4ae6bf68) at /data/Server/11.4-MDEV-37244/storage/innobase/que/que0que.cc:629
|
#11 0x00005d2c4874f2b3 in srv_task_execute () at /data/Server/11.4-MDEV-37244/storage/innobase/srv/srv0srv.cc:1349
|
#12 0x00005d2c4874f441 in srv_purge_worker_task_low () at /data/Server/11.4-MDEV-37244/storage/innobase/srv/srv0srv.cc:1480
|
#13 0x00005d2c4874f997 in purge_worker_callback () at /data/Server/11.4-MDEV-37244/storage/innobase/srv/srv0srv.cc:1491
|
...
|
(rr) thread apply 5 backtrace
|
|
|
Thread 5 (Thread 2016324.2021029 (mariadbd)):
|
...
|
#16 0x00005d2c487ced80 in buf_page_get_gen (page_id=page_id@entry=..., zip_size=zip_size@entry=0x2000, rw_latch=rw_latch@entry=RW_S_LATCH, guess=guess@entry=0x782f43811510, mode=mode@entry=0xa, mtr=mtr@entry=0x782f57fb21b0, err=0x782f57fb186c) at /data/Server/11.4-MDEV-37244/storage/innobase/buf/buf0buf.cc:2913
|
#17 0x00005d2c487b7cff in btr_cur_t::search_leaf (this=this@entry=0x782f57fb1dc0, tuple=tuple@entry=0x782f1cc7ede8, mode=mode@entry=PAGE_CUR_LE, latch_mode=<optimized out>, latch_mode@entry=BTR_MODIFY_LEAF, mtr=mtr@entry=0x782f57fb21b0) at /data/Server/11.4-MDEV-37244/storage/innobase/btr/btr0cur.cc:1227
|
#18 0x00005d2c486ebb44 in row_ins_sec_index_entry_low (flags=flags@entry=0x0, mode=mode@entry=BTR_MODIFY_LEAF, index=index@entry=0x782f380b4ef0, offsets_heap=<optimized out>, offsets_heap@entry=0x782f24123560, heap=heap@entry=0x782f2411b710, entry=entry@entry=0x782f1cc7ede8, trx_id=0x0, thr=0x5d2c4b3495d0) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3101
|
#19 0x00005d2c486ec434 in row_ins_sec_index_entry (index=index@entry=0x782f380b4ef0, entry=entry@entry=0x782f1cc7ede8, thr=thr@entry=0x5d2c4b3495d0, check_foreign=check_foreign@entry=0x1) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3400
|
#20 0x00005d2c486edded in row_ins_index_entry (index=0x782f380b4ef0, entry=0x782f1cc7ede8, thr=thr@entry=0x5d2c4b3495d0) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3462
|
#21 0x00005d2c486ede9e in row_ins_index_entry_step (node=node@entry=0x5d2c4b3490e0, thr=thr@entry=0x5d2c4b3495d0) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3626
|
#22 0x00005d2c486ee114 in row_ins (node=node@entry=0x5d2c4b3490e0, thr=thr@entry=0x5d2c4b3495d0) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3743
|
#23 0x00005d2c486ee3ee in row_ins_step (thr=thr@entry=0x5d2c4b3495d0) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0ins.cc:3872
|
#24 0x00005d2c487066ae in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x5d2c4b43de60 "\350\001", prebuilt=0x5d2c4b348b60, ins_mode=<optimized out>) at /data/Server/11.4-MDEV-37244/storage/innobase/row/row0mysql.cc:1300
|
#25 0x00005d2c485d7f7e in ha_innobase::write_row (this=0x5d2c4b43d648, record=0x5d2c4b43de60 "\350\001") at /data/Server/11.4-MDEV-37244/storage/innobase/handler/ha_innodb.cc:7823
|
When the crashing thread attempted to (unsafely) construct the second oldest version of the record that had actually been purged already, it hit the assertion failure when trying to fetch a BLOB page of the ROW_FORMAT=COMPRESSED table.
Attachments
Issue Links
- relates to
-
-
- Stalled
-
-
-
- Open
-