Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-20038

Assertion `rw_lock_own(dict_index_get_lock(index), RW_LOCK_S)' failed. in btr_cur_search_to_nth_level_func

Details

    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

        1. MDEV-20038.tgz
          3 kB
        2. MDEV-20038.yy
          1 kB
        3. prt
          76 kB
        4. simp_MDEV-20038.cfg
          38 kB

        Activity

          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
          

          marko Marko Mäkelä added a comment - 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
          mleich Matthias Leich added a comment - - edited

          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.
          

          mleich Matthias Leich added a comment - - edited 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.

          elenst Elena Stepanova added a comment - 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
          

          elenst Elena Stepanova added a comment - 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.

          marko Marko Mäkelä added a comment - 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.

          People

            vlad.lesin Vladislav Lesin
            mleich Matthias Leich
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.