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

Assertion `!writer.checksum_len || writer.remains == 0' fails upon concurrent online ALTER and transactions with failing statements and binary log enabled

Details

    Description

      Set to blocker as it's a bug in a new feature in a soon-to-be GA.

      --source include/have_binlog_format_mixed.inc
      		 
      --source include/have_innodb.inc
      		 
      --source include/have_debug_sync.inc
      		 
       
      		 
      CREATE TABLE t1 (a INT, b TEXT) ENGINE=InnoDB;
      		 
      CREATE TABLE t2 (a INT, b INT, c CHAR(8), d TEXT, UNIQUE(a)) ENGINE=InnoDB;
      		 
       
      		 
      --connect (con1,localhost,root,,test)
      		 
      START TRANSACTION;
      		 
      CREATE TEMPORARY TABLE tmp (id INT, PRIMARY KEY(id)) ENGINE=InnoDB;
      		 
      INSERT INTO t1 VALUES (1, REPEAT('x',8000)),(2, REPEAT('x',8000));
      		 
      UPDATE t2 SET b = NULL ORDER BY b LIMIT 2;
      		 
      INSERT INTO t1 VALUES (3, REPEAT('x',8000));
      		 
      DELETE FROM t1;
      		 
      INSERT INTO t2 VALUES (1,1,'f','e'),(1000,1000,'c','b');
      		 
      COMMIT;
      		 
      --send
      		 
        SET debug_sync= 'NOW WAIT_FOR go_trx';
      		 
       
      		 
      --connection default
      		 
      SET debug_sync= 'alter_table_online_progress SIGNAL go_trx WAIT_FOR go_alter';
      		 
      --send
      		 
        ALTER TABLE t2 FORCE, ALGORITHM=COPY, LOCK=NONE;
      		 
       
      		 
      --connection con1
      		 
      --reap
      		 
      START TRANSACTION;
      		 
      DROP TEMPORARY TABLE IF EXISTS tmp;
      		 
      --error ER_DUP_ENTRY
      		 
      INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x');
      		 
      COMMIT;
      		 
      set debug_sync= 'NOW SIGNAL go_alter';
      		 
       
      		 
      --connection default
      		 
      --reap
      		 
       
      		 
      # Cleanup
      		 
      DROP TABLE t1, t2;

      11.2 9ad7c899

      		 
      mariadbd: /data/src/11.2/sql/log.cc:8052: int Event_log::write_cache(THD*, IO_CACHE*): Assertion `!writer.checksum_len || writer.remains == 0' failed.
      		 
      230907 20:29:34 [ERROR] mysqld got signal 6 ;
      		 
       
      		 
      #9  0x00007f18bb453df2 in __GI___assert_fail (assertion=0x5583e5c76de0 "!writer.checksum_len || writer.remains == 0", file=0x5583e5c6bf20 "/data/src/11.2/sql/log.cc", line=8052, function=0x5583e5c76b60 "int Event_log::write_cache(THD*, IO_CACHE*)") at ./assert/assert.c:101
      		 
      #10 0x00005583e425af27 in Event_log::write_cache (this=0x5583e7af1f28 <mysql_bin_log+8>, thd=0x62c000240218, cache=0x61b000040038) at /data/src/11.2/sql/log.cc:8052
      		 
      #11 0x00005583e4262515 in MYSQL_BIN_LOG::write_transaction_or_stmt (this=0x5583e7af1f20 <mysql_bin_log>, entry=0x7f18a3249830, commit_id=0) at /data/src/11.2/sql/log.cc:9182
      		 
      #12 0x00005583e425fc6f in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x5583e7af1f20 <mysql_bin_log>, leader=0x7f18a3249830) at /data/src/11.2/sql/log.cc:8902
      		 
      #13 0x00005583e425e773 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x5583e7af1f20 <mysql_bin_log>, entry=0x7f18a3249830) at /data/src/11.2/sql/log.cc:8694
      		 
      #14 0x00005583e425c5d1 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x5583e7af1f20 <mysql_bin_log>, thd=0x62c000240218, cache_mngr=0x61b00003fe98, end_ev=0x7f18a3249cc0, all=true, using_stmt_cache=false, using_trx_cache=true, is_ro_1pc=true) at /data/src/11.2/sql/log.cc:8291
      		 
      #15 0x00005583e4232bf1 in binlog_flush_cache (thd=0x62c000240218, cache_mngr=0x61b00003fe98, end_ev=0x7f18a3249cc0, all=true, using_stmt=false, using_trx=true, is_ro_1pc=true) at /data/src/11.2/sql/log.cc:1907
      		 
      #16 0x00005583e42339f7 in binlog_commit_flush_trx_cache (thd=0x62c000240218, all=true, cache_mngr=0x61b00003fe98, ro_1pc=true) at /data/src/11.2/sql/log.cc:2006
      		 
      #17 0x00005583e4236c1c in binlog_commit (thd=0x62c000240218, all=true, ro_1pc=true) at /data/src/11.2/sql/log.cc:2418
      		 
      #18 0x00005583e3efc181 in commit_one_phase_2 (thd=0x62c000240218, all=true, trans=0x62c000243cc0, is_real_trans=true) at /data/src/11.2/sql/handler.cc:2131
      		 
      #19 0x00005583e3efbdd7 in ha_commit_one_phase (thd=0x62c000240218, all=true) at /data/src/11.2/sql/handler.cc:2093
      		 
      #20 0x00005583e3efa048 in ha_commit_trans (thd=0x62c000240218, all=true) at /data/src/11.2/sql/handler.cc:1887
      		 
      #21 0x00005583e3ac52a3 in trans_commit (thd=0x62c000240218) at /data/src/11.2/sql/transaction.cc:266
      		 
      #22 0x00005583e35d1925 in mysql_execute_command (thd=0x62c000240218, is_called_from_prepared_stmt=false) at /data/src/11.2/sql/sql_parse.cc:5403
      		 
      #23 0x00005583e35e10d7 in mysql_parse (thd=0x62c000240218, rawbuf=0x6290002e9238 "COMMIT", length=6, parser_state=0x7f18a324b9f0) at /data/src/11.2/sql/sql_parse.cc:7811
      		 
      #24 0x00005583e35b9491 in dispatch_command (command=COM_QUERY, thd=0x62c000240218, packet=0x6290002df219 "COMMIT", packet_length=6, blocking=true) at /data/src/11.2/sql/sql_parse.cc:1893
      		 
      #25 0x00005583e35b61ce in do_command (thd=0x62c000240218, blocking=true) at /data/src/11.2/sql/sql_parse.cc:1406
      		 
      #26 0x00005583e3a81fac in do_handle_one_connection (connect=0x608000003cb8, put_in_cache=true) at /data/src/11.2/sql/sql_connect.cc:1445
      		 
      #27 0x00005583e3a8196d in handle_one_connection (arg=0x608000003cb8) at /data/src/11.2/sql/sql_connect.cc:1347
      		 
      #28 0x00005583e46aa652 in pfs_spawn_thread (arg=0x617000008c98) at /data/src/11.2/storage/perfschema/pfs.cc:2201
      		 
      #29 0x00007f18bb4a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
      		 
      #30 0x00007f18bb5285bc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

      Attachments

        Issue Links

          is caused by

          Task - A task that needs to be done. MDEV-16329 Engine-independent online ALTER TABLE

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

          Activity

            Ascending order - Click to sort in descending order
            nikitamalyavin Nikita Malyavin added a comment -

            The smaller test, leading to the same problem, however a different assertion, has been found:

            --source include/have_binlog_format_mixed.inc
            		 
            --source include/have_innodb.inc
            		 
            --source include/have_debug_sync.inc
            		 
             
            		 
            CREATE TEMPORARY TABLE tmp (id INT, PRIMARY KEY(id)) ENGINE=InnoDB;
            		 
            CREATE TABLE t1 (a INT, b TEXT) ENGINE=InnoDB;
            		 
            CREATE TABLE t2 (a INT, b INT, c CHAR(8), d TEXT, UNIQUE(a)) ENGINE=InnoDB;
            		 
            INSERT INTO t2 VALUES (1,1,'f','e'),(1000,1000,'c','b');
            		 
            --connection default
            		 
            SET debug_sync= 'alter_table_online_before_lock SIGNAL go_trx WAIT_FOR go_alter';
            		 
            send ALTER TABLE t2 FORCE, ALGORITHM=COPY, LOCK=NONE;
            		 
             
            		 
            --connect (con1,localhost,root,,test)
            		 
             
            		 
            SET debug_sync= 'now WAIT_FOR go_trx';
            		 
            START TRANSACTION;
            		 
            INSERT INTO t1 VALUES (3,'a');
            		 
            --error ER_DUP_ENTRY
            		 
            INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x');
            		 
            INSERT INTO t2 VALUES (3,3,'a','x');
            		 
            COMMIT;
            		 
            set debug_sync= 'now SIGNAL go_alter';

            nikitamalyavin Nikita Malyavin added a comment - The smaller test, leading to the same problem, however a different assertion, has been found: --source include/have_binlog_format_mixed.inc --source include/have_innodb.inc --source include/have_debug_sync.inc   CREATE TEMPORARY TABLE tmp (id INT , PRIMARY KEY (id)) ENGINE=InnoDB; CREATE TABLE t1 (a INT , b TEXT) ENGINE=InnoDB; CREATE TABLE t2 (a INT , b INT , c CHAR (8), d TEXT, UNIQUE (a)) ENGINE=InnoDB; INSERT INTO t2 VALUES (1,1, 'f' , 'e' ),(1000,1000, 'c' , 'b' ); --connection default SET debug_sync= 'alter_table_online_before_lock SIGNAL go_trx WAIT_FOR go_alter' ; send ALTER TABLE t2 FORCE , ALGORITHM=COPY, LOCK=NONE;   --connect (con1,localhost,root,,test)   SET debug_sync= 'now WAIT_FOR go_trx' ; START TRANSACTION ; INSERT INTO t1 VALUES (3, 'a' ); --error ER_DUP_ENTRY INSERT INTO t2 VALUES (3,3, 'a' , 'x' ), (3,3, 'a' , 'x' ); INSERT INTO t2 VALUES (3,3, 'a' , 'x' ); COMMIT ; set debug_sync= 'now SIGNAL go_alter' ;
            nikitamalyavin Nikita Malyavin added a comment -

            Please review branch bb-11.2-nikita, commit b96b093d

            nikitamalyavin Nikita Malyavin added a comment - Please review branch bb-11.2-nikita , commit b96b093d
            nikitamalyavin Nikita Malyavin added a comment -

            There is a lot of interference with binlog_hton enabled by online alter, which I couldn't fight by adhoc state deductions. So I decided to carry online alter out, into a separate handlerton.

            This gave me a possibility to store connection-local online alter data as ha_data.
            Also I reworked the savepoints handling as handlerton functions.
            Please review the following commits:

            217a7a7c online alter: rework savepoints
            		 
            ad6a305d online alter: use thd->ha_data to store cache_list
            		 
            132c56f1 online alter: extract the source to a separate file
            		 
            a71b1343 MDEV-32126 Assertion fails upon online ALTER and binary log enabled

            Also please consider my 132c56f1 commit among then, which creates online_alter.cc and moves all the producer side code there. It's optional, but really helps reading and editing.

            nikitamalyavin Nikita Malyavin added a comment - There is a lot of interference with binlog_hton enabled by online alter, which I couldn't fight by adhoc state deductions. So I decided to carry online alter out, into a separate handlerton. This gave me a possibility to store connection-local online alter data as ha_data. Also I reworked the savepoints handling as handlerton functions. Please review the following commits: 217a7a7c online alter: rework savepoints ad6a305d online alter: use thd->ha_data to store cache_list 132c56f1 online alter: extract the source to a separate file a71b1343 MDEV-32126 Assertion fails upon online ALTER and binary log enabled Also please consider my 132c56f1 commit among then, which creates online_alter.cc and moves all the producer side code there. It's optional, but really helps reading and editing.
            serg Sergei Golubchik added a comment -

            The overall problem is a deep interference with the effect of an installed
            binlog_hton.

            this doesn't really explain anything. Please explain why the assert actually fires.

            You can explain here to avoid recommitting everything just to change a comment. Later, when everything is "ok to push" you can fix the comment in commit too together with other changes, if any

            serg Sergei Golubchik added a comment - The overall problem is a deep interference with the effect of an installed binlog_hton. this doesn't really explain anything. Please explain why the assert actually fires. You can explain here to avoid recommitting everything just to change a comment. Later, when everything is "ok to push" you can fix the comment in commit too together with other changes, if any
            nikitamalyavin Nikita Malyavin added a comment -

            The high-level reason is that the assumption about that thd->binlog_get_cache_mngr() is, sufficiently, NULL, when we shouldn't run the binlog part of binlog_commit/binlog_rollback, is wrong, i.e. this condition:

              binlog_cache_mngr *const cache_mngr= thd->binlog_get_cache_mngr();
            		 
             
            		 
              if (!cache_mngr)
            		 
              {
            		 
            ...
            		 
                DBUG_RETURN(0);
            		 
              }

            is not enough.

            I don't know whether cache_mgr is used for statement logging or not. Here we have a mixed logging, and that is, some operations may have no row-base logging. However, cache_mngr exists, which makes me think, that a statement logging is done differently, and cache_mngr only serves row-based logging, since trx_cache is also empty at the moment of check.

            What's definite is that binlog_hton wouldn't have been set for SBR. It gets enabled during binlog_log_row_to_binlog, in THD::binlog_start_trans_and_stmt.

            In particular, trx_cache.restore_prev_position() is called during binlog_rollback, when it actually shouldn't have to – bacause it's SBR and binlog_hton is not set:

            0x000055f154ef0ac8 in reinit_io_cache (info=0x61b000060638, type=WRITE_CACHE, seek_offset=18446744073709551615, use_async_io=0 '\000', clear_cache=0 '\000') at /home/nik/mariadb/mysys/mf_iocache.c:483
            		 
            483	    info->pos_in_file=seek_offset;
            		 
            (gdb) bt
            		 
            #0  0x000055f154ef0ac8 in reinit_io_cache (info=0x61b000060638, type=WRITE_CACHE, seek_offset=18446744073709551615, use_async_io=0 '\000', clear_cache=0 '\000') at /home/nik/mariadb/mysys/mf_iocache.c:483
            		 
            #1  0x000055f152b2b072 in binlog_cache_data::truncate (this=0x61b000060638, pos=18446744073709551615, reset_cache=false) at /home/nik/mariadb/sql/log.cc:492
            		 
            #2  0x000055f152b2341a in binlog_cache_data::restore_prev_position (this=0x61b000060638) at /home/nik/mariadb/sql/log.cc:364
            		 
            #3  0x000055f152b1c2d3 in binlog_truncate_trx_cache (thd=0x62b0001c0218, cache_mngr=0x61b000060498, all=false) at /home/nik/mariadb/sql/log.cc:2109
            		 
            #4  0x000055f152ac7c80 in binlog_rollback (hton=0x615000002118, thd=0x62b0001c0218, all=false) at /home/nik/mariadb/sql/log.cc:2535
            		 
            #5  0x000055f152617f6e in ha_rollback_trans (thd=0x62b0001c0218, all=false) at /home/nik/mariadb/sql/handler.cc:2264
            		 
            #6  0x000055f1537c4d75 in trans_rollback_stmt (thd=0x62b0001c0218) at /home/nik/mariadb/sql/transaction.cc:535
            		 
            #7  0x000055f15313e5ab in mysql_execute_command (thd=0x62b0001c0218, is_called_from_prepared_stmt=false) at /home/nik/mariadb/sql/sql_parse.cc:5854
            		 
            #8  0x000055f15311ccfb in mysql_parse (thd=0x62b0001c0218, rawbuf=0x629000316238 "INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x')", length=50, parser_state=0x7f2f140497f0) at /home/nik/mariadb/sql/sql_parse.cc:7811
            		 
            #9  0x000055f15311674e in dispatch_command (command=COM_QUERY, thd=0x62b0001c0218, packet=0x62900030c219 "INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x')", packet_length=50, blocking=true) at /home/nik/mariadb/sql/sql_parse.cc:1893
            		 
            #10 0x000055f15311eb2a in do_command (thd=0x62b0001c0218, blocking=true) at /home/nik/mariadb/sql/sql_parse.cc:1406

            I tried a few approaches to fix that problem. I tried to only exit when trx_cache->before_stmt_pos is MY_OFF_T_UNDEF, but then DBUG_ASSERT(WSREP(thd) || rollback_online) breaks, meaning, that sometimes it's fine to have undefined trx_cache. But in that case, binlog_commit/binlog_rollback is supposed to work somehow – since the handlerton was installed for some reason.

            I tried to go deeper and take MY_OFF_T_UNDEF more carefully into account – actually, I tried to modify binlog_cache_data::empty() and write a more careful exit condition. That failed tests in random places, like it had an assertion failure in MYSQL_BIN_LOG::trx_group_commit_leader.

            So overall this demonstrates that binlog state consistency is quite fragile, and I don't want to play around with it. I had a success in extracting everything in a separate hton with no much price, but some benefits, like online_alter_cache_list is moved out of thd, and I call it debloating (yes, first I bloated it ). And what's more important is more independency from binlog, which will definitely come quite handy.

            nikitamalyavin Nikita Malyavin added a comment - The high-level reason is that the assumption about that thd->binlog_get_cache_mngr() is, sufficiently, NULL, when we shouldn't run the binlog part of binlog_commit/binlog_rollback , is wrong, i.e. this condition: binlog_cache_mngr * const cache_mngr= thd->binlog_get_cache_mngr();   if (!cache_mngr) { ... DBUG_RETURN(0); } is not enough. I don't know whether cache_mgr is used for statement logging or not. Here we have a mixed logging, and that is, some operations may have no row-base logging. However, cache_mngr exists, which makes me think, that a statement logging is done differently, and cache_mngr only serves row-based logging, since trx_cache is also empty at the moment of check. What's definite is that binlog_hton wouldn't have been set for SBR. It gets enabled during binlog_log_row_to_binlog , in THD::binlog_start_trans_and_stmt . In particular, trx_cache.restore_prev_position() is called during binlog_rollback , when it actually shouldn't have to – bacause it's SBR and binlog_hton is not set: 0x000055f154ef0ac8 in reinit_io_cache (info=0x61b000060638, type=WRITE_CACHE, seek_offset=18446744073709551615, use_async_io=0 '\000', clear_cache=0 '\000') at /home/nik/mariadb/mysys/mf_iocache.c:483 483 info->pos_in_file=seek_offset; (gdb) bt #0 0x000055f154ef0ac8 in reinit_io_cache (info=0x61b000060638, type=WRITE_CACHE, seek_offset=18446744073709551615, use_async_io=0 '\000', clear_cache=0 '\000') at /home/nik/mariadb/mysys/mf_iocache.c:483 #1 0x000055f152b2b072 in binlog_cache_data::truncate (this=0x61b000060638, pos=18446744073709551615, reset_cache=false) at /home/nik/mariadb/sql/log.cc:492 #2 0x000055f152b2341a in binlog_cache_data::restore_prev_position (this=0x61b000060638) at /home/nik/mariadb/sql/log.cc:364 #3 0x000055f152b1c2d3 in binlog_truncate_trx_cache (thd=0x62b0001c0218, cache_mngr=0x61b000060498, all=false) at /home/nik/mariadb/sql/log.cc:2109 #4 0x000055f152ac7c80 in binlog_rollback (hton=0x615000002118, thd=0x62b0001c0218, all=false) at /home/nik/mariadb/sql/log.cc:2535 #5 0x000055f152617f6e in ha_rollback_trans (thd=0x62b0001c0218, all=false) at /home/nik/mariadb/sql/handler.cc:2264 #6 0x000055f1537c4d75 in trans_rollback_stmt (thd=0x62b0001c0218) at /home/nik/mariadb/sql/transaction.cc:535 #7 0x000055f15313e5ab in mysql_execute_command (thd=0x62b0001c0218, is_called_from_prepared_stmt=false) at /home/nik/mariadb/sql/sql_parse.cc:5854 #8 0x000055f15311ccfb in mysql_parse (thd=0x62b0001c0218, rawbuf=0x629000316238 "INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x')", length=50, parser_state=0x7f2f140497f0) at /home/nik/mariadb/sql/sql_parse.cc:7811 #9 0x000055f15311674e in dispatch_command (command=COM_QUERY, thd=0x62b0001c0218, packet=0x62900030c219 "INSERT INTO t2 VALUES (3,3,'a','x'), (3,3,'a','x')", packet_length=50, blocking=true) at /home/nik/mariadb/sql/sql_parse.cc:1893 #10 0x000055f15311eb2a in do_command (thd=0x62b0001c0218, blocking=true) at /home/nik/mariadb/sql/sql_parse.cc:1406 I tried a few approaches to fix that problem. I tried to only exit when trx_cache->before_stmt_pos is MY_OFF_T_UNDEF , but then DBUG_ASSERT(WSREP(thd) || rollback_online) breaks, meaning, that sometimes it's fine to have undefined trx_cache. But in that case, binlog_commit/binlog_rollback is supposed to work somehow – since the handlerton was installed for some reason. I tried to go deeper and take MY_OFF_T_UNDEF more carefully into account – actually, I tried to modify binlog_cache_data::empty() and write a more careful exit condition. That failed tests in random places, like it had an assertion failure in MYSQL_BIN_LOG::trx_group_commit_leader . So overall this demonstrates that binlog state consistency is quite fragile, and I don't want to play around with it. I had a success in extracting everything in a separate hton with no much price, but some benefits, like online_alter_cache_list is moved out of thd, and I call it debloating (yes, first I bloated it ). And what's more important is more independency from binlog, which will definitely come quite handy.
            nikitamalyavin Nikita Malyavin added a comment -

            Minor issues are resolved, head is now 8d21bf9f5. Waiting for the final verdict.

            nikitamalyavin Nikita Malyavin added a comment - Minor issues are resolved, head is now 8d21bf9f5 . Waiting for the final verdict.
            serg Sergei Golubchik added a comment - - edited

            8d21bf9f5 2e38c6cb8d8c (new commit with GPL headers) is ok to push, thanks!

            serg Sergei Golubchik added a comment - - edited 8d21bf9f5 2e38c6cb8d8c (new commit with GPL headers) is ok to push, thanks!

            People

              nikitamalyavin Nikita Malyavin
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              5 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.