Elena Stepanova added a comment - 2018-05-15 22:06 New occurrence: https://api.travis-ci.org/v3/job/378823604/log.txt

Matthias Leich added a comment - 2018-07-19 19:58 - edited I have some RQG grammar which replays the problem quite fast. But I do not know if the '+d,ib_rename_indexes_too_many_concurrent_trxs' has sideeffects which leaves the server in some bad state and than is some assert maybe to expected. query: ALTER TABLE t1 ADD COLUMN col2_copy INT ; ALTER TABLE t1 DROP COLUMN col2 ; ALTER TABLE t1 CHANGE COLUMN col2_copy col2 INT ; SET SESSION DEBUG_DBUG = '' | SET SESSION DEBUG_DBUG = '+d,ib_rename_indexes_too_many_concurrent_trxs' ; DELETE FROM t1 ; INSERT INTO t1 VALUES (1,1); SET SESSION DEBUG_DBUG = '';   query_init: CREATE TABLE IF NOT EXISTS t1 (col1 INT, col2 INT) ENGINE = InnoDB; MariaDB 10.3 compiled with debug commit 141a5b24843c626f545a0c2f49013b54da194c0d ~ Sat Jul 14 The binary claims to be a 10.3.9. My backtrace: mysqld: 10.3/storage/innobase/include/dict0mem.h:1094: const byte* dict_index_t::instant_field_value(ulint, ulint*) const: Assertion `is_instant() || id == DICT_INDEXES_ID' failed. [ERROR] mysqld got signal 6 ; ... Query (0x7fccc0012d70): ALTER TABLE t1 DROP COLUMN col2 /* E_R Thread6 QNO 2375 CON_ID 19 */ Connection ID (thread ID): 19 Status: NOT_KILLED   #3 <signal handler called> #4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51 #5 0x00007fcd70a97f5d in __GI_abort () at abort.c:90 #6 0x00007fcd70a8df17 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x557d00ca6368 "is_instant() || id == DICT_INDEXES_ID", file=file@entry=0x557d00ca6288 "storage/innobase/include/dict0mem.h", line=line@entry=1094, function=function@entry=0x557d00cac820 <dict_index_t::instant_field_value(unsigned long, unsigned long*) const::__PRETTY_FUNCTION__> "const byte* dict_index_t::instant_field_value(ulint, ulint*) const") at assert.c:92 #7 0x00007fcd70a8dfc2 in __GI___assert_fail (assertion=0x557d00ca6368 "is_instant() || id == DICT_INDEXES_ID", file=0x557d00ca6288 "storage/innobase/include/dict0mem.h", line=1094, function=0x557d00cac820 <dict_index_t::instant_field_value(unsigned long, unsigned long*) const::__PRETTY_FUNCTION__> "const byte* dict_index_t::instant_field_value(ulint, ulint*) const") at assert.c:101 #8 0x0000557d0049776d in dict_index_t::instant_field_value (this=0x7fccd4029848, n=4, len=0x7fcd50c3b338) at storage/innobase/include/dict0mem.h:1094 #9 0x0000557d0055db28 in rec_init_offsets_comp_ordinary (rec=0x7fcd50a63004 "", index=0x7fccd4029848, offsets=0x7fccc009a130, n_core=4, format=REC_LEAF_ORDINARY) at storage/innobase/rem/rem0rec.cc:384 #10 0x0000557d0056203d in rec_init_offsets_temp (rec=0x7fcd50a63004 "", index=0x7fccd4029848, offsets=0x7fccc009a130, n_core=4, status=REC_STATUS_ORDINARY) at storage/innobase/rem/rem0rec.cc:1713 #11 0x0000557d005c2617 in row_log_table_apply_op (thr=0x7fccc00a5358, new_trx_id_col=1, dup=0x7fcd50c3b780, error=0x7fcd50c3b4fc, offsets_heap=0x7fccc00d56a0, heap=0x7fccc00d1610, mrec=0x7fcd50a63004 "", mrec_end=0x7fcd50a6301f "", offsets=0x7fccc009a130) at storage/innobase/row/row0log.cc:2418 #12 0x0000557d005c4970 in row_log_table_apply_ops (thr=0x7fccc00a5358, dup=0x7fcd50c3b780, stage=0x7fccc0094d40) at storage/innobase/row/row0log.cc:2988 #13 0x0000557d005c4f72 in row_log_table_apply (thr=0x7fccc00a5358, old_table=0x7fcccc0234c8, table=0x7fccc00ab8f8, stage=0x7fccc0094d40, new_table=0x7fccc00234f8) at storage/innobase/row/row0log.cc:3097 #14 0x0000557d0049a70d in commit_try_rebuild (ha_alter_info=0x7fcd50c3cc70, ctx=0x7fccc0014100, altered_table=0x7fccc00ab8f8, old_table=0x7fccc00a7b38, trx=0x7fcd5b3ff3b8, table_name=0x7fccdc244d5d "t1") at storage/innobase/handler/handler0alter.cc:8692 #15 0x0000557d00494b94 in ha_innobase::commit_inplace_alter_table (this=0x7fccc00a6fb0, altered_table=0x7fccc00ab8f8, ha_alter_info=0x7fcd50c3cc70, commit=true) at storage/innobase/handler/handler0alter.cc:9555 #16 0x0000557d00245579 in handler::ha_commit_inplace_alter_table (this=0x7fccc00a6fb0, altered_table=0x7fccc00ab8f8, ha_alter_info=0x7fcd50c3cc70, commit=true) at sql/handler.cc:4416 #17 0x0000557d00027c69 in mysql_inplace_alter_table (thd=0x7fccc0000ce8, table_list=0x7fccc0012ea8, table=0x7fccc00a7b38, altered_table=0x7fccc00ab8f8, ha_alter_info=0x7fcd50c3cc70, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7fcd50c3cce0, alter_ctx=0x7fcd50c3d8e0) at sql/sql_table.cc:7616 #18 0x0000557d0002daa7 in mysql_alter_table (thd=0x7fccc0000ce8, new_db=0x7fccc0005398, new_name=0x7fccc0005750, create_info=0x7fcd50c3e4d0, table_list=0x7fccc0012ea8, alter_info=0x7fcd50c3e410, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9710 #19 0x0000557d000b4212 in Sql_cmd_alter_table::execute (this=0x7fccc0013520, thd=0x7fccc0000ce8) at sql/sql_alter.cc:489 #20 0x0000557cfff58972 in mysql_execute_command (thd=0x7fccc0000ce8) at sql/sql_parse.cc:6280 #21 0x0000557cfff5dbf3 in mysql_parse (thd=0x7fccc0000ce8, rawbuf=0x7fccc0012d70 "ALTER TABLE t1 DROP COLUMN col2 /* E_R Thread6 QNO 2375 CON_ID 19 */", length=69, parser_state=0x7fcd50c3f630, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8073 #22 0x0000557cfff4acab in dispatch_command (command=COM_QUERY, thd=0x7fccc0000ce8, packet=0x7fccc000aa39 " ALTER TABLE t1 DROP COLUMN col2 /* E_R Thread6 QNO 2375 CON_ID 19 */ ", packet_length=71, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1846 #23 0x0000557cfff4970c in do_command (thd=0x7fccc0000ce8) at sql/sql_parse.cc:1391

Matthias Leich added a comment - 2018-07-19 20:29 No replay on a 10.2 compiled with debug within 8 attempts. I have uploaded the files required for the replay. You will need my experimental RQG. git clone https://github.com/mleich1/rqg RQG_mleich1 cd RQG_mleich1 git checkout experimental In case that does not work please show up.

Marko Mäkelä added a comment - 2018-07-26 06:57 There is no debug injection point ib_rename_indexes_too_many_concurrent_trxs in MariaDB, so the SET DEBUG_DBUG  should have no effect. The problem appears to be that a table-rebuilding ALTER (as needed for the DROP COLUMN before MDEV-15562 ) fails to properly parse the table. Likely, a purge following the DELETE FROM t1 will occasionally empty the table (removing its ‘instantness’), and row_log_table_apply() is not prepared for the table format change. I can repeat this with a slightly simpler test: --source include/have_innodb.inc CREATE TABLE t1 (col1 INT PRIMARY KEY ) ENGINE=InnoDB; sleep 3600; DROP TABLE t1; Then, after starting the test, start two clients: yes 'ALTER TABLE t1 ADD COLUMN col2 INT; ALTER TABLE t1 DROP COLUMN col2;'| $BUILDDIR/client/mysql --defaults-file=$BUILDDIR/mysql-test/var/my.cnf -uroot test & yes 'REPLACE INTO t1 SET col1=1; DELETE FROM t1;'| $BUILDDIR/client/mysql --defaults-file=$BUILDDIR/mysql-test/var/my.cnf -uroot test & This will result in the assertion failure during the execution of DROP COLUMN .

Marko Mäkelä added a comment - 2018-07-26 07:27 I think that the following is happening: ALTER TABLE t1 DROP COLUMN col2; was started. REPLACE INTO t1 SET col1=1; was executed while the table was in the "instantly added column" format, and it wrote a ROW_T_INSERT record that did not contain an explicit value for col2 . DELETE FROM t1; and a subsequent purge were executed. This emptied the table and converted it to the canonical "non-instant" format. Applying the ROW_T_INSERT record fails in ALTER TABLE when trying to retrieve the value for col2 , because the table no longer is in "instantly added column" format. We could try 2 fixes: If a table rebuild is in progress, never convert the table to non-instant format when it becomes empty. In the log that is handled by row_log_table_apply() , explicitly store values for all columns, no matter if they were instantly added. I believe that the first fix is easier and less risky. Converting the table to the canonical format is merely an optimization for performance and file format compatibility. If the table-rebuilding ALTER succeeds, the table would be in the canonical format again. If the ALTER fails, then the table would remain in the less efficient "instant" format.

Marko Mäkelä added a comment - 2018-07-26 07:58 Deterministic test case: --source include/have_innodb.inc --source include/have_debug.inc --source include/have_debug_sync.inc   SET @saved_frequency = @@ GLOBAL .innodb_purge_rseg_truncate_frequency; SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;   CREATE TABLE t1 (a INT PRIMARY KEY ) ENGINE=InnoDB; INSERT INTO t1 SET a=0; ALTER TABLE t1 ADD COLUMN b INT ;   connect (con1,localhost,root); START TRANSACTION WITH CONSISTENT SNAPSHOT;   connection default ; DELETE FROM t1;   connection con1; SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL go WAIT_FOR insert' ; send ALTER TABLE t1 FORCE ;   connection default ; SET DEBUG_SYNC = 'now WAIT_FOR go' ; let $wait_all_purged = 1; --source include/wait_all_purged.inc INSERT INTO t1 SET a=1; SET DEBUG_SYNC = 'now SIGNAL insert' ;   connection con1; reap; disconnect con1;   connection default ; SET DEBUG_SYNC = RESET; SELECT * FROM t1; DROP TABLE t1; SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;

Marko Mäkelä added a comment - 2018-07-26 09:57 The test case needs 2 auxiliary connections to be deterministic. We must keep the read view open until after the ALTER TABLE has been sent. Also, adding a default value of NULL is a special case. When adding a column with a NOT NULL DEFAULT value, then we would have a similar problem in row_log_table_apply_convert_mrec() . It turns out to be simplest to introduce row_log_t::non_core_fields[] for storing the default values, and rely on those during row_log_table_apply() . In that way, we are free to invoke dict_index_t::remove_instant() on the source table at any time. I implemented this fix, but it needs some adjustment, because my test is randomly crashing due to row_log_table_apply_op() not consuming all data for instantly added columns.

Marko Mäkelä added a comment - 2018-07-26 20:14 My fix ensures that the online_log is written and parsed in a consistent way. It was easier to change how online table rebuild works than to try avoid calls to dict_index_t::remove_instant() .