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

Assertion failure in file lock0lock.cc line 6901 / DeadlockChecker::check_and_resolve

    XMLWordPrintable

    Details

      Description

      Notes:
      The test case currently fails every time for me, but there is still some timing involved, so try to run several times and/or modify timeouts if it doesn't fail right away.
      The problem is likely to be related to MDEV-20666 / MDEV-14846. On a debug build it causes the same assertion failure as MDEV-20666. However, unlike test cases in other reports, this one also affects non-debug builds (causing a non-debug assertion failure), which means it potentially more severe.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (a DATE DEFAULT '2000-01-01', b DATE DEFAULT '2020-01-01', PERIOD FOR app(a,b)) ENGINE=InnoDB;
      INSERT INTO t1 () VALUES (),();
      START TRANSACTION;
      INSERT INTO t1 () VALUES (),();
       
      --connect (con1,localhost,root,,test)
      SET innodb_lock_wait_timeout= 2, lock_wait_timeout= 2;
      --send
        DELETE FROM t1 FOR PORTION OF app FROM '2004-10-21 12:00:00.000' TO '2020-03-19 19:50:10.187';
       
      --connection default
      --sleep 1
      UPDATE t1 SET a = '2010-01-01';
       
      --connection con1
      --error ER_LOCK_WAIT_TIMEOUT
      --reap
       
      # Cleanup
      --disconnect con1
      --connection default
      DROP TABLE t1;
      

      10.4 RelWithDebInfo 6a634576

      2020-03-19 21:04:07 0x7fbf38105700  InnoDB: Assertion failure in file /data/src/10.4/storage/innobase/lock/lock0lock.cc line 6901
      InnoDB: We intentionally generate a memory trap.
       
      #6  0x00005632b153ba8d in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x5632b1ee1aa0 "/data/src/10.4/storage/innobase/lock/lock0lock.cc", line=line@entry=6901) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
      #7  0x00005632b19d7a46 in DeadlockChecker::check_and_resolve (lock=lock@entry=0x7fbf33400228, trx=trx@entry=0x7fbf33400158) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:6901
      #8  0x00005632b19d7b7c in lock_rec_enqueue_waiting (c_lock=0x7fbf333ff2e0, type_mode=type_mode@entry=1027, block=block@entry=0x7fbf32c19828, heap_no=heap_no@entry=2, index=index@entry=0x7fbee407fc88, thr=thr@entry=0x7fbee40c3420, prdt=0x0) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:1727
      #9  0x00005632b19d854e in lock_rec_lock (impl=impl@entry=false, mode=mode@entry=1027, block=block@entry=0x7fbf32c19828, heap_no=2, index=index@entry=0x7fbee407fc88, thr=thr@entry=0x7fbee40c3420) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:1972
      #10 0x00005632b19d8c9d in lock_clust_rec_read_check_and_lock (flags=flags@entry=0, block=block@entry=0x7fbf32c19828, rec=rec@entry=0x7fbf3311007d <error: Cannot access memory at address 0x7fbf3311007d>, index=index@entry=0x7fbee407fc88, offsets=offsets@entry=0x7fbf38100020, mode=mode@entry=LOCK_X, gap_mode=1024, thr=0x7fbee40c3420) at /data/src/10.4/storage/innobase/lock/lock0lock.cc:5832
      #11 0x00005632b1a613fe in sel_set_rec_lock (pcur=pcur@entry=0x7fbee40c2c00, rec=rec@entry=0x7fbf3311007d <error: Cannot access memory at address 0x7fbf3311007d>, index=index@entry=0x7fbee407fc88, offsets=0x7fbf38100020, mode=3, type=type@entry=1024, thr=0x7fbee40c3420, mtr=0x7fbf38100c60) at /data/src/10.4/storage/innobase/row/row0sel.cc:1264
      #12 0x00005632b1a6663c in row_search_mvcc (buf=buf@entry=0x7fbee4081728 "\377!\240\017!\310\017", mode=mode@entry=PAGE_CUR_GE, prebuilt=0x7fbee40c2a38, match_mode=match_mode@entry=1, direction=direction@entry=0) at /data/src/10.4/storage/innobase/row/row0sel.cc:5051
      #13 0x00005632b1997abb in ha_innobase::index_read (this=0x7fbee40839e0, buf=0x7fbee4081728 "\377!\240\017!\310\017", key_ptr=0x7fbee800fcb8 "", key_len=<optimized out>, find_flag=<optimized out>) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:9296
      #14 0x00005632b1813603 in handler::ha_rnd_pos (this=0x7fbee40839e0, buf=0x7fbee4081728 "\377!\240\017!\310\017", pos=0x7fbee800fcb8 "") at /data/src/10.4/sql/handler.cc:2861
      #15 0x00005632b192478a in rr_from_pointers (info=0x7fbf38101370) at /data/src/10.4/sql/records.cc:543
      #16 0x00005632b19395e6 in READ_RECORD::read_record (this=0x7fbf38101370) at /data/src/10.4/sql/records.h:69
      #17 mysql_delete (thd=thd@entry=0x7fbee80009a8, table_list=0x7fbee800fe98, conds=<optimized out>, order_list=order_list@entry=0x7fbee80051a0, limit=18446744073709551615, options=<optimized out>, result=0x0) at /data/src/10.4/sql/sql_delete.cc:772
      #18 0x00005632b161759b in mysql_execute_command (thd=thd@entry=0x7fbee80009a8) at /data/src/10.4/sql/sql_parse.cc:4727
      #19 0x00005632b161c0c9 in mysql_parse (thd=thd@entry=0x7fbee80009a8, rawbuf=<optimized out>, length=93, parser_state=parser_state@entry=0x7fbf381041a0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.4/sql/sql_parse.cc:7900
      #20 0x00005632b161e4c8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fbee80009a8, packet=packet@entry=0x7fbee8007a19 "DELETE FROM t1 FOR PORTION OF app FROM '2004-10-21 12:00:00.000' TO '2020-03-19 19:50:10.187'", packet_length=packet_length@entry=93, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.4/sql/sql_parse.cc:1842
      #21 0x00005632b161fca9 in do_command (thd=0x7fbee80009a8) at /data/src/10.4/sql/sql_parse.cc:1360
      #22 0x00005632b16ef944 in do_handle_one_connection (connect=connect@entry=0x5632b5274548) at /data/src/10.4/sql/sql_connect.cc:1412
      #23 0x00005632b16ef9f4 in handle_one_connection (arg=arg@entry=0x5632b5274548) at /data/src/10.4/sql/sql_connect.cc:1316
      #24 0x00005632b1c9e154 in pfs_spawn_thread (arg=0x5632b52748e8) at /data/src/10.4/storage/perfschema/pfs.cc:1869
      #25 0x00007fbf3f92f4a4 in start_thread (arg=0x7fbf38105700) at pthread_create.c:456
      #26 0x00007fbf3da63d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      Reproducible on 10.4, 10.5. The test case is not applicable to previous versions.

      The debug failure for the record:

      10.4 Debug 6a634576

      mysqld: /data/src/10.4/storage/innobase/row/row0sel.cc:4485: dberr_t row_search_mvcc(byte*, page_cur_mode_t, row_prebuilt_t*, ulint, ulint): Assertion `prebuilt->sql_stat_start || trx->state == TRX_STATE_ACTIVE || (prebuilt->table->no_rollback() && trx->state == TRX_STATE_NOT_STARTED)' failed.
      200319 21:09:23 [ERROR] mysqld got signal 6 ;
       
      #6  0x00007f4dd79c7e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55cbad89f388 "prebuilt->sql_stat_start || trx->state == TRX_STATE_ACTIVE || (prebuilt->table->no_rollback() && trx->state == TRX_STATE_NOT_STARTED)", file=file@entry=0x55cbad89e0a0 "/data/src/10.4/storage/innobase/row/row0sel.cc", line=line@entry=4485, function=function@entry=0x55cbad8a2500 <row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)::__PRETTY_FUNCTION__> "dberr_t row_search_mvcc(byte*, page_cur_mode_t, row_prebuilt_t*, ulint, ulint)") at assert.c:92
      #7  0x00007f4dd79c7f12 in __GI___assert_fail (assertion=0x55cbad89f388 "prebuilt->sql_stat_start || trx->state == TRX_STATE_ACTIVE || (prebuilt->table->no_rollback() && trx->state == TRX_STATE_NOT_STARTED)", file=0x55cbad89e0a0 "/data/src/10.4/storage/innobase/row/row0sel.cc", line=4485, function=0x55cbad8a2500 <row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)::__PRETTY_FUNCTION__> "dberr_t row_search_mvcc(byte*, page_cur_mode_t, row_prebuilt_t*, ulint, ulint)") at assert.c:101
      #8  0x000055cbad0964c6 in row_search_mvcc (buf=0x7f4d8400a5c0 "\377!\240\017!\310\017", '\245' <repeats 17 times>, "\360\245", mode=PAGE_CUR_GE, prebuilt=0x7f4d84188220, match_mode=1, direction=0) at /data/src/10.4/storage/innobase/row/row0sel.cc:4485
      #9  0x000055cbacea87ba in ha_innobase::index_read (this=0x7f4d8400aa18, buf=0x7f4d8400a5c0 "\377!\240\017!\310\017", '\245' <repeats 17 times>, "\360\245", key_ptr=0x7f4d78018f00 "", key_len=6, find_flag=HA_READ_KEY_EXACT) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:9296
      #10 0x000055cbacea9add in ha_innobase::rnd_pos (this=0x7f4d8400aa18, buf=0x7f4d8400a5c0 "\377!\240\017!\310\017", '\245' <repeats 17 times>, "\360\245", pos=0x7f4d78018f00 "") at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:9797
      #11 0x000055cbacc5ccff in handler::ha_rnd_pos (this=0x7f4d8400aa18, buf=0x7f4d8400a5c0 "\377!\240\017!\310\017", '\245' <repeats 17 times>, "\360\245", pos=0x7f4d78018f00 "") at /data/src/10.4/sql/handler.cc:2861
      #12 0x000055cbace0252d in rr_from_pointers (info=0x7f4dd0d23e30) at /data/src/10.4/sql/records.cc:543
      #13 0x000055cbac845559 in READ_RECORD::read_record (this=0x7f4dd0d23e30) at /data/src/10.4/sql/records.h:69
      #14 0x000055cbace2068d in mysql_delete (thd=0x7f4d78000af0, table_list=0x7f4d78011f40, conds=0x7f4d780133c0, order_list=0x7f4d780054a8, limit=18446744073709551615, options=0, result=0x0) at /data/src/10.4/sql/sql_delete.cc:772
      #15 0x000055cbac8f9a0a in mysql_execute_command (thd=0x7f4d78000af0) at /data/src/10.4/sql/sql_parse.cc:4727
      #16 0x000055cbac905247 in mysql_parse (thd=0x7f4d78000af0, rawbuf=0x7f4d78011dd8 "DELETE FROM t1 FOR PORTION OF app FROM '2004-10-21 12:00:00.000' TO '2020-03-19 19:50:10.187'", length=93, parser_state=0x7f4dd0d25160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
      #17 0x000055cbac8f042a in dispatch_command (command=COM_QUERY, thd=0x7f4d78000af0, packet=0x7f4d780083a1 "DELETE FROM t1 FOR PORTION OF app FROM '2004-10-21 12:00:00.000' TO '2020-03-19 19:50:10.187'", packet_length=93, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
      #18 0x000055cbac8eeab7 in do_command (thd=0x7f4d78000af0) at /data/src/10.4/sql/sql_parse.cc:1360
      #19 0x000055cbaca77f3d in do_handle_one_connection (connect=0x55cbb01a5e30) at /data/src/10.4/sql/sql_connect.cc:1412
      #20 0x000055cbaca77c8c in handle_one_connection (arg=0x55cbb01a5e30) at /data/src/10.4/sql/sql_connect.cc:1316
      #21 0x000055cbad47f129 in pfs_spawn_thread (arg=0x55cbb01107f0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
      #22 0x00007f4dd99504a4 in start_thread (arg=0x7f4dd0d26700) at pthread_create.c:456
      #23 0x00007f4dd7a84d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              sanja Oleksandr Byelkin
              Reporter:
              elenst Elena Stepanova
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated: