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

Possible hang during purge of history, or transaction rollback

    XMLWordPrintable

Details

    Description

      WL#6326 in MySQL 5.7.2 and MariaDB 10.2.2 introduced a potential hang on purge or rollback when an index tree is being shrunk by multiple levels.

      The symptoms should be similar to MDEV-14637: the server could hang. The hang can probably only occur if there is a concurrent access to the index tree. It apparently also requires that the btr_cur_pessimistic_delete() would shrink the tree by multiple levels. First, we will need some instrumentation to control the concurrency:

      diff --git a/storage/innobase/row/row0umod.cc b/storage/innobase/row/row0umod.cc
      		 
      index 4598e8959d6..83d85f663a4 100644
      		 
      --- a/storage/innobase/row/row0umod.cc
      		 
      +++ b/storage/innobase/row/row0umod.cc
      		 
      @@ -169,12 +169,15 @@ row_undo_mod_remove_clust_low(
      		 
       	/* Find out if the record has been purged already
      		 
       	or if we can remove it. */
      		 
       
      -	if (!btr_pcur_restore_position(mode, &node->pcur, mtr)
      		 
      -	    || row_vers_must_preserve_del_marked(node->new_trx_id,
      		 
      -						 node->table->name,
      		 
      -						 mtr)) {
      		 
      +	if (!btr_pcur_restore_position(mode, &node->pcur, mtr)) {
      		 
      +		return DB_SUCCESS;
      		 
      +	}
      		 
       
      -		return(DB_SUCCESS);
      		 
      +	DEBUG_SYNC_C("rollback_purge_clust");
      		 
      +
      		 
      +	if (row_vers_must_preserve_del_marked(node->new_trx_id,
      		 
      +					      node->table->name, mtr)) {
      		 
      +		return DB_SUCCESS;
      		 
       	}
      		 
       
       	btr_cur = btr_pcur_get_btr_cur(&node->pcur);
      		 
      @@ -361,6 +364,7 @@ row_undo_mod_clust(
      		 
       	      == node->new_trx_id);
      		 
       
       	btr_pcur_commit_specify_mtr(pcur, &mtr);
      		 
      +	DEBUG_SYNC_C("rollback_undo_pk");
      		 
       
       	if (err == DB_SUCCESS && node->rec_type == TRX_UNDO_UPD_DEL_REC) {

      With that change, the following test case (an adapted subset of a test case that was published in MySQL 5.7.29) crashes almost every time:

      #
      		 
      # Test for Bug#30113362 : BTR_CUR_WILL_MODIFY_TREE() IS INSUFFICIENT FOR HIGHER TREE LEVEL
      		 
      #
      		 
       
      		 
      --source include/have_innodb.inc
      		 
      --source include/have_debug.inc
      		 
      --source include/have_debug_sync.inc
      		 
      --source include/have_innodb_16k.inc
      		 
       
      		 
      --disable_query_log
      		 
      SET @old_innodb_limit_optimistic_insert_debug = @@innodb_limit_optimistic_insert_debug;
      		 
      SET @old_innodb_adaptive_hash_index = @@innodb_adaptive_hash_index;
      		 
      SET @old_innodb_stats_persistent = @@innodb_stats_persistent;
      		 
      --enable_query_log
      		 
       
      		 
      # Save the initial number of concurrent sessions
      		 
      --source include/count_sessions.inc
      		 
       
      		 
      SET GLOBAL innodb_adaptive_hash_index = false;
      		 
      SET GLOBAL innodb_stats_persistent = false;
      		 
       
      		 
      connect (purge_control,localhost,root,,);
      		 
      START TRANSACTION WITH CONSISTENT SNAPSHOT;
      		 
       
      		 
      --connect (con2,localhost,root,,)
      		 
       
      		 
      CREATE TABLE t1 (
      		 
        a00 CHAR(255) NOT NULL DEFAULT 'a',
      		 
        a01 CHAR(255) NOT NULL DEFAULT 'a',
      		 
        a02 CHAR(255) NOT NULL DEFAULT 'a',
      		 
        b INT NOT NULL DEFAULT 0,
      		 
        CONSTRAINT pkey PRIMARY KEY(a00, a01, a02)
      		 
      ) charset latin1 ENGINE = InnoDB COMMENT='MERGE_THRESHOLD=45';
      		 
       
      		 
      #
      		 
      # Prepare primary key index tree to be used for this test.
      		 
      #
      		 
       
      		 
      SET GLOBAL innodb_limit_optimistic_insert_debug = 3;
      		 
       
      		 
      delimiter |;
      		 
      CREATE PROCEDURE data_load_t1()
      		 
      BEGIN
      		 
        DECLARE c1 INT DEFAULT 97;
      		 
        DECLARE c2 INT DEFAULT 97;
      		 
        DECLARE c3 INT DEFAULT 97;
      		 
       
      		 
        WHILE c1 < 102 DO
      		 
          WHILE c2 < 123 DO
      		 
            WHILE c3 < 123 DO
      		 
              INSERT INTO t1 (a00) VALUES (CHAR(c1,c2,c3));
      		 
              SET c3 = c3 + 1;
      		 
            END WHILE;
      		 
            SET c3 = 97;
      		 
            SET c2 = c2 + 1;
      		 
          END WHILE;
      		 
          SET c2 = 97;
      		 
          SET c1 = c1 + 1;
      		 
        END WHILE;
      		 
      END |
      		 
      delimiter ;|
      		 
      call data_load_t1();
      		 
      DROP PROCEDURE data_load_t1;
      		 
       
      		 
      connection con2;
      		 
      DELETE FROM t1 WHERE a00 = 'cnm';
      		 
      COMMIT;
      		 
      BEGIN;
      		 
      INSERT INTO t1 SET a00 = 'cnm';
      		 
      # causes "domino falling" merges to upper level
      		 
      connection purge_control;
      		 
      COMMIT;
      		 
      connection con2;
      		 
      SET GLOBAL innodb_limit_optimistic_insert_debug = 0;
      		 
      ROLLBACK;
      		 
       
      		 
      # at this moment, in the tree,
      		 
      # ...
      		 
      # level 4: ...(ast,avw,ayz)(bcc,bff,bii,bll,boo,brr,buu,bxx,cba,ced,cqp,cts)(cwv,czy,ddb)...
      		 
      # ...
      		 
       
      		 
      --echo # Test start
      		 
       
      		 
      # (1) Similar case to the first reported corefile at bug#30113362
      		 
      #     - Deleting 'bii' causes "domino falling" merges and the node_ptr becomes left_most of level 4.
      		 
      #       So, the operation needs upper level pages' X-latch, though doesn't cause merge more.
      		 
       
      		 
      connection purge_control;
      		 
      START TRANSACTION WITH CONSISTENT SNAPSHOT;
      		 
      connection con2;
      		 
      DELETE FROM t1 WHERE a00 = 'bii';
      		 
      COMMIT;
      		 
      BEGIN;
      		 
      INSERT INTO t1 SET a00 = 'bii';
      		 
      SET DEBUG_SYNC = 'rollback_undo_pk SIGNAL roll1_wait WAIT_FOR roll2';
      		 
      SET DEBUG_SYNC = 'rollback_purge_clust SIGNAL rollback_waiting WAIT_FOR resume';
      		 
      send ROLLBACK;
      		 
       
      		 
      connection purge_control;
      		 
      SET DEBUG_SYNC = 'now WAIT_FOR roll1_wait';
      		 
      COMMIT;
      		 
      SET DEBUG_SYNC = 'now SIGNAL roll2';
      		 
       
      		 
      connect (con1,localhost,root,,);
      		 
      SET DEBUG_SYNC = 'now WAIT_FOR rollback_waiting';
      		 
      SET DEBUG_SYNC = 'rw_s_lock_waiting SIGNAL lockwait1';
      		 
      send SELECT a00 FROM t1 WHERE a00 = 'bii';
      		 
       
      		 
      connection default;
      		 
      SET DEBUG_SYNC = 'now WAIT_FOR lockwait1';
      		 
      # bug#30113362 caused deadlock
      		 
      SET DEBUG_SYNC = 'now SIGNAL resume';
      		 
       
      		 
      connection con1;
      		 
      reap;
      		 
      connection con2;
      		 
      reap;
      		 
      disconnect purge_control;
      		 
      connection default;
      		 
       
      		 
      SET DEBUG_SYNC = 'RESET';
      		 
       
      		 
      DROP TABLE t1;
      		 
       
      		 
      --disable_query_log
      		 
      SET GLOBAL innodb_limit_optimistic_insert_debug = @old_innodb_limit_optimistic_insert_debug;
      		 
      SET GLOBAL innodb_adaptive_hash_index = @old_innodb_adaptive_hash_index;
      		 
      SET GLOBAL innodb_stats_persistent = @old_innodb_stats_persistent;
      		 
      --enable_query_log
      		 
       
      		 
      --source include/wait_until_count_sessions.inc

      10.2 bb8226deabd177d70151d5e0729bf08533954ffd

      		 
      mysqltest: At line 115: query 'reap' failed: 2013: Lost connection to MySQL server during query
      		 
      …
      		 
      2020-01-17  9:15:04 139752220287808 [Note] /dev/shm/10.2/sql/mysqld: ready for connections.
      		 
      Version: '10.2.31-MariaDB-debug-log'  socket: '/dev/shm/10.2/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
      		 
      ########################################
      		 
      DEADLOCK of threads detected!
      		 
      rw-lock 0x7f1a8f7cb538 --Thread 139752132396800 has waited at btr0cur.cc line 5787 for 0.00 seconds the semaphore:
      		 
      S-lock on RW-latch at 0x7f1a8f7cb538 created in file buf0buf.cc line 1540
      		 
      a writer (thread id 139752132704000) has reserved it in mode  exclusive
      		 
      number of readers 0, waiters flag 1, lock_word: ffffffffdffffff9
      		 
      Last time read locked in file btr0cur.cc line 5733
      		 
      Last time write locked in file btr0cur.cc line 2046
      		 
      Locked: thread 139752132704000 file btr0cur.cc line 2046  X-LOCK
      		 
      rw-lock 0x7f1a8f7c2858 --Thread 139752132704000 has waited at btr0cur.cc line 2046 for 0.00 seconds the semaphore:
      		 
      X-lock (wait_ex) on RW-latch at 0x7f1a8f7c2858 created in file buf0buf.cc line 1540
      		 
      a writer (thread id 139752132704000) has reserved it in mode  wait exclusive
      		 
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      		 
      Last time read locked in file btr0cur.cc line 5787
      		 
      Last time write locked in file btr0cur.cc line 2046
      		 
      Locked: thread 139752132396800 file btr0cur.cc line 5787  S-LOCK
      		 
      Locked: thread 139752132396800 file btr0cur.cc line 5787  S-LOCK
      		 
      2020-01-17  9:15:04 139752132704000 [ERROR] [FATAL] InnoDB: ######################################## Deadlock Detected!
      		 
      200117  9:15:04 [ERROR] mysqld got signal 6 ;
      		 
      …
      		 
      #5  0x000055d87f1bb76a in ib::fatal::~fatal (this=0x7f1a94398c00) at /mariadb/10.2o/storage/innobase/ut/ut0ut.cc:645
      		 
      #6  0x000055d87f166801 in sync_array_wait_event (arr=0x55d882389970, cell=<optimized out>) at /mariadb/10.2o/storage/innobase/sync/sync0arr.cc:463
      		 
      #7  0x000055d87f16af83 in rw_lock_x_lock_wait_func (lock=0x7f1a8f7c2858, pass=0, threshold=0, file_name=0x55d87f64dd88 "/mariadb/10.2o/storage/innobase/btr/btr0cur.cc", line=2046) at /mariadb/10.2o/storage/innobase/sync/sync0rw.cc:452
      		 
      #8  0x000055d87f169d73 in rw_lock_x_lock_low (lock=0x7f1a8f7c2858, pass=0, file_name=0x55d87f64dd88 "/mariadb/10.2o/storage/innobase/btr/btr0cur.cc", line=2046) at /mariadb/10.2o/storage/innobase/sync/sync0rw.cc:508
      		 
      #9  0x000055d87f1697e2 in rw_lock_x_lock_func (lock=0x7f1a8f7c2858, pass=0, file_name=0x55d87f64dd88 "/mariadb/10.2o/storage/innobase/btr/btr0cur.cc", line=2046) at /mariadb/10.2o/storage/innobase/sync/sync0rw.cc:659
      		 
      #10 0x000055d87f221dae in pfs_rw_lock_x_lock_func (lock=0x7f1a8f7c2858, pass=0, file_name=0x55d87f64dd88 "/mariadb/10.2o/storage/innobase/btr/btr0cur.cc", line=<optimized out>) at /mariadb/10.2o/storage/innobase/include/sync0rw.ic:544
      		 
      #11 buf_page_get_gen (page_id=..., page_size=..., rw_latch=<optimized out>, guess=0x0, mode=<optimized out>, file=0x55d87f64dd88 "/mariadb/10.2o/storage/innobase/btr/btr0cur.cc", line=2046, mtr=0x7f1a9439c000, err=0x7f1a94399320) at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:4888
      		 
      #12 0x000055d87f1e3c80 in btr_block_get_func (page_id=..., page_size=..., mode=2, file=0x7f1a94398970 "\ap\b", line=2046, index=0x7f1a3401e508, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/include/btr0btr.ic:61
      		 
      #13 btr_cur_search_to_nth_level (index=<optimized out>, level=<optimized out>, tuple=<optimized out>, mode=<optimized out>, latch_mode=<optimized out>, cursor=<optimized out>, has_search_latch=0, file=0x55d87f64a68f "/mariadb/10.2o/storage/innobase/btr/btr0btr.cc", line=973, mtr=0x7f1a9439c000, autoinc=0) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:2044
      		 
      #14 0x000055d87f1bee8a in btr_page_get_father_node_ptr_func (offsets=<optimized out>, heap=<optimized out>, cursor=0x7f1a9439a2e0, latch_mode=<optimized out>, file=0x55d87f64a68f "/mariadb/10.2o/storage/innobase/btr/btr0btr.cc", line=973, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:876
      		 
      #15 0x000055d87f1be97e in btr_page_get_father (index=<optimized out>, block=0x7f1a8f7cb470, mtr=0x7f1a9439c000, cursor=0x7f1a9439a2e0) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:973
      		 
      #16 0x000055d87f1f503d in btr_cur_pessimistic_delete (err=0x7f1a9439a4c4, has_reserved_extents=<optimized out>, cursor=0x7f1a9439a570, flags=16, rollback=<optimized out>, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5350
      		 
      #17 0x000055d87f1f5b75 in btr_cur_node_ptr_delete (parent=0x7f1a9439a570, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5434
      		 
      #18 0x000055d87f1cd4d5 in btr_compress (cursor=<optimized out>, adjust=<optimized out>, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:3717
      		 
      #19 0x000055d87f1f2242 in btr_cur_compress_if_useful (cursor=0x7f1a9439ac10, adjust=0, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5069
      		 
      #20 0x000055d87f1f5192 in btr_cur_pessimistic_delete (err=0x7f1a9439ab64, has_reserved_extents=<optimized out>, cursor=0x7f1a9439ac10, flags=16, rollback=<optimized out>, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5391
      		 
      #21 0x000055d87f1f5b75 in btr_cur_node_ptr_delete (parent=0x7f1a9439ac10, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5434
      		 
      #22 0x000055d87f1cd4d5 in btr_compress (cursor=<optimized out>, adjust=<optimized out>, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:3717
      		 
      #23 0x000055d87f1f2242 in btr_cur_compress_if_useful (cursor=0x7f1a9439b2b0, adjust=0, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5069
      		 
      #24 0x000055d87f1f5192 in btr_cur_pessimistic_delete (err=0x7f1a9439b204, has_reserved_extents=<optimized out>, cursor=0x7f1a9439b2b0, flags=16, rollback=<optimized out>, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5391
      		 
      #25 0x000055d87f1f5b75 in btr_cur_node_ptr_delete (parent=0x7f1a9439b2b0, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5434
      		 
      #26 0x000055d87f1cd4d5 in btr_compress (cursor=<optimized out>, adjust=<optimized out>, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:3717
      		 
      #27 0x000055d87f1f2242 in btr_cur_compress_if_useful (cursor=0x7f1a9439b950, adjust=0, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5069
      		 
      #28 0x000055d87f1f5192 in btr_cur_pessimistic_delete (err=0x7f1a9439b8a4, has_reserved_extents=<optimized out>, cursor=0x7f1a9439b950, flags=16, rollback=<optimized out>, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5391
      		 
      #29 0x000055d87f1f5b75 in btr_cur_node_ptr_delete (parent=0x7f1a9439b950, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5434
      		 
      #30 0x000055d87f1cd4d5 in btr_compress (cursor=<optimized out>, adjust=<optimized out>, mtr=<optimized out>) at /mariadb/10.2o/storage/innobase/btr/btr0btr.cc:3717
      		 
      #31 0x000055d87f1f2242 in btr_cur_compress_if_useful (cursor=0x7f1a34069488, adjust=0, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5069
      		 
      #32 0x000055d87f1f5192 in btr_cur_pessimistic_delete (err=0x7f1a9439bf50, has_reserved_extents=<optimized out>, cursor=0x7f1a34069488, flags=0, rollback=<optimized out>, mtr=0x7f1a9439c000) at /mariadb/10.2o/storage/innobase/btr/btr0cur.cc:5391
      		 
      #33 0x000055d87f32755b in row_undo_mod_remove_clust_low (node=0x7f1a34069418, mtr=<optimized out>, mode=<optimized out>) at /mariadb/10.2o/storage/innobase/row/row0umod.cc:238
      		 
      #34 0x000055d87f3237d9 in row_undo_mod_clust (node=0x7f1a34069418, thr=<optimized out>) at /mariadb/10.2o/storage/innobase/row/row0umod.cc:396
      		 
      #35 row_undo_mod (node=0x7f1a34069418, thr=<optimized out>) at /mariadb/10.2o/storage/innobase/row/row0umod.cc:1277
      		 
      #36 0x000055d87f13c02e in row_undo (node=<optimized out>, thr=0x7f1a3401db90) at /mariadb/10.2o/storage/innobase/row/row0undo.cc:303
      		 
      #37 row_undo_step (thr=0x7f1a3401db90) at /mariadb/10.2o/storage/innobase/row/row0undo.cc:351
      		 
      #38 0x000055d87f0afe48 in que_thr_step (thr=<optimized out>) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1038
      		 
      #39 que_run_threads_low (thr=0x7f1a3401db90) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1102
      		 
      #40 que_run_threads (thr=0x7f1a3401db90) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1142
      		 
      #41 0x000055d87f195436 in trx_rollback_to_savepoint_low (trx=0x7f1a947bb268, savept=0x0) at /mariadb/10.2o/storage/innobase/trx/trx0roll.cc:107
      		 
      #42 0x000055d87f195bb3 in trx_rollback_for_mysql (trx=0x7f1a947bb268) at /mariadb/10.2o/storage/innobase/trx/trx0roll.cc:242
      		 
      #43 0x000055d87efe6285 in innobase_rollback (hton=<optimized out>, thd=0x7f1a34000ce8, rollback_trx=true) at /mariadb/10.2o/storage/innobase/handler/ha_innodb.cc:4834
      		 
      #44 0x000055d87ee089c5 in ha_rollback_trans (thd=0x7f1a34000ce8, all=true) at /mariadb/10.2o/sql/handler.cc:1707
      		 
      #45 0x000055d87ed383bf in trans_rollback (thd=0x7f1a34000ce8) at /mariadb/10.2o/sql/transaction.cc:415
      		 
      #46 0x000055d87ec310b2 in mysql_execute_command (thd=0x7f1a34000ce8) at /mariadb/10.2o/sql/sql_parse.cc:5358
      		 
      #47 0x000055d87ec2cfc4 in mysql_parse (thd=0x7f1a34000ce8, rawbuf=0x7f1a34010790 "ROLLBACK", length=<optimized out>, parser_state=0x7f1a9439e300, is_com_multi=<optimized out>, is_next_command=false) at /mariadb/10.2o/sql/sql_parse.cc:7740

      A deadlock might not always be detected. Instead, the server could hang, and we could get the infamous ‘long semaphore wait’ messages before InnoDB would finally kill itself after some 10 to 15 minutes.

      The hang is caused by an incorrect prediction that was made by the predicate btr_cur_will_modify_tree().

      Attachments

        Issue Links

          blocks

          Bug - A problem which impairs or prevents the functions of the product. MDEV-21499 Merge new release of InnoDB 5.7.29 to 10.2

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14637 Latching order violation during btr_cur_pessimistic_delete()

          • Major - Major loss of function.
          • Closed

          Activity

            People

              marko Marko Mäkelä
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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