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

InnoDB: Fix the bogus debug assertion introduced in MDEV-12219

Details

    Description

      It's a regression introduced by this commit:

      commit 13e5c9de800254dc80a4ba4cc98d788be899acb6
      Author: Marko Mäkelä <marko.makela@mariadb.com>
      Date:   Thu Mar 9 23:20:51 2017 +0200
       
          MDEV-12219 Discard temporary undo logs at transaction commit
      

      10.2 a77c2ea78f76c07446a3014052cb8c3b74c4860c

      2017-03-14 19:46:30 0x7f8c225a9300  InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/trx/trx0roll.cc line 998
      InnoDB: Failing assertion: !insert || !update || !insert->top_undo_no || insert->top_undo_no != update->top_undo_no
      InnoDB: We intentionally generate a memory trap.
       
      #6  0x00007f8c21c3f526 in ut_dbg_assertion_failed (expr=0x7f8c220c4668 "!insert || !update || !insert->top_undo_no || insert->top_undo_no != update->top_undo_no", file=0x7f8c220c40f0 "/data/src/10.2/storage/innobase/trx/trx0roll.cc", line=998) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
      #7  0x00007f8c21c1fc19 in trx_roll_pop_top_rec_of_trx (trx=0x7f8c164008c8, roll_ptr=0x7f8c058878d0, heap=0x7f8c05a90380) at /data/src/10.2/storage/innobase/trx/trx0roll.cc:997
      #8  0x00007f8c21bb8d78 in row_undo (node=0x7f8c05887888, thr=0x7f8c059f8c60) at /data/src/10.2/storage/innobase/row/row0undo.cc:273
      #9  0x00007f8c21bb8f9b in row_undo_step (thr=0x7f8c059f8c60) at /data/src/10.2/storage/innobase/row/row0undo.cc:348
      #10 0x00007f8c21b14576 in que_thr_step (thr=0x7f8c059f8c60) at /data/src/10.2/storage/innobase/que/que0que.cc:1055
      #11 0x00007f8c21b14794 in que_run_threads_low (thr=0x7f8c059f8c60) at /data/src/10.2/storage/innobase/que/que0que.cc:1119
      #12 0x00007f8c21b14946 in que_run_threads (thr=0x7f8c059f8c60) at /data/src/10.2/storage/innobase/que/que0que.cc:1159
      #13 0x00007f8c21c1d7c1 in trx_rollback_to_savepoint_low (trx=0x7f8c164008c8, savept=0x7f8c16400c08) at /data/src/10.2/storage/innobase/trx/trx0roll.cc:122
      #14 0x00007f8c21c1daf2 in trx_rollback_to_savepoint (trx=0x7f8c164008c8, savept=0x7f8c16400c08) at /data/src/10.2/storage/innobase/trx/trx0roll.cc:163
      #15 0x00007f8c21c1e3fe in trx_rollback_last_sql_stat_for_mysql (trx=0x7f8c164008c8) at /data/src/10.2/storage/innobase/trx/trx0roll.cc:323
      #16 0x00007f8c21a1a679 in innobase_rollback (hton=0x7f8c1e04daf0, thd=0x7f8c05816070, rollback_trx=false) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:4935
      #17 0x00007f8c217136ba in ha_rollback_trans (thd=0x7f8c05816070, all=false) at /data/src/10.2/sql/handler.cc:1658
      #18 0x00007f8c216001c0 in trans_rollback_stmt (thd=0x7f8c05816070) at /data/src/10.2/sql/transaction.cc:566
      #19 0x00007f8c214afe2b in mysql_execute_command (thd=0x7f8c05816070) at /data/src/10.2/sql/sql_parse.cc:6225
      #20 0x00007f8c214b4540 in mysql_parse (thd=0x7f8c05816070, rawbuf=0x7f8c05864088 "INSERT INTO t2 VALUES (4)", length=25, parser_state=0x7f8c225a7dd0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7858
      #21 0x00007f8c214a2606 in dispatch_command (command=COM_QUERY, thd=0x7f8c05816070, packet=0x7f8c05858071 "INSERT INTO t2 VALUES (4)", packet_length=25, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1812
      #22 0x00007f8c214a0f76 in do_command (thd=0x7f8c05816070) at /data/src/10.2/sql/sql_parse.cc:1362
      #23 0x00007f8c215e9f47 in do_handle_one_connection (connect=0x7f8c1e0656b0) at /data/src/10.2/sql/sql_connect.cc:1354
      #24 0x00007f8c215e9cd4 in handle_one_connection (arg=0x7f8c1e0656b0) at /data/src/10.2/sql/sql_connect.cc:1260
      #25 0x00007f8c21a021fc in pfs_spawn_thread (arg=0x7f8c157ce870) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      #26 0x00007f8c20acb064 in start_thread (arg=0x7f8c225a9300) at pthread_create.c:309
      #27 0x00007f8c1ec8362d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
       
      Query (0x7f8c05864088): INSERT INTO t2 VALUES (4)
      Connection ID (thread ID): 8
      Status: NOT_KILLED
      

      Test case

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (i INT) ENGINE=InnoDB;
      CREATE TABLE t2 (i INT) ENGINE=InnoDB;
      CREATE TABLE t3 (i INT) ENGINE=InnoDB;
       
      CREATE OR REPLACE TRIGGER tr1
        AFTER UPDATE ON t2
        FOR EACH ROW
        INSERT INTO tlog (i) VALUES (1);
       
      INSERT IGNORE INTO t2 VALUES (1);
       
      CREATE TRIGGER IF NOT EXISTS tr2
        BEFORE INSERT ON t2
        FOR EACH ROW
        INSERT INTO tlog (i) VALUES (2);
       
      START TRANSACTION;
      INSERT INTO t1 VALUES (1);
      --error ER_NO_SUCH_TABLE
      UPDATE t2 SET i = 3;
      INSERT INTO t3 VALUES (1);
      INSERT INTO t2 VALUES (4);
      COMMIT;
      

      Attachments

        Issue Links

          Activity

            MDEV-12219 added this assertion. MDEV-12288 would merge the two persistent undo logs into one and remove this possibility of inconsistency (and remove the assertion as well).

            It is possible that this is sharing a root cause with MySQL Bug#55283 assert trx0roll.c undo_no + 1 == trx->undo_no in trx_rollback_or_clean_all_recov. That bug is harder to reproduce, because it would require the server to be killed and restarted at the right moment. That bug was filed in 2010. If I remember correctly, it was originally filed in an InnoDB internal bug tracking system a couple of years earlier.

            marko Marko Mäkelä added a comment - MDEV-12219 added this assertion. MDEV-12288 would merge the two persistent undo logs into one and remove this possibility of inconsistency (and remove the assertion as well). It is possible that this is sharing a root cause with MySQL Bug#55283 assert trx0roll.c undo_no + 1 == trx->undo_no in trx_rollback_or_clean_all_recov . That bug is harder to reproduce, because it would require the server to be killed and restarted at the right moment. That bug was filed in 2010. If I remember correctly, it was originally filed in an InnoDB internal bug tracking system a couple of years earlier.

            marko, I'm afraid it is not good enough. MDEV-12288 is only targeted for 10.3, which means this assertion failure will stay in 10.2 forever. Even if it's a true debug assertion and doesn't happen on release builds as other InnoDB assertions do, still, it's a very simple and common use case, it is going to be a testing nightmare for the rest of 10.2 life. Please do something about it in 10.2.

            elenst Elena Stepanova added a comment - marko , I'm afraid it is not good enough. MDEV-12288 is only targeted for 10.3, which means this assertion failure will stay in 10.2 forever. Even if it's a true debug assertion and doesn't happen on release builds as other InnoDB assertions do, still, it's a very simple and common use case, it is going to be a testing nightmare for the rest of 10.2 life. Please do something about it in 10.2.

            Here is what happens after the START TRANSACTION:
            First, the INSERT is undo-logged, creating trx->rsegs.m_redo.insert_undo with top_undo_no=0 and size=1.
            Then, the UPDATE is undo-logged, creating trx->rsegs.m_redo.update_undo with top_undo_no=1 and size=1.
            The first partial rollback is for the UPDATE statement. At this point, everything looks good. But, when trx_roll_pop_top_rec_of_trx() is invoking trx_roll_pop_top_rec(), it will only set update_undo->empty=TRUE but leave update_undo->top_undo_no unchanged at top_undo_no=1. This will trip the debug assertion when the second INSERT statement is rolled back, because at that time, we would still have update_undo->empty, update_undo->top_undo_no=1 and insert_undo->top_undo_no=1.

            The debug assertions must be revised to check whether the particular undo log segment is empty, which can be the case after a partial rollback. Previously, a wrong condition top_undo_no==0 was used.

            marko Marko Mäkelä added a comment - Here is what happens after the START TRANSACTION: First, the INSERT is undo-logged, creating trx->rsegs.m_redo.insert_undo with top_undo_no=0 and size=1. Then, the UPDATE is undo-logged, creating trx->rsegs.m_redo.update_undo with top_undo_no=1 and size=1. The first partial rollback is for the UPDATE statement. At this point, everything looks good. But, when trx_roll_pop_top_rec_of_trx() is invoking trx_roll_pop_top_rec(), it will only set update_undo->empty=TRUE but leave update_undo->top_undo_no unchanged at top_undo_no=1. This will trip the debug assertion when the second INSERT statement is rolled back, because at that time, we would still have update_undo->empty, update_undo->top_undo_no=1 and insert_undo->top_undo_no=1. The debug assertions must be revised to check whether the particular undo log segment is empty, which can be the case after a partial rollback. Previously, a wrong condition top_undo_no==0 was used.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              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.