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

XA: Assertion `!clust_index->online_log' failed in rollback_inplace_alter_table

Details

    • 10.2.14

    Description

      --source include/have_innodb.inc
      --source include/have_partition.inc
       
      CREATE TABLE t1 (a INT, b INT) ENGINE=InnoDB PARTITION BY HASH(a) PARTITIONS 2;
      XA START 'xid';
      INSERT INTO t1 VALUES (1,10);
      --error ER_XAER_RMFAIL
      CREATE DATABASE IF NOT EXISTS db;
       
      --connect (con1,localhost,root,,test)
      SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
      ALTER TABLE t1 DROP COLUMN b;
       
      # Cleanup
      --disconnect con1
      --connection default
      XA END 'xid';
      XA ROLLBACK 'xid';
      DROP TABLE t1;
      

      10.0 9216a4f69f11

      mysqld: /data/src/10.0/storage/innobase/handler/handler0alter.cc:4366: bool rollback_inplace_alter_table(Alter_inplace_info*, const TABLE*, row_prebuilt_t*): Assertion `!clust_index->online_log' failed.
      180220 14:28:33 [ERROR] mysqld got signal 6 ;
       
      #7  0x00007fc189c50ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      #8  0x00007fc18276c7d8 in rollback_inplace_alter_table (ha_alter_info=0x7fc18bcc7260, table=0x7fc17589e470, prebuilt=0x7fc175a12078) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:4366
      #9  0x00007fc182769f39 in ha_innodb::commit_inplace_alter_table (this=0x7fc175880088, altered_table=0x7fc175ce4070, ha_alter_info=0x7fc18bcc7260, commit=false) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5640
      #10 0x0000000000842aad in handler::ha_commit_inplace_alter_table (this=0x7fc175880088, altered_table=0x7fc175ce4070, ha_alter_info=0x7fc18bcc7260, commit=false) at /data/src/10.0/sql/handler.cc:4226
      #11 0x0000000000df87ed in ha_partition::commit_inplace_alter_table (this=0x7fc17587f088, altered_table=0x7fc175ce4070, ha_alter_info=0x7fc18bcc7260, commit=false) at /data/src/10.0/sql/ha_partition.cc:8405
      #12 0x0000000000842aad in handler::ha_commit_inplace_alter_table (this=0x7fc17587f088, altered_table=0x7fc175ce4070, ha_alter_info=0x7fc18bcc7260, commit=false) at /data/src/10.0/sql/handler.cc:4226
      #13 0x0000000000701565 in mysql_inplace_alter_table (thd=0x7fc17e36f070, table_list=0x7fc175c22170, table=0x7fc17589e470, altered_table=0x7fc175ce4070, ha_alter_info=0x7fc18bcc7260, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fc18bcc6cb0, alter_ctx=0x7fc18bcc7840) at /data/src/10.0/sql/sql_table.cc:7232
      #14 0x0000000000705852 in mysql_alter_table (thd=0x7fc17e36f070, new_db=0x7fc175c22750 "test", new_name=0x0, create_info=0x7fc18bcc84e0, table_list=0x7fc175c22170, alter_info=0x7fc18bcc8450, order_num=0, order=0x0, ignore=false) at /data/src/10.0/sql/sql_table.cc:8949
      #15 0x000000000076e2b1 in Sql_cmd_alter_table::execute (this=0x7fc175c22780, thd=0x7fc17e36f070) at /data/src/10.0/sql/sql_alter.cc:312
      #16 0x0000000000654607 in mysql_execute_command (thd=0x7fc17e36f070) at /data/src/10.0/sql/sql_parse.cc:5114
      #17 0x0000000000657a3e in mysql_parse (thd=0x7fc17e36f070, rawbuf=0x7fc175c22088 "ALTER TABLE t1 DROP COLUMN b", length=28, parser_state=0x7fc18bcc9640) at /data/src/10.0/sql/sql_parse.cc:6569
      #18 0x000000000064a57d in dispatch_command (command=COM_QUERY, thd=0x7fc17e36f070, packet=0x7fc17e375071 "ALTER TABLE t1 DROP COLUMN b", packet_length=28) at /data/src/10.0/sql/sql_parse.cc:1296
      #19 0x000000000064987d in do_command (thd=0x7fc17e36f070) at /data/src/10.0/sql/sql_parse.cc:999
      #20 0x0000000000769a04 in do_handle_one_connection (thd_arg=0x7fc17e36f070) at /data/src/10.0/sql/sql_connect.cc:1377
      #21 0x0000000000769776 in handle_one_connection (arg=0x7fc17e36f070) at /data/src/10.0/sql/sql_connect.cc:1292
      #22 0x0000000000aca0fc in pfs_spawn_thread (arg=0x7fc17e319b70) at /data/src/10.0/storage/perfschema/pfs.cc:1861
      #23 0x00007fc18b954494 in start_thread (arg=0x7fc18bcca700) at pthread_create.c:333
      #24 0x00007fc189d0d93f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Reproducible on all of 10.x. Not reproducible on MariaDB 5.5, MySQL 5.6.39, 5.7.21.

      Attachments

        Issue Links

          Activity

            marko Marko Mäkelä added a comment - - edited

            The ALGORITHM=INPLACE code in InnoDB assumes that the table is exclusively locked both at ha_innobase::prepare_inplace_alter_table() and at ha_innobase::commit_inplace_alter_table(). As a work-around for missing WL#6049 (proper metadata lock coverage for FOREIGN KEY operations), InnoDB does try to acquire exclusive transactional table locks at commit. And that is the reason why the ALTER TABLE operation goes to rollback:

            		/* Exclusively lock the table, to ensure that no other
            		transaction is holding locks on the table while we
            		change the table definition. The MySQL meta-data lock
            		should normally guarantee that no conflicting locks
            		exist. However, FOREIGN KEY constraints checks and any
            		transactions collected during crash recovery could be
            		holding InnoDB locks only, not MySQL locks. */
             
            		error = row_merge_lock_table(
            			m_prebuilt->trx, ctx->old_table, LOCK_X);
             
            		if (error != DB_SUCCESS) {
            			my_error_innodb(
            				error, table_share->table_name.str, 0);
            			DBUG_RETURN(true);
            		}
            

            The above is the code in MariaDB 10.2. After the lock timeout, the SQL layer would invoke ha_innobase::commit_inplace_alter_table(commit=false), and during this operation, the assertion inside InnoDB would fail.

            This seems to demonstrate poor error handling in InnoDB. The online_log is actually owned by the ALTER TABLE operation, and InnoDB should free it on failure, instead of complaining that it exists. A similar situation should be possible when the table being ALTERed is being locked as a child or parent table of a FOREIGN KEY operation.

            I will try to create a test case for this. The original test case should be fixed as part of MDEV-15490 outside InnoDB.

            marko Marko Mäkelä added a comment - - edited The ALGORITHM=INPLACE code in InnoDB assumes that the table is exclusively locked both at ha_innobase::prepare_inplace_alter_table() and at ha_innobase::commit_inplace_alter_table() . As a work-around for missing WL#6049 (proper metadata lock coverage for FOREIGN KEY operations), InnoDB does try to acquire exclusive transactional table locks at commit. And that is the reason why the ALTER TABLE operation goes to rollback: /* Exclusively lock the table, to ensure that no other transaction is holding locks on the table while we change the table definition. The MySQL meta-data lock should normally guarantee that no conflicting locks exist. However, FOREIGN KEY constraints checks and any transactions collected during crash recovery could be holding InnoDB locks only, not MySQL locks. */   error = row_merge_lock_table( m_prebuilt->trx, ctx->old_table, LOCK_X);   if (error != DB_SUCCESS) { my_error_innodb( error, table_share->table_name.str, 0); DBUG_RETURN( true ); } The above is the code in MariaDB 10.2. After the lock timeout, the SQL layer would invoke ha_innobase::commit_inplace_alter_table(commit=false) , and during this operation, the assertion inside InnoDB would fail. This seems to demonstrate poor error handling in InnoDB. The online_log is actually owned by the ALTER TABLE operation, and InnoDB should free it on failure, instead of complaining that it exists. A similar situation should be possible when the table being ALTERed is being locked as a child or parent table of a FOREIGN KEY operation. I will try to create a test case for this. The original test case should be fixed as part of MDEV-15490 outside InnoDB.

            I tested the FOREIGN KEY case, and there is no problem with that one: InnoDB will report an error after the exclusive lock acquisition failed at commit, and it would free the online_log as part of the rollback (below is the 10.2 version of the code):

            	if (ctx->need_rebuild()) {
            		dberr_t	err = DB_SUCCESS;
            		ulint	flags	= ctx->new_table->flags;
             
            		/* DML threads can access ctx->new_table via the
            		online rebuild log. Free it first. */
            		innobase_online_rebuild_log_free(prebuilt->table);
            

            So, this bug seems to share a common root cause with MDEV-15490: XA transactions are not using meta-data locks correctly.
            I successfully ran the following test in 10.0, 10.1, 10.2, 10.3:

            --source include/have_innodb.inc
             
            CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
            CREATE TABLE t2 (pk INT PRIMARY KEY,
                             FOREIGN KEY(pk) REFERENCES t1(pk)) ENGINE=InnoDB;
            --error ER_NO_REFERENCED_ROW_2
            INSERT INTO t2 VALUES(1);
            INSERT INTO t1 VALUES(1);
            BEGIN;
            INSERT INTO t2 VALUES(1);
            --connect (con1,localhost,root,,test)
            SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 1;
            --error ER_LOCK_WAIT_TIMEOUT
            ALTER TABLE t1 FORCE, ALGORITHM=INPLACE;
            --disconnect con1
            --connection default
            ROLLBACK;
            DROP TABLE t2,t1;
            

            marko Marko Mäkelä added a comment - I tested the FOREIGN KEY case, and there is no problem with that one: InnoDB will report an error after the exclusive lock acquisition failed at commit, and it would free the online_log as part of the rollback (below is the 10.2 version of the code): if (ctx->need_rebuild()) { dberr_t err = DB_SUCCESS; ulint flags = ctx->new_table->flags;   /* DML threads can access ctx->new_table via the online rebuild log. Free it first. */ innobase_online_rebuild_log_free(prebuilt->table); So, this bug seems to share a common root cause with MDEV-15490 : XA transactions are not using meta-data locks correctly. I successfully ran the following test in 10.0, 10.1, 10.2, 10.3: --source include/have_innodb.inc   CREATE TABLE t1 (pk INT PRIMARY KEY ) ENGINE=InnoDB; CREATE TABLE t2 (pk INT PRIMARY KEY , FOREIGN KEY (pk) REFERENCES t1(pk)) ENGINE=InnoDB; --error ER_NO_REFERENCED_ROW_2 INSERT INTO t2 VALUES (1); INSERT INTO t1 VALUES (1); BEGIN ; INSERT INTO t2 VALUES (1); --connect (con1,localhost,root,,test) SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 1; --error ER_LOCK_WAIT_TIMEOUT ALTER TABLE t1 FORCE , ALGORITHM=INPLACE; --disconnect con1 --connection default ROLLBACK ; DROP TABLE t2,t1;

            Yes and no. Yes, metadata lock would've avoided this crash by preventing ha_innobase::commit_inplace_alter_table from being executed at all.

            But the reason for this bug is different. It's a partitioned InnoDB table with two partitions. Online alter fails for some reason (deadlock in this particular case). The server needs to roll back the changes, it invokes ha_partition::commit_inplace_alter_table(commit=false). It invokes rollback_inplace_alter_table() for the first partition. It frees online log just fine, as you explained above. But then ha_partition invokes rollback_inplace_alter_table() for the second partition. Which does nothing because ctx->trx is NULL. And assert fires, as the online log for the second partition is not freed.

            serg Sergei Golubchik added a comment - Yes and no. Yes, metadata lock would've avoided this crash by preventing ha_innobase::commit_inplace_alter_table from being executed at all. But the reason for this bug is different. It's a partitioned InnoDB table with two partitions. Online alter fails for some reason (deadlock in this particular case). The server needs to roll back the changes, it invokes ha_partition::commit_inplace_alter_table(commit=false) . It invokes rollback_inplace_alter_table() for the first partition. It frees online log just fine, as you explained above. But then ha_partition invokes rollback_inplace_alter_table() for the second partition. Which does nothing because ctx->trx is NULL. And assert fires, as the online log for the second partition is not freed.

            For partitioned tables, all changes should be committed or rolled back when invoking ha_innobase::commit_inplace_alter_table() on the first partition. The MySQL 5.6.11 change to implement this appears to be present in MariaDB 10.0.

            In 10.0, the test case causes an invocation of ha_innobase::commit_inplace_alter_table(commit=true). This call will fail due to row_merge_lock_table() failing to acquire an exclusive transactional lock on the second partition (p1). Then we get subsequent calls to ha_innobase::commit_inplace_alter_table(commit=false), to roll back the ALTER TABLE operation (one call for each partition).

            The error is caused because ha_innobase::commit_inplace_alter_table(commit=true) cleared the ctx->trx of other partitions than the first one, and rollback_inplace_alter_table() would skip some necessary steps.

            It seems simplest to move the freeing of ctx->trx to a later stage. Alternatively, we could make rollback_inplace_alter_table() process all partitions of the table, instead of rolling back changes to each partition in separate commits.

            I will write a DEBUG_SYNC test case so that the test will not have to be rewritten when the XA MDL bug is fixed. This should be repeatable by issuing a locking read on a partition while an online ALTER TABLE is running.

            marko Marko Mäkelä added a comment - For partitioned tables, all changes should be committed or rolled back when invoking ha_innobase::commit_inplace_alter_table() on the first partition. The MySQL 5.6.11 change to implement this appears to be present in MariaDB 10.0. In 10.0, the test case causes an invocation of ha_innobase::commit_inplace_alter_table(commit=true) . This call will fail due to row_merge_lock_table() failing to acquire an exclusive transactional lock on the second partition (p1). Then we get subsequent calls to ha_innobase::commit_inplace_alter_table(commit=false) , to roll back the ALTER TABLE operation (one call for each partition). The error is caused because ha_innobase::commit_inplace_alter_table(commit=true) cleared the ctx->trx of other partitions than the first one, and rollback_inplace_alter_table() would skip some necessary steps. It seems simplest to move the freeing of ctx->trx  to a later stage. Alternatively, we could make rollback_inplace_alter_table() process all partitions of the table, instead of rolling back changes to each partition in separate commits. I will write a DEBUG_SYNC test case so that the test will not have to be rewritten when the XA MDL bug is fixed. This should be repeatable by issuing a locking read on a partition while an online ALTER TABLE is running.

            I wrote a DEBUG_SYNC test case, but it will always result in a MDL timeout, not InnoDB lock timeout. The InnoDB lock timeout can only be reached by exploiting bugs in the MDL. One bug would be the XA scenario in the bug report; another would be to exploit missing MDL coverage for certain FOREIGN KEY operations; however, FOREIGN KEY are not implemented for PARTITION tables.
            For the record, here is my test, which fails to crash the server, because the innodb_lock_wait_timeout is not triggered:

            --source include/have_innodb.inc
            --source include/have_partition.inc
            --source include/have_debug.inc
            --source include/have_debug_sync.inc
             
            CREATE TABLE t1 (a INT UNSIGNED PRIMARY KEY) ENGINE=InnoDB
            PARTITION BY RANGE(a)
            (PARTITION pa VALUES LESS THAN (3),
            PARTITION pb VALUES LESS THAN (5));
             
            INSERT INTO t1 VALUES(2),(4);
             
            SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
            SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL ready WAIT_FOR locked';
            send ALTER TABLE t1 FORCE;
             
            connect dml,localhost,root,,;
            SET DEBUG_SYNC = 'now WAIT_FOR ready';
            BEGIN;
            SELECT * FROM t1 WHERE a=4 LOCK IN SHARE MODE;
            SET DEBUG_SYNC = 'now SIGNAL locked';
             
            connection default;
            --error ER_LOCK_WAIT_TIMEOUT
            reap;
            disconnect dml;
             
            SET DEBUG_SYNC = 'RESET';
            ALTER TABLE t1 FORCE;
            DROP TABLE t1;
            

            marko Marko Mäkelä added a comment - I wrote a DEBUG_SYNC  test case, but it will always result in a MDL timeout, not InnoDB lock timeout. The InnoDB lock timeout can only be reached by exploiting bugs in the MDL. One bug would be the XA scenario in the bug report; another would be to exploit missing MDL coverage for certain FOREIGN KEY operations; however, FOREIGN KEY  are not implemented for PARTITION tables. For the record, here is my test, which fails to crash the server, because the innodb_lock_wait_timeout  is not triggered: --source include/have_innodb.inc --source include/have_partition.inc --source include/have_debug.inc --source include/have_debug_sync.inc   CREATE TABLE t1 (a INT UNSIGNED PRIMARY KEY ) ENGINE=InnoDB PARTITION BY RANGE(a) (PARTITION pa VALUES LESS THAN (3), PARTITION pb VALUES LESS THAN (5));   INSERT INTO t1 VALUES (2),(4);   SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2; SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL ready WAIT_FOR locked' ; send ALTER TABLE t1 FORCE ;   connect dml,localhost,root,,; SET DEBUG_SYNC = 'now WAIT_FOR ready' ; BEGIN ; SELECT * FROM t1 WHERE a=4 LOCK IN SHARE MODE; SET DEBUG_SYNC = 'now SIGNAL locked' ;   connection default ; --error ER_LOCK_WAIT_TIMEOUT reap; disconnect dml;   SET DEBUG_SYNC = 'RESET' ; ALTER TABLE t1 FORCE ; DROP TABLE t1;

            I also tried to trigger this with duplicate key error in a partitioned table, but it did not crash:

            --source include/have_innodb.inc
            --source include/have_partition.inc
            --source include/have_debug.inc
            --source include/have_debug_sync.inc
             
            CREATE TABLE t1 (a INT, b INT) ENGINE=InnoDB
            PARTITION BY RANGE(a)
            (PARTITION pa VALUES LESS THAN (3),
            PARTITION pb VALUES LESS THAN (5));
             
            INSERT INTO t1 VALUES(2,2),(4,4);
             
            SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2;
            SET DEBUG_SYNC = 'inplace_after_index_build SIGNAL ready WAIT_FOR done';
            send ALTER TABLE t1 ADD UNIQUE KEY(a,b), FORCE;
             
            connect dml,localhost,root,,;
            SET DEBUG_SYNC = 'now WAIT_FOR ready';
            INSERT INTO t1 VALUES (4,4);
            SET DEBUG_SYNC = 'now SIGNAL done';
            disconnect dml;
             
            connection default;
            --error ER_DUP_ENTRY
            reap;
             
            SET DEBUG_SYNC = 'RESET';
            DROP TABLE t1;
            

            marko Marko Mäkelä added a comment - I also tried to trigger this with duplicate key error in a partitioned table, but it did not crash: --source include/have_innodb.inc --source include/have_partition.inc --source include/have_debug.inc --source include/have_debug_sync.inc   CREATE TABLE t1 (a INT , b INT ) ENGINE=InnoDB PARTITION BY RANGE(a) (PARTITION pa VALUES LESS THAN (3), PARTITION pb VALUES LESS THAN (5));   INSERT INTO t1 VALUES (2,2),(4,4);   SET innodb_lock_wait_timeout= 1, lock_wait_timeout= 2; SET DEBUG_SYNC = 'inplace_after_index_build SIGNAL ready WAIT_FOR done' ; send ALTER TABLE t1 ADD UNIQUE KEY (a,b), FORCE ;   connect dml,localhost,root,,; SET DEBUG_SYNC = 'now WAIT_FOR ready' ; INSERT INTO t1 VALUES (4,4); SET DEBUG_SYNC = 'now SIGNAL done' ; disconnect dml;   connection default ; --error ER_DUP_ENTRY reap;   SET DEBUG_SYNC = 'RESET' ; DROP TABLE t1;

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.