Details
-
Bug
-
Status: Stalled (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.0.26, 10.3.11, 10.4.7, 10.0(EOL), 10.1(EOL), 10.2(EOL), 10.5
Description
Assert hit during RQG testing on
|
10.4.7 commit 70c2bde931246ea4966d82fa56773b8ef1e0074f 2019-07-09
|
mysqld: storage/innobase/btr/btr0cur.cc:1444: dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, rw_lock_t*, const char*, unsigned int, mtr_t*, ib_uint64_t): Assertion `rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)' failed.
|
190710 19:41:21 [ERROR] mysqld got signal 6 ;
|
...
|
# 2019-07-10T19:41:42 [243109] | Query (0x7fd098011180): UPDATE t2 SET col1 = 1175 LIMIT 2 /* E_R Thread9 QNO 607 CON_ID 24 */
|
# 2019-07-10T19:41:42 [243109] | Connection ID (thread ID): 366
|
# 2019-07-10T19:41:42 [243109] | Status: NOT_KILLED
|
|
Attachments
- MDEV-20038.tgz
- 3 kB
- MDEV-20038.yy
- 1 kB
- prt
- 76 kB
- simp_MDEV-20038.cfg
- 38 kB
Activity
Replay also on MySQL 5.6.31-debug-log
|
https://github.com/mysql/mysql-server , git checkout 5.6 , commit 6594835303da437105bb3841df976620b716e088
|
There comes a
|
2019-08-23 15:42:21 7f8c4d6b9700 InnoDB: Assertion failure in thread 140240571045632 in file row0ins.cc line 1913
|
InnoDB: Failing assertion: s_latch == rw_lock_own(&index->lock, 352)
|
....
|
Query (7f8c20004c90): UPDATE t2 SET col1 = 2722 LIMIT 2 /* E_R Thread2 QNO 7933 CON_ID 10 */
|
Status: NOT_KILLED
|
if algorithm = NOCOPY gets replaced by algorithm INPLACE.
|
|
The MTR based brute force test case does not run well on 5.6.
|
So I uploaded the RQG test
|
MDEV-20038.yy -- Simplified RQG grammar
|
simp_MDEV-20038.cfg - RQG config file
|
The test needs (only) threads=4 and replays in ~ 60s on MySQL 5.6.
|
Another attempt. The test case below currently fails for me on 10.4 debug within 1-100 attempts (unfortunately, can't give any better stats, it's really this volatile). Luckily, the test case is fast.
The rr profile with mysqld binary can be found here.
--source include/have_sequence.inc
|
--source include/have_innodb.inc
|
|
CREATE TABLE t1 (id INT, a CHAR(65), b VARCHAR(64), PRIMARY KEY(id,a,b), UNIQUE(a(64),id)) ENGINE=InnoDB; |
INSERT INTO t1 (id,a,b) SELECT seq, '', '' FROM seq_1_to_100; |
|
--connect (con1,localhost,root,,test)
|
ALTER TABLE t1 ADD f INT; |
ALTER TABLE t1 ADD KEY(f); |
|
--connection default
|
--send
|
ALTER TABLE t1 DROP KEY f; |
|
--connection con1
|
UPDATE t1 SET b = 'foo'; |
|
# Cleanup
|
--disconnect con1
|
--connection default
|
--reap
|
DROP TABLE t1; |
10.4 bc891054 |
mysqld: /data/src/10.4/storage/innobase/btr/btr0cur.cc:1508: dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, rw_lock_t*, const char*, unsigned int, mtr_t*, ib_uint64_t): Assertion `rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)' failed.
|
200129 19:55:52 [ERROR] mysqld got signal 6 ;
|
|
#6 0x00007fd3fd51ae67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x561887cb0e30 "rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)", file=file@entry=0x561887cb0070 "/data/src/10.4/storage/innobase/btr/btr0cur.cc", line=line@entry=1508, function=function@entry=0x561887cb5140 <btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, rw_lock_t*, char const*, unsigned int, mtr_t*, unsigned long)::__PRETTY_FUNCTION__> "dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, rw_lock_t*, const char*, unsigned int, mtr_t*, ib_uint64_t)") at assert.c:92
|
#7 0x00007fd3fd51af12 in __GI___assert_fail (assertion=0x561887cb0e30 "rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)", file=0x561887cb0070 "/data/src/10.4/storage/innobase/btr/btr0cur.cc", line=1508, function=0x561887cb5140 <btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, rw_lock_t*, char const*, unsigned int, mtr_t*, unsigned long)::__PRETTY_FUNCTION__> "dberr_t btr_cur_search_to_nth_level_func(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, rw_lock_t*, const char*, unsigned int, mtr_t*, ib_uint64_t)") at assert.c:101
|
#8 0x00005618875323a4 in btr_cur_search_to_nth_level_func (index=0x7fd3a41a7418, level=0, tuple=0x7fd3a802a308, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x7fd3f805daa0, ahi_latch=0x0, file=0x561887c46b90 "/data/src/10.4/storage/innobase/row/row0ins.cc", line=2155, mtr=0x7fd3f805e0f0, autoinc=0) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:1508
|
#9 0x00005618873e6e31 in btr_pcur_open_low (index=0x7fd3a41a7418, level=0, tuple=0x7fd3a802a308, mode=PAGE_CUR_GE, latch_mode=16385, cursor=0x7fd3f805daa0, file=0x561887c46b90 "/data/src/10.4/storage/innobase/row/row0ins.cc", line=2155, autoinc=0, mtr=0x7fd3f805e0f0) at /data/src/10.4/storage/innobase/include/btr0pcur.ic:441
|
#10 0x00005618873ed065 in row_ins_scan_sec_index_for_duplicate (flags=0, index=0x7fd3a41a7418, entry=0x7fd3a802a308, thr=0x7fd3a805c2e0, s_latch=true, mtr=0x7fd3f805e0f0, offsets_heap=0x7fd3a80936c0) at /data/src/10.4/storage/innobase/row/row0ins.cc:2155
|
#11 0x00005618873effe7 in row_ins_sec_index_entry_low (flags=0, mode=33, index=0x7fd3a41a7418, offsets_heap=0x7fd3a80936c0, heap=0x7fd3a80a0b50, entry=0x7fd3a802a308, trx_id=0, thr=0x7fd3a805c2e0) at /data/src/10.4/storage/innobase/row/row0ins.cc:3041
|
#12 0x00005618873f0e0b in row_ins_sec_index_entry (index=0x7fd3a41a7418, entry=0x7fd3a802a308, thr=0x7fd3a805c2e0, check_foreign=true) at /data/src/10.4/storage/innobase/row/row0ins.cc:3330
|
#13 0x0000561887479cf1 in row_upd_sec_index_entry (node=0x7fd3a805bf78, thr=0x7fd3a805c2e0) at /data/src/10.4/storage/innobase/row/row0upd.cc:2519
|
#14 0x0000561887479f56 in row_upd_sec_step (node=0x7fd3a805bf78, thr=0x7fd3a805c2e0) at /data/src/10.4/storage/innobase/row/row0upd.cc:2546
|
#15 0x000056188747cf77 in row_upd (node=0x7fd3a805bf78, thr=0x7fd3a805c2e0) at /data/src/10.4/storage/innobase/row/row0upd.cc:3327
|
#16 0x000056188747d3bd in row_upd_step (thr=0x7fd3a805c2e0) at /data/src/10.4/storage/innobase/row/row0upd.cc:3442
|
#17 0x0000561887418c94 in row_update_for_mysql (prebuilt=0x7fd3a805b718) at /data/src/10.4/storage/innobase/row/row0mysql.cc:1889
|
#18 0x0000561887273e06 in ha_innobase::update_row (this=0x7fd3a807a668, old_row=0x7fd3a8025360 "\377\021", new_row=0x7fd3a80252d0 "\377\021") at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:8830
|
#19 0x000056188703579a in handler::ha_update_row (this=0x7fd3a807a668, old_data=0x7fd3a8025360 "\377\021", new_data=0x7fd3a80252d0 "\377\021") at /data/src/10.4/sql/handler.cc:6720
|
#20 0x0000561886dd54b1 in mysql_update (thd=0x7fd3a8000af0, table_list=0x7fd3a8011eb0, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=18446744073709551599, ignore=false, found_return=0x7fd3f8060840, updated_return=0x7fd3f8060900) at /data/src/10.4/sql/sql_update.cc:1055
|
#21 0x0000561886cc5967 in mysql_execute_command (thd=0x7fd3a8000af0) at /data/src/10.4/sql/sql_parse.cc:4377
|
#22 0x0000561886cd290d in mysql_parse (thd=0x7fd3a8000af0, rawbuf=0x7fd3a8011dd8 "UPDATE t1 SET b = 'foo'", length=23, parser_state=0x7fd3f8061160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
|
#23 0x0000561886cbdada in dispatch_command (command=COM_QUERY, thd=0x7fd3a8000af0, packet=0x7fd3a807d931 "UPDATE t1 SET b = 'foo'", packet_length=23, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
|
#24 0x0000561886cbc167 in do_command (thd=0x7fd3a8000af0) at /data/src/10.4/sql/sql_parse.cc:1360
|
#25 0x0000561886e45381 in do_handle_one_connection (connect=0x56188a5835c0) at /data/src/10.4/sql/sql_connect.cc:1412
|
#26 0x0000561886e450d0 in handle_one_connection (arg=0x56188a5835c0) at /data/src/10.4/sql/sql_connect.cc:1316
|
#27 0x000056188784d7cd in pfs_spawn_thread (arg=0x56188a4a22f0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
|
#28 0x00007fd3ff4a34a4 in start_thread (arg=0x7fd3f8062700) at pthread_create.c:456
|
#29 0x00007fd3fd5d7d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Couldn't reproduce with this test case on other versions, only 10.4. Could be just the matter of luck.
Yet another attempt
rr:/data/MDEV-20038/rr-profile-packed
10.5 b04af64882f233e3937f729aac321de504db3f63 |
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x0000146bae9fe859 in __GI_abort () at abort.c:79
|
#2 0x0000146bae9fe729 in __assert_fail_base (fmt=0x146baeb94588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f81ea7d680 "rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)",
|
file=0x55f81ea7b720 "/data/MDEV-20038/10.5/storage/innobase/btr/btr0cur.cc", line=1504, function=<optimized out>) at assert.c:92
|
#3 0x0000146baea0ffd6 in __GI___assert_fail (assertion=0x55f81ea7d680 "rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)", file=0x55f81ea7b720 "/data/MDEV-20038/10.5/storage/innobase/btr/btr0cur.cc",
|
line=1504, function=0x55f81ea7ce40 "dberr_t btr_cur_search_to_nth_level(dict_index_t*, ulint, const dtuple_t*, page_cur_mode_t, ulint, btr_cur_t*, const char*, unsigned int, mtr_t*, ib_uint64_t)")
|
at assert.c:101
|
#4 0x000055f81d6f30a7 in btr_cur_search_to_nth_level (index=0x617000080408, level=0, tuple=0x6190001aaa08, mode=PAGE_CUR_GE, latch_mode=1, cursor=0x146b93667330,
|
file=0x55f81e92e580 "/data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc", line=2162, mtr=0x146b93667bd0, autoinc=0) at /data/MDEV-20038/10.5/storage/innobase/btr/btr0cur.cc:1504
|
#5 0x000055f81d48bfb7 in btr_pcur_open_low (index=0x617000080408, level=0, tuple=0x6190001aaa08, mode=PAGE_CUR_GE, latch_mode=16385, cursor=0x146b93667330,
|
file=0x55f81e92e580 "/data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc", line=2162, autoinc=0, mtr=0x146b93667bd0) at /data/MDEV-20038/10.5/storage/innobase/include/btr0pcur.inl:441
|
#6 0x000055f81d4985fb in row_ins_scan_sec_index_for_duplicate (flags=0, index=0x617000080408, entry=0x6190001aaa08, thr=0x6210000e9588, s_latch=true, mtr=0x146b93667bd0, offsets_heap=0x6190001aae80)
|
at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:2162
|
#7 0x000055f81d49d93d in row_ins_sec_index_entry_low (flags=0, mode=33, index=0x617000080408, offsets_heap=0x6190001aae80, heap=0x6190001ab380, entry=0x6190001aaa08, trx_id=0, thr=0x6210000e9588)
|
at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:3087
|
#8 0x000055f81d49efdc in row_ins_sec_index_entry (index=0x617000080408, entry=0x6190001aaa08, thr=0x6210000e9588, check_foreign=true) at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:3372
|
#9 0x000055f81d5977ce in row_upd_sec_index_entry (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:2237
|
#10 0x000055f81d597d0f in row_upd_sec_step (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:2264
|
#11 0x000055f81d59ce68 in row_upd (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:3028
|
#12 0x000055f81d59d634 in row_upd_step (thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:3143
|
#13 0x000055f81d4e7c33 in row_update_for_mysql (prebuilt=0x6210000e8988) at /data/MDEV-20038/10.5/storage/innobase/row/row0mysql.cc:1801
|
#14 0x000055f81d168e13 in ha_innobase::update_row (this=0x61d0002ae4b8, old_row=0x623000053290 "\004", new_row=0x623000052538 "\004") at /data/MDEV-20038/10.5/storage/innobase/handler/ha_innodb.cc:8477
|
#15 0x000055f81c932997 in handler::ha_update_row (this=0x61d0002ae4b8, old_data=0x623000053290 "\004", new_data=0x623000052538 "\004") at /data/MDEV-20038/10.5/sql/handler.cc:7334
|
#16 0x000055f81c453249 in mysql_update (thd=0x62b0000e0218, table_list=0x62b0000e7468, fields=..., values=..., conds=0x0, order_num=0, order=0x0, limit=18446744073709551615, ignore=false,
|
found_return=0x146b9366a1d0, updated_return=0x146b9366a1f0) at /data/MDEV-20038/10.5/sql/sql_update.cc:1090
|
#17 0x000055f81c185263 in mysql_execute_command (thd=0x62b0000e0218) at /data/MDEV-20038/10.5/sql/sql_parse.cc:4484
|
#18 0x000055f81c19d075 in mysql_parse (thd=0x62b0000e0218, rawbuf=0x62b0000e7238 "/* WRK-1 QNO 9845 */ UPDATE `advanced_db`.`t5_InnoDB` SET `col_varchar` = CONVERT('rehabilitation' USING UCS2)",
|
length=110, parser_state=0x146b9366ab00, is_com_multi=false, is_next_command=false) at /data/MDEV-20038/10.5/sql/sql_parse.cc:8120
|
#19 0x000055f81c175363 in dispatch_command (command=COM_QUERY, thd=0x62b0000e0218,
|
packet=0x6290002ee219 "/* WRK-1 QNO 9845 */ UPDATE `advanced_db`.`t5_InnoDB` SET `col_varchar` = CONVERT('rehabilitation' USING UCS2)", packet_length=110, is_com_multi=false, is_next_command=false)
|
at /data/MDEV-20038/10.5/sql/sql_parse.cc:1891
|
#20 0x000055f81c172622 in do_command (thd=0x62b0000e0218) at /data/MDEV-20038/10.5/sql/sql_parse.cc:1375
|
#21 0x000055f81c56061e in do_handle_one_connection (connect=0x608000002b38, put_in_cache=true) at /data/MDEV-20038/10.5/sql/sql_connect.cc:1416
|
#22 0x000055f81c55ffb2 in handle_one_connection (arg=0x608000002b38) at /data/MDEV-20038/10.5/sql/sql_connect.cc:1318
|
#23 0x0000146baef28609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#24 0x0000146baeafb133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
In that trace, the mini-transaction is only holding the index.lock, in SX mode, not S mode:
(rr) p *(mtr_memo_slot_t*)mtr.m_memo.m_first_block.m_data
|
$2 = {object = 0x617000080578, type = MTR_MEMO_SX_LOCK}
|
The index latch was acquired a little earlier by the same thread:
#2 0x000055f81d2ce4af in mtr_t::sx_lock (this=0x146b93667bd0, lock=0x617000080578, file=0x55f81e92e580 "/data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc", line=2897)
|
at /data/MDEV-20038/10.5/storage/innobase/include/mtr0mtr.h:251
|
#3 0x000055f81d49c8bf in row_ins_sec_mtr_start_and_check_if_aborted (mtr=0x146b93667bd0, index=0x617000080408, check=true, search_mode=545) at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:2897
|
#4 0x000055f81d49d8f6 in row_ins_sec_index_entry_low (flags=0, mode=33, index=0x617000080408, offsets_heap=0x6190001aae80, heap=0x6190001ab380, entry=0x6190001aaa08, trx_id=0, thr=0x6210000e9588)
|
at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:3082
|
#5 0x000055f81d49efdc in row_ins_sec_index_entry (index=0x617000080408, entry=0x6190001aaa08, thr=0x6210000e9588, check_foreign=true) at /data/MDEV-20038/10.5/storage/innobase/row/row0ins.cc:3372
|
#6 0x000055f81d5977ce in row_upd_sec_index_entry (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:2237
|
#7 0x000055f81d597d0f in row_upd_sec_step (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:2264
|
#8 0x000055f81d59ce68 in row_upd (node=0x6210000e91d8, thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:3028
|
#9 0x000055f81d59d634 in row_upd_step (thr=0x6210000e9588) at /data/MDEV-20038/10.5/storage/innobase/row/row0upd.cc:3143
|
#10 0x000055f81d4e7c33 in row_update_for_mysql (prebuilt=0x6210000e8988) at /data/MDEV-20038/10.5/storage/innobase/row/row0mysql.cc:1801
|
#11 0x000055f81d168e13 in ha_innobase::update_row (this=0x61d0002ae4b8, old_row=0x623000053290 "\004", new_row=0x623000052538 "\004") at /data/MDEV-20038/10.5/storage/innobase/handler/ha_innodb.cc:8477
|
The failing debug assertion is too strict. It should qualify also an SX latch and not only S latch on the index. Would the following patch work, or would it trigger an assertion failure somewhere else?
diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.cc
|
index e076a3b7962..c76d167dcab 100644
|
--- a/storage/innobase/btr/btr0cur.cc
|
+++ b/storage/innobase/btr/btr0cur.cc
|
@@ -1501,8 +1501,9 @@ dberr_t btr_cur_search_to_nth_level(dict_index_t *index, ulint level,
|
default:
|
if (!srv_read_only_mode) {
|
if (s_latch_by_caller) {
|
- ut_ad(rw_lock_own(dict_index_get_lock(index),
|
- RW_LOCK_S));
|
+ ut_ad(rw_lock_own_flagged(&index->lock,
|
+ RW_LOCK_FLAG_SX
|
+ | RW_LOCK_FLAG_S));
|
} else if (!modify_external) {
|
/* BTR_SEARCH_TREE is intended to be used with
|
BTR_ALREADY_S_LATCHED */ |
In MDEV-30400 and MDEV-24142, this code had been refactored in MariaDB Server 10.6. A corresponding assertion is at the start of btr_cur_t::search_leaf():
ut_ad(!(latch_mode & BTR_ALREADY_S_LATCHED) ||
|
mtr->memo_contains_flagged(&index()->lock,
|
MTR_MEMO_S_LOCK | MTR_MEMO_SX_LOCK |
|
MTR_MEMO_X_LOCK));
|
This assertion checks that if the caller claims that the index tree was already latched, the mtr_t::m_memo must contain the index tree in one of the modes. For latch_mode=BTR_MODIFY_TREE we additionally assert that the exclusive index latch is being held.
I gave MDEV-20038.tgz
one more try on mysql-5.6.31 (replacing ALGORITHM=NOCOPY with ALGORITHM=INPLACE in order to avoid a syntax error). According to top, the mysqltest_background.sh is not running in parallel with the test, and that might explain why the failure is not being repeated.
mleich, could you please check if MySQL 5.6 or 5.7 are affected? I used the following procedure:
cd /mariadb/mysql-server
git checkout mysql-5.6.31
mkdir /dev/shm/5.6
cd /dev/shm/5.6
CXXFLAGS='-O2 -std=gnu++98' cmake -DWITH_DEBUG=ON -DWITH_EMBEDDED_SERVER=OFF /mariadb/mysql-server
nice make -j$(nproc}
cd /mariadb/mysql-server
MTR_BINDIR=/dev/shm/5.6 perl -I. mysql-test-run.pl main.ml_MDEV-20038