| Bug #85765 | Assert !rw_lock_own(lock, RW_LOCK_S) rw_lock_s_lock_func in include/sync0rw.ic | ||
|---|---|---|---|
| Submitted: | 3 Apr 2017 7:43 | Modified: | 13 Oct 2017 16:49 |
| Reporter: | Shipra Jain | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 8.0.2 (trunk) | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[7 Apr 2017 7:12]
Naga Satyanarayana Bodapati
Posted by developer:
This is case where a page is latched twice by the same thread. We don't allow recursive S_latch.
This kind of latching can only happen with ICP.
On why we need this latch across with ICP, according to Jimmy on channel
(05:28:52 IST) jimmy.yang: basically, when we find a record, we latch the page, making a copy of it, and then send it to server, release the latch. Then server ask for another record, then do join etc.
(05:29:12 IST) jimmy.yang: so each time, we fetch a record etc.
(05:30:15 IST) jimmy.yang: when ICP comes, it might do some screening etc. all in InnoDB, so it might involve multiple records. To keep the correctness of the records, the pages holding those records have to be kept latched
(05:31:33 IST) jimmy.yang: and if it involves operations between multiple records that eventually leads to the same page, then such multiple attempt of latching the same page could happened
But if you observe, the second entry to InnoDB is for reading DD tables. This uses attachable trx.
gdb) f 41
#41 0x00000000029553b1 in row_search_mvcc (buf=0x7f4770335d30 "\350\037\241\026", mode=PAGE_CUR_GE, prebuilt=0x7f4770376cc8, match_mode=1, direction=0)
at /log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc:5677
5677 switch (row_search_idx_cond_check(buf, prebuilt, rec, offsets)) {
(gdb) p prebuilt->trx
$16 = (trx_t *) 0x7f4807200b00
(gdb) p prebuilt->trx->id
$17 = 0
(gdb) p prebuilt->trx->is_dd_trx
$18 = false
(gdb)
f 41
gdb) p prebuilt->index->name
$7 = {m_name = 0x7f4800611e38 "schema_id"}
(gdb) p prebuilt->index->table->name
$8 = {m_name = 0x7f48005f4b98 "mysql/tables"}
gdb) f 12
#12 0x0000000002953c6c in row_search_mvcc (buf=0x7f477353f320 "", mode=PAGE_CUR_GE, prebuilt=0x7f4770361ce8, match_mode=1, direction=0)
at /log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc:5081
5081 pcur, 0, &mtr);
(gdb) p prebuilt->trx
$13 = (trx_t *) 0x7f48072024b0
(gdb) p prebuilt->trx->id
$14 = 0
(gdb) p prebuilt->trx->is_dd_trx
$15 = true
gdb) f 12
#12 0x0000000002953c6c in row_search_mvcc (buf=0x7f477353f320 "", mode=PAGE_CUR_GE, prebuilt=0x7f4770361ce8, match_mode=1, direction=0)
at /log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc:5081
5081 pcur, 0, &mtr);
(gdb) p prebuilt->index->name
$11 = {m_name = 0x7f4800611e38 "schema_id"}
(gdb) p prebuilt->index->table->name
$12 = {m_name = 0x7f48005f4b98 "mysql/tables"}
f 12 -> second entry (attachable trx)
f 41 -> first entry (normal trx)
So the second read is indeed read caused by attachable trxs. Then why this assert happened?
To check if rw_lock is already latched, we use thread_id. Since thread_id is same, we think it is being latched twice by same thread.
Acc to Jimmy "block latch is not particular to trx". So even though we use attachable trx, it is still considered as same thread.
[7 Apr 2017 7:14]
Naga Satyanarayana Bodapati
Posted by developer:
rw_lock_own used thread_id. See here
rw_lock_own(
/*========*/
rw_lock_t* lock, /*!< in: rw-lock */
ulint lock_type) /*!< in: lock type: RW_LOCK_S,
RW_LOCK_X */
{
ut_ad(lock);
ut_ad(rw_lock_validate(lock));
rw_lock_debug_mutex_enter();
for (const rw_lock_debug_t* info = UT_LIST_GET_FIRST(lock->debug_list);
info != NULL;
info = UT_LIST_GET_NEXT(list, info)) {
if (os_thread_eq(info->thread_id, os_thread_get_curr_id())
&& info->pass == 0
&& info->lock_type == lock_type) {
rw_lock_debug_mutex_exit();
/* Found! */
return(TRUE);
}
}
rw_lock_debug_mutex_exit();
return(FALSE);
}
[16 Oct 2017 12:47]
Paul DuBois
Fixed in 8.0.4, 9.0.0. Queries on the INFORMATION_SCHEMA TABLES and STATISTICS tables, if evaluated using Index Condition Pushdown, could push down internal data dictionary funtions, resulting in an assertion being raised.
Description: Assert !rw_lock_own(lock, RW_LOCK_S) rw_lock_s_lock_func in include/sync0rw.ic Seen on mysql-trunk with latest commit as Revision-Id: tor.didriksen@oracle.com-73c2befa4cf312130052cf186c091b7a549a0395 (31st Mar 2017) #6 0x00000000029e8a29 in ut_dbg_assertion_failed (expr=0x366e714 "!rw_lock_own(lock, RW_LOCK_S)", file=0x366e6b0 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/include/sync0rw.ic", line=426) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/ut/ut0dbg.cc:60 #7 0x0000000002a49f26 in rw_lock_s_lock_func (lock=0x7f4806c6b230, pass=0, file_name=0x3630538 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc", line=5081) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/include/sync0rw.ic:426 #8 0x0000000002a4a945 in pfs_rw_lock_s_lock_func (lock=0x7f4806c6b230, pass=0, file_name=0x3630538 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc", line=5081) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/include/sync0rw.ic:802 #9 0x0000000002a589b6 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x3630538 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc", line=5081, mtr=0x7f48040c5280, dirty_with_no_latch=false) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/buf/buf0buf.cc:4001 #10 0x0000000002a254b8 in btr_cur_search_to_nth_level (index=0x7f4800611b08, level=0, tuple=0x7f4770362170, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7f4770361f40, has_search_latch=0, file=0x3630538 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc", line=5081, mtr=0x7f48040c5280) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/btr/btr0cur.cc:1036 #11 0x000000000294950d in btr_pcur_open_with_no_init_func (index=0x7f4800611b08, tuple=0x7f4770362170, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7f4770361f40, has_search_latch=0, file=0x3630538 "/log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc", line=5081, mtr=0x7f48040c5280) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/include/btr0pcur.ic:521 #12 0x0000000002953c6c in row_search_mvcc (buf=0x7f477353f320 "", mode=PAGE_CUR_GE, prebuilt=0x7f4770361ce8, match_mode=1, direction=0) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/row/row0sel.cc:5081 #13 0x00000000027bcb97 in ha_innobase::index_read (this=0x7f47703f3e40, buf=0x7f477353f320 "", key_ptr=0x7f4770244a40 "\003", key_len=202, find_flag=HA_READ_KEY_EXACT) at /log/RQG/shipjain/trunkvigdis28/storage/innobase/handler/ha_innodb.cc:9318 #14 0x0000000001ea63b4 in handler::index_read_map (this=0x7f47703f3e40, buf=0x7f477353f320 "", key=0x7f4770244a40 "\003", keypart_map=18446744073709551615, find_flag=HA_READ_KEY_EXACT) at /log/RQG/shipjain/trunkvigdis28/sql/handler.h:3939 #15 0x0000000001ea2d16 in handler::index_read_idx_map (this=0x7f47703f3e40, buf=0x7f477353f320 "", index=1, key=0x7f4770244a40 "\003", keypart_map=18446744073709551615, find_flag=HA_READ_KEY_EXACT) at /log/RQG/shipjain/trunkvigdis28/sql/handler.cc:7897 #16 0x0000000001e98fb7 in handler::ha_index_read_idx_map (this=0x7f47703f3e40, buf=0x7f477353f320 "", index=1, key=0x7f4770244a40 "\003", keypart_map=18446744073709551615, find_flag=HA_READ_KEY_EXACT) at /log/RQG/shipjain/trunkvigdis28/sql/handler.cc:3342 #17 0x0000000001cca5e0 in dd::Raw_table::find_record (this=0x7f47702d1db0, key=..., r=std::unique_ptr<dd::Raw_record> containing 0x0) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/raw/raw_table.cc:82 #18 0x0000000001cb6710 in dd::cache::Storage_adapter::get<dd::Item_name_key, dd::Abstract_table> (thd=0x7f4770000be0, key=..., isolation=ISO_READ_COMMITTED, object=0x7f48040c63e0) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/cache/storage_adapter.cc:153 #19 0x0000000001cb27e2 in dd::cache::Shared_dictionary_cache::get_uncached<dd::Item_name_key, dd::Abstract_table> ( this=0x4249480 <dd::cache::Shared_dictionary_cache::instance()::s_cache>, thd=0x7f4770000be0, key=..., isolation=ISO_READ_COMMITTED, object=0x7f48040c63e0) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/cache/shared_dictionary_cache.cc:108 #20 0x0000000001cb25da in dd::cache::Shared_dictionary_cache::get<dd::Item_name_key, dd::Abstract_table> ( this=0x4249480 <dd::cache::Shared_dictionary_cache::instance()::s_cache>, thd=0x7f4770000be0, key=..., element=0x7f48040c6468) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/cache/shared_dictionary_cache.cc:90 #21 0x0000000001c17626 in dd::cache::Dictionary_client::acquire<dd::Item_name_key, dd::Abstract_table> (this=0x7f47700042e0, key=..., object=0x7f48040c7110, local_committed=0x7f48040c710f, local_uncommitted=0x7f48040c710e) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/cache/dictionary_client.cc:742 #22 0x0000000001c03ded in dd::cache::Dictionary_client::acquire<dd::Table> (this=0x7f47700042e0, schema_name="performance_schema", object_name="global_variables", object=0x7f48040c7dc0) at /log/RQG/shipjain/trunkvigdis28/sql/dd/impl/cache/dictionary_client.cc:1229 #23 0x0000000001b68dc9 in open_table_from_share (thd=0x7f4770000be0, share=0x656f390, alias=0x7f47734dd268 "global_variables", db_stat=39, prgflag=8, ha_open_flags=0, outparam=0x7f47701e0210, is_create_table=false, table_def_param=0x0) at /log/RQG/shipjain/trunkvigdis28/sql/table.cc:3300 #24 0x00000000019ecb0b in open_table (thd=0x7f4770000be0, table_list=0x7f47734dd280, ot_ctx=0x7f48040c82c0) at /log/RQG/shipjain/trunkvigdis28/sql/sql_base.cc:3418 #25 0x00000000019efc12 in open_and_process_table (thd=0x7f4770000be0, lex=0x7f48040c85a0, tables=0x7f47734dd280, counter=0x7f48040c8650, prelocking_strategy=0x7f48040c83c0, has_prelocking_list=false, ot_ctx=0x7f48040c82c0) at /log/RQG/shipjain/trunkvigdis28/sql/sql_base.cc:5212 How to repeat: gdb /log/RQG/shipjain/rqg/storageIS/1490950951/1058log//log/RQG/shipjain/trunkvigdis28/sql/mysqld /log/RQG/shipjain/rqg/storageIS/1490950951/1058log//dev/shm/vardir/1490950951/13/1/data/core.5151 (vigdis29.no.oracle.com) using RMR run of inoformation_schema_new.yy grammar