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

Assertion `log->blobs' failed in row_log_table_apply_update

Details

    Description

      Apparently belongs to the MDEV-14693 family.

      10.2 a05018977

      		 
      mysqld: /data/src/10.2/storage/innobase/row/row0log.cc:1985: dberr_t row_log_table_apply_update(que_thr_t*, ulint, const mrec_t*, const ulint*, mem_heap_t*, mem_heap_t*, row_merge_dup_t*, trx_id_t, const dtuple_t*): Assertion `log->blobs' failed.
      		 
      180309 17:43:15 [ERROR] mysqld got signal 6 ;
      		 
       
      		 
      Query (0x7eff34013618): ALTER TABLE `AA` ADD COLUMN c INTEGER DEFAULT NULL /* QNO 2942 CON_ID 16 */
      		 
      Connection ID (thread ID): 16
      		 
      Status: KILL_TIMEOUT


      #7  0x00007fe3fc442ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      		 
      #8  0x0000560a3f71a73b in row_log_table_apply_update (thr=0x7fe388685620, new_trx_id_col=1, mrec=0x7fe3e00c7202 "\200", offsets=0x7fe388055920, offsets_heap=0x7fe3884b9940, heap=0x7fe3886dd470, dup=0x7fe3e0ef02e0, trx_id=6660, old_pk=0x7fe3886dd4f8) at /data/src/10.2/storage/innobase/row/row0log.cc:1985
      		 
      #9  0x0000560a3f71c061 in row_log_table_apply_op (thr=0x7fe388685620, trx_id_col=1, new_trx_id_col=1, dup=0x7fe3e0ef02e0, error=0x7fe3e0ef0084, offsets_heap=0x7fe3884b9940, heap=0x7fe3886dd470, mrec=0x7fe3e00c7202 "\200", mrec_end=0x7fe3e00d3b9c "", offsets=0x7fe388055920) at /data/src/10.2/storage/innobase/row/row0log.cc:2540
      		 
      #10 0x0000560a3f71d4bf in row_log_table_apply_ops (thr=0x7fe388685620, dup=0x7fe3e0ef02e0, stage=0x7fe388565430) at /data/src/10.2/storage/innobase/row/row0log.cc:2909
      		 
      #11 0x0000560a3f71d9ca in row_log_table_apply (thr=0x7fe388685620, old_table=0x7fe374189e88, table=0x7fe38805f050, stage=0x7fe388565430) at /data/src/10.2/storage/innobase/row/row0log.cc:3008
      		 
      #12 0x0000560a3f6048ae in ha_innobase::inplace_alter_table (this=0x7fe3741b1fa8, altered_table=0x7fe38805f050, ha_alter_info=0x7fe3e0ef0610) at /data/src/10.2/storage/innobase/handler/handler0alter.cc:6488
      		 
      #13 0x0000560a3f11a8f7 in handler::ha_inplace_alter_table (this=0x7fe3741b1fa8, altered_table=0x7fe38805f050, ha_alter_info=0x7fe3e0ef0610) at /data/src/10.2/sql/handler.h:3775
      		 
      #14 0x0000560a3f1117b1 in mysql_inplace_alter_table (thd=0x7fe388000ba0, table_list=0x7fe388013768, table=0x7fe3741b13a0, altered_table=0x7fe38805f050, ha_alter_info=0x7fe3e0ef0610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fe3e0ef0680, alter_ctx=0x7fe3e0ef1240) at /data/src/10.2/sql/sql_table.cc:7332
      		 
      #15 0x0000560a3f116de4 in mysql_alter_table (thd=0x7fe388000ba0, new_db=0x7fe388013d78 "test", new_name=0x0, create_info=0x7fe3e0ef1e50, table_list=0x7fe388013768, alter_info=0x7fe3e0ef1da0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9353
      		 
      #16 0x0000560a3f190954 in Sql_cmd_alter_table::execute (this=0x7fe388013f20, thd=0x7fe388000ba0) at /data/src/10.2/sql/sql_alter.cc:324
      		 
      #17 0x0000560a3f04bc57 in mysql_execute_command (thd=0x7fe388000ba0) at /data/src/10.2/sql/sql_parse.cc:6208
      		 
      #18 0x0000560a3f0505d1 in mysql_parse (thd=0x7fe388000ba0, rawbuf=0x7fe388013618 "ALTER TABLE `E` ADD COLUMN m INTEGER DEFAULT NULL /* QNO 3376 CON_ID 16 */", length=74, parser_state=0x7fe3e0ef3200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7902
      		 
      #19 0x0000560a3f03e4f1 in dispatch_command (command=COM_QUERY, thd=0x7fe388000ba0, packet=0x7fe38807ed41 "ALTER TABLE `E` ADD COLUMN m INTEGER DEFAULT NULL /* QNO 3376 CON_ID 16 */ ", packet_length=75, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1806
      		 
      #20 0x0000560a3f03ce54 in do_command (thd=0x7fe388000ba0) at /data/src/10.2/sql/sql_parse.cc:1360
      		 
      #21 0x0000560a3f18b646 in do_handle_one_connection (connect=0x560a41e93610) at /data/src/10.2/sql/sql_connect.cc:1335
      		 
      #22 0x0000560a3f18b3d3 in handle_one_connection (arg=0x560a41e93610) at /data/src/10.2/sql/sql_connect.cc:1241
      		 
      #23 0x0000560a3f5ab1f8 in pfs_spawn_thread (arg=0x560a41f35e50) at /data/src/10.2/storage/perfschema/pfs.cc:1862
      		 
      #24 0x00007fe3fe119494 in start_thread (arg=0x7fe3e0ef4700) at pthread_create.c:333
      		 
      #25 0x00007fe3fc4ff93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

      Getting it periodically on 10.2 while running

      experimental f6acdbc55e206

      		 
      perl ./runall-trials.pl --trials=20 --duration=350 --threads=6 --seed=1520525874 --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --transformers=ExecuteAsCTE,ExecuteAsDeleteReturning,ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,ExecuteAsPreparedTwice,ExecuteAsSPTwice --redefine=conf/mariadb/general-workarounds.yy --mysqld=--log_output=FILE --views --vcols --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/xa.yy --basedir=/data/bld/10.2 --mysqld=--log_bin_trust_function_creators=1 --mysqld=--log-bin --mysqld=--max-statement-time=30 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/runtime/performance_schema.yy --mysqld=--performance-schema --engine=InnoDB --vardir=/data/logs/travis3 --force

      No reliable information about other version. Most likely isn't worth digging, because root cause is likely to be the same as for the rest of MDEV-14693 family.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23310 InnoDB fails to refuse ALTER ONLINE TABLE when no PRIMARY KEY exists

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14693 XA: Assertion `!clust_index->online_log' failed in rollback_inplace_alter_table

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15490 XA: ASAN heap-use-after-free or valgrind Invalid write in trx_update_mod_tables_timestamp

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15518 XA: Server crash or ASAN heap-use-after-free in ha_innobase::delete_table

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15532 XA: Assertion `!log->same_pk' failed in row_log_table_apply_delete

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-23244 ALTER TABLE…ADD PRIMARY KEY fails to flag duplicate key error from concurrent DML

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 9 older comments
            marko Marko Mäkelä added a comment - - edited

            I filed MDEV-23310 for the bug that I think should be repeatable without involving XA transactions. But, in the end, I determined that there is no problem to allow an online table rebuild when no PRIMARY KEY exists. The operation is like any table rebuild where the PRIMARY KEY is being preserved.

            That being said, it is more convenient to debug cases where an explicit PRIMARY KEY exists.

            marko Marko Mäkelä added a comment - - edited I filed MDEV-23310 for the bug that I think should be repeatable without involving XA transactions. But, in the end, I determined that there is no problem to allow an online table rebuild when no PRIMARY KEY exists. The operation is like any table rebuild where the PRIMARY KEY is being preserved. That being said, it is more convenient to debug cases where an explicit PRIMARY KEY exists.
            marko Marko Mäkelä added a comment -

            I can repeat the crash on 10.2 with the latest test case. It failed on the first try both with and without the -rr option. The log>tail.block contains the following records:
            ROW_T_UPDATE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(update),a=3)
            ROW_T_UPDATE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(update),a=3)
            ROW_T_UPDATE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert2),a=2)
            ROW_T_UPDATE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert1),a=1)
            ROW_T_DELETE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert2))
            ROW_T_DELETE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert1))

            In this log, everything would be fine if also the initial two INSERT rows of the XA BEGIN 'x' transaction were present. In that case, the online ALTER would have copied the empty table and then applied the log for the concurrent rolled-back transaction, ending up with an empty table again.

            Clearly, something is wrongly allowing the ALTER TABLE t1 FORCE to start while that transaction is active and accessing the table. As expected, the MDL was incorrectly released by a statement that returned an error. Maybe the erroneous UPDATE is needed as well, but the FLUSH TABLES is what will violate the design constraints:

            10.2 3c3f172f17de217389bc51053c555a5d7e91ddff

            		 
            Thread 29 hit Breakpoint 1, MDL_context::release_transactional_locks (
            		 
                this=0x7f7900000e48) at /mariadb/10.2o/sql/mdl.cc:2843
            		 
            2843	{
            		 
            (rr) bt
            		 
            #0  MDL_context::release_transactional_locks (this=0x7f7900000e48)
            		 
                at /mariadb/10.2o/sql/mdl.cc:2843
            		 
            #1  0x000055f2bce3ce1d in mysql_execute_command (thd=0x7f7900000d28)
            		 
                at /mariadb/10.2o/sql/sql_parse.cc:6080
            		 
            #2  0x000055f2bce33564 in mysql_parse (thd=0x7f7900000d28, 
                rawbuf=0x7f7900011970 "FLUSH TABLES", length=<optimized out>, 
                parser_state=0x7f796405d6d0, is_com_multi=<optimized out>, 
                is_next_command=false) at /mariadb/10.2o/sql/sql_parse.cc:7733
            		 
            …
            		 
            (rr) break ha_innobase::prepare_inplace_alter_table
            		 
            Breakpoint 2 at 0x55f2bd1e8570: file /mariadb/10.2o/storage/innobase/handler/handler0alter.cc, line 5326.
            		 
            (rr) when
            		 
            Current event: 118228
            		 
            (rr) c
            		 
            Continuing.
            		 
            [Switching to Thread 539985.540023]
            		 
             
            		 
            Thread 3 hit Breakpoint 2, ha_innobase::prepare_inplace_alter_table (

            The MDL is being released in a different piece of the code than in MDEV-15532:

              else if (stmt_causes_implicit_commit(thd, CF_IMPLICIT_COMMIT_END))
            		 
              {
            		 
                /* No transaction control allowed in sub-statements. */
            		 
                DBUG_ASSERT(! thd->in_sub_stmt);
            		 
                if (!(thd->variables.option_bits & OPTION_GTID_BEGIN))
            		 
                {
            		 
                  /* If commit fails, we should be able to reset the OK status. */
            		 
                  thd->get_stmt_da()->set_overwrite_status(true);
            		 
                  /* Commit the normal transaction if one is active. */
            		 
                  trans_commit_implicit(thd);
            		 
                  thd->get_stmt_da()->set_overwrite_status(false);
            		 
                  thd->mdl_context.release_transactional_locks();
            		 
                }
            		 
              }

            marko Marko Mäkelä added a comment - I can repeat the crash on 10.2 with the latest test case. It failed on the first try both with and without the - rr option. The log >tail.block contains the following records: ROW_T_UPDATE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(update),a=3) ROW_T_UPDATE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(update),a=3) ROW_T_UPDATE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert2),a=2) ROW_T_UPDATE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert1),a=1) ROW_T_DELETE(pk=2,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert2)) ROW_T_DELETE(pk=1,DB_TRX_ID=0x504,DB_ROLL_PTR=(insert1)) In this log, everything would be fine if also the initial two INSERT rows of the XA BEGIN 'x' transaction were present. In that case, the online ALTER would have copied the empty table and then applied the log for the concurrent rolled-back transaction, ending up with an empty table again. Clearly, something is wrongly allowing the ALTER TABLE t1 FORCE to start while that transaction is active and accessing the table. As expected, the MDL was incorrectly released by a statement that returned an error. Maybe the erroneous UPDATE is needed as well, but the FLUSH TABLES is what will violate the design constraints: 10.2 3c3f172f17de217389bc51053c555a5d7e91ddff Thread 29 hit Breakpoint 1, MDL_context::release_transactional_locks ( this=0x7f7900000e48) at /mariadb/10.2o/sql/mdl.cc:2843 2843 { (rr) bt #0 MDL_context::release_transactional_locks (this=0x7f7900000e48) at /mariadb/10.2o/sql/mdl.cc:2843 #1 0x000055f2bce3ce1d in mysql_execute_command (thd=0x7f7900000d28) at /mariadb/10.2o/sql/sql_parse.cc:6080 #2 0x000055f2bce33564 in mysql_parse (thd=0x7f7900000d28, rawbuf=0x7f7900011970 "FLUSH TABLES", length=<optimized out>, parser_state=0x7f796405d6d0, is_com_multi=<optimized out>, is_next_command=false) at /mariadb/10.2o/sql/sql_parse.cc:7733 … (rr) break ha_innobase::prepare_inplace_alter_table Breakpoint 2 at 0x55f2bd1e8570: file /mariadb/10.2o/storage/innobase/handler/handler0alter.cc, line 5326. (rr) when Current event: 118228 (rr) c Continuing. [Switching to Thread 539985.540023]   Thread 3 hit Breakpoint 2, ha_innobase::prepare_inplace_alter_table ( The MDL is being released in a different piece of the code than in MDEV-15532 : else if (stmt_causes_implicit_commit(thd, CF_IMPLICIT_COMMIT_END)) { /* No transaction control allowed in sub-statements. */ DBUG_ASSERT(! thd->in_sub_stmt); if (!(thd->variables.option_bits & OPTION_GTID_BEGIN)) { /* If commit fails, we should be able to reset the OK status. */ thd->get_stmt_da()->set_overwrite_status( true ); /* Commit the normal transaction if one is active. */ trans_commit_implicit(thd); thd->get_stmt_da()->set_overwrite_status( false ); thd->mdl_context.release_transactional_locks(); } }
            wlad Vladislav Vaintroub added a comment -

            Not able to reproduce the mtr example crash, seems to be fixed with MDEV-14693

            wlad Vladislav Vaintroub added a comment - Not able to reproduce the mtr example crash, seems to be fixed with MDEV-14693
            elenst Elena Stepanova added a comment -

            It was actually fixed with MDEV-15532.
            It is still easily enough reproducible on a previous commit, but not since this one:

            commit 828471cbf83774f4537a78551290b7a4a7f5d374
            		 
            Author: Monty
            		 
            Date:   Mon Nov 30 15:29:32 2020 +0200
            		 
             
            		 
                MDEV 15532 Assertion `!log->same_pk' failed in row_log_table_apply_delete

            elenst Elena Stepanova added a comment - It was actually fixed with MDEV-15532 . It is still easily enough reproducible on a previous commit, but not since this one: commit 828471cbf83774f4537a78551290b7a4a7f5d374 Author: Monty Date: Mon Nov 30 15:29:32 2020 +0200   MDEV 15532 Assertion `!log->same_pk' failed in row_log_table_apply_delete
            wlad Vladislav Vaintroub added a comment -

            yes, a small mixup.

            wlad Vladislav Vaintroub added a comment - yes, a small mixup.

            People

              wlad Vladislav Vaintroub
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              7 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.