[MDEV-21658] Error on online ADD PRIMARY KEY after instant DROP/reorder Created: 2020-02-04  Updated: 2020-02-05  Resolved: 2020-02-05

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Data Manipulation - Update, Prepared Statements, Storage Engine - InnoDB
Affects Version/s: 10.4
Fix Version/s: 10.5.1, 10.4.13

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-21660 Unexpected ER_INVALID_USE_OF_NULL upo... Closed
Problem/Incident
is caused by MDEV-15562 Instant DROP COLUMN or changing the o... Closed

 Description   

Notes:

  • There is a lot of "back and forth" in the test case with creating/dropping/renaming columns, but I can't get rid of the remaining part without having the outcome changed.
  • If I add ALGORITHM=COPY to any of the ALTER statements in the test case, the crash stops happening. Explicit ALGORITHM=INSTANT or ALGORITHM=INPLACE don't seem to change the outcome.
  • The test case is concurrent and hence should be non-deterministic. It fails every time for me, but if it doesn't for you, try to run with --repeat.

--source include/have_innodb.inc
 
 
 
--connect (con1,localhost,root,,test)
 
--connection default
 
CREATE  TABLE t1 (f GEOMETRY DEFAULT POINT(0,0), a INT, b INT, c INT, col INT) ENGINE=InnoDB;
 
ALTER TABLE t1 DROP COLUMN a;
 
ALTER TABLE t1 DROP COLUMN c;
 
ALTER TABLE t1 DROP COLUMN b;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP COLUMN b;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP COLUMN b  ;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
INSERT INTO t1 () VALUES ();
 
 
 
SET SQL_MODE= '';
 
--send
 
    ALTER TABLE t1 ADD PRIMARY KEY(b);
 
 
 
--connection con1
 
PREPARE stmt FROM 'UPDATE t1 SET b = 1';
 
EXECUTE stmt;
 
 
 
# Cleanup
 
DEALLOCATE PREPARE stmt;
 
--disconnect con1
 
 
 
--connection default
 
--reap
 
DROP TABLE t1;

10.4 574354a6

 
mysqld: /data/src/10.4/storage/innobase/row/row0log.cc:2121: dberr_t row_log_table_apply_update(que_thr_t*, ulint, const mrec_t*, const offset_t*, mem_heap_t*, mem_heap_t*, row_merge_dup_t*, const dtuple_t*): Assertion `log->blobs' failed.
 
200204 14:18:35 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f0d897a5f12 in __GI___assert_fail (assertion=0x5562839cee4a "log->blobs", file=0x5562839ce248 "/data/src/10.4/storage/innobase/row/row0log.cc", line=2121, function=0x5562839d1f40 <row_log_table_apply_update(que_thr_t*, unsigned long, unsigned char const*, unsigned short const*, mem_block_info_t*, mem_block_info_t*, row_merge_dup_t*, dtuple_t const*)::__PRETTY_FUNCTION__> "dberr_t row_log_table_apply_update(que_thr_t*, ulint, const mrec_t*, const offset_t*, mem_heap_t*, mem_heap_t*, row_merge_dup_t*, const dtuple_t*)") at assert.c:101
 
#8  0x00005562831a3c54 in row_log_table_apply_update (thr=0x7f0d381ae4a8, new_trx_id_col=1, mrec=0x7f0d7e8fe016 "", offsets=0x7f0d381a24e0, offsets_heap=0x7f0d381d7460, heap=0x7f0d381d33d0, dup=0x7f0d8414bcf0, old_pk=0x7f0d381d3458) at /data/src/10.4/storage/innobase/row/row0log.cc:2121
 
#9  0x00005562831a5dcb in row_log_table_apply_op (thr=0x7f0d381ae4a8, new_trx_id_col=1, dup=0x7f0d8414bcf0, error=0x7f0d8414ba6c, offsets_heap=0x7f0d381d7460, heap=0x7f0d381d33d0, mrec=0x7f0d7e8fe016 "", mrec_end=0x7f0d7e8fe045 "", offsets=0x7f0d381a24e0) at /data/src/10.4/storage/innobase/row/row0log.cc:2664
 
#10 0x00005562831a7fe1 in row_log_table_apply_ops (thr=0x7f0d381ae4a8, dup=0x7f0d8414bcf0, stage=0x7f0d381b1340) at /data/src/10.4/storage/innobase/row/row0log.cc:3037
 
#11 0x00005562831a873d in row_log_table_apply (thr=0x7f0d381ae4a8, old_table=0x7f0d3800be58, table=0x7f0d8414c800, stage=0x7f0d381b1340, new_table=0x7f0d381aed98) at /data/src/10.4/storage/innobase/row/row0log.cc:3143
 
#12 0x000055628302ded0 in ha_innobase::inplace_alter_table (this=0x7f0d38066ed8, altered_table=0x7f0d8414c800, ha_alter_info=0x7f0d8414c770) at /data/src/10.4/storage/innobase/handler/handler0alter.cc:8379
 
#13 0x0000556282b2d9ff in handler::ha_inplace_alter_table (this=0x7f0d38066ed8, altered_table=0x7f0d8414c800, ha_alter_info=0x7f0d8414c770) at /data/src/10.4/sql/handler.h:4361
 
#14 0x0000556282b21a91 in mysql_inplace_alter_table (thd=0x7f0d38000af0, table_list=0x7f0d38013288, table=0x7f0d38066070, altered_table=0x7f0d8414c800, ha_alter_info=0x7f0d8414c770, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f0d8414d5d0, alter_ctx=0x7f0d8414e100) at /data/src/10.4/sql/sql_table.cc:7725
 
#15 0x0000556282b28953 in mysql_alter_table (thd=0x7f0d38000af0, new_db=0x7f0d380052b0, new_name=0x7f0d380056b8, create_info=0x7f0d8414ecf0, table_list=0x7f0d38013288, alter_info=0x7f0d8414ec30, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_table.cc:10119
 
#16 0x0000556282bc0a47 in Sql_cmd_alter_table::execute (this=0x7f0d38013a18, thd=0x7f0d38000af0) at /data/src/10.4/sql/sql_alter.cc:508
 
#17 0x0000556282a3f221 in mysql_execute_command (thd=0x7f0d38000af0) at /data/src/10.4/sql/sql_parse.cc:6102
 
#18 0x0000556282a448e3 in mysql_parse (thd=0x7f0d38000af0, rawbuf=0x7f0d38013198 "ALTER TABLE t1 ADD PRIMARY KEY(b)", length=33, parser_state=0x7f0d84150160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
 
#19 0x0000556282a2fab0 in dispatch_command (command=COM_QUERY, thd=0x7f0d38000af0, packet=0x7f0d381371b1 "ALTER TABLE t1 ADD PRIMARY KEY(b)", packet_length=33, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
 
#20 0x0000556282a2e13d in do_command (thd=0x7f0d38000af0) at /data/src/10.4/sql/sql_parse.cc:1360
 
#21 0x0000556282bb7357 in do_handle_one_connection (connect=0x556285d28b80) at /data/src/10.4/sql/sql_connect.cc:1412
 
#22 0x0000556282bb70a6 in handle_one_connection (arg=0x556285d28b80) at /data/src/10.4/sql/sql_connect.cc:1316
 
#23 0x00005562835bfb45 in pfs_spawn_thread (arg=0x556285c47b30) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#24 0x00007f0d8b72e4a4 in start_thread (arg=0x7f0d84151700) at pthread_create.c:456
 
#25 0x00007f0d89862d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible on 10.4 and 10.5.
Not reproducible on 10.3 with the provided test case (although I do have a record of a similar failure on a 10.3 build).
Only reproducible with UPDATE executed as a prepared statement.

Non-debug build doesn't crash, but it produces an error which I wouldn't expect:

mysqltest: At line 31: query 'reap' failed: 1062: Duplicate entry '0' for key 'PRIMARY'

The table only has one row, so duplicate key error doesn't make sense to me.

 Comments   
Comment by Elena Stepanova [ 2020-02-04 ]

The test case below is almost identical to the one in the description, with the only difference being the datatype of the first column. It causes a different assertion failure.

--source include/have_innodb.inc
 
 
 
--connect (con1,localhost,root,,test)
 
--connection default
 
CREATE  TABLE t1 (f INT, a INT, b INT, c INT, col INT) ENGINE=InnoDB;
 
ALTER TABLE t1 DROP COLUMN a;
 
ALTER TABLE t1 DROP COLUMN c;
 
ALTER TABLE t1 DROP COLUMN b;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP COLUMN b;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP COLUMN b  ;
 
ALTER TABLE t1 CHANGE COLUMN col b INT;
 
INSERT INTO t1 () VALUES ();
 
 
 
SET SQL_MODE= '';
 
--send
 
    ALTER TABLE t1 ADD PRIMARY KEY(b);
 
 
 
--connection con1
 
PREPARE stmt FROM 'UPDATE t1 SET b = 1';
 
EXECUTE stmt;
 
 
 
# Cleanup
 
DEALLOCATE PREPARE stmt;
 
--disconnect con1
 
 
 
--connection default
 
--reap
 
DROP TABLE t1;

10.4 574354a6

 
mysqld: /data/src/10.4/storage/innobase/row/row0log.cc:2638: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, offset_t*): Assertion `extra_size || !is_instant' failed.
 
 
 
#7  0x00007f6f39b0af12 in __GI___assert_fail (assertion=0x5562cc07a1c3 "extra_size || !is_instant", file=0x5562cc079248 "/data/src/10.4/storage/innobase/row/row0log.cc", line=2638, function=0x5562cc07d060 <row_log_table_apply_op(que_thr_t*, unsigned long, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, unsigned char const*, unsigned char const*, unsigned short*)::__PRETTY_FUNCTION__> "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, offset_t*)") at assert.c:101
 
#8  0x00005562cb850c18 in row_log_table_apply_op (thr=0x7f6ee41b5fd8, new_trx_id_col=1, dup=0x7f6f340afcf0, error=0x7f6f340afa6c, offsets_heap=0x7f6ee41defc0, heap=0x7f6ee41daf30, mrec=0x7f6f2ecff015 "", mrec_end=0x7f6f2ecff02f "", offsets=0x7f6ee4068170) at /data/src/10.4/storage/innobase/row/row0log.cc:2638
 
#9  0x00005562cb852fe1 in row_log_table_apply_ops (thr=0x7f6ee41b5fd8, dup=0x7f6f340afcf0, stage=0x7f6ee41b8e00) at /data/src/10.4/storage/innobase/row/row0log.cc:3037
 
#10 0x00005562cb85373d in row_log_table_apply (thr=0x7f6ee41b5fd8, old_table=0x7f6ee400b598, table=0x7f6f340b0800, stage=0x7f6ee41b8e00, new_table=0x7f6ee41b6958) at /data/src/10.4/storage/innobase/row/row0log.cc:3143
 
#11 0x00005562cb6d8ed0 in ha_innobase::inplace_alter_table (this=0x7f6ee4064c28, altered_table=0x7f6f340b0800, ha_alter_info=0x7f6f340b0770) at /data/src/10.4/storage/innobase/handler/handler0alter.cc:8379
 
#12 0x00005562cb1d89ff in handler::ha_inplace_alter_table (this=0x7f6ee4064c28, altered_table=0x7f6f340b0800, ha_alter_info=0x7f6f340b0770) at /data/src/10.4/sql/handler.h:4361
 
#13 0x00005562cb1cca91 in mysql_inplace_alter_table (thd=0x7f6ee4000af0, table_list=0x7f6ee4013290, table=0x7f6ee4063dc0, altered_table=0x7f6f340b0800, ha_alter_info=0x7f6f340b0770, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f6f340b15d0, alter_ctx=0x7f6f340b2100) at /data/src/10.4/sql/sql_table.cc:7725
 
#14 0x00005562cb1d3953 in mysql_alter_table (thd=0x7f6ee4000af0, new_db=0x7f6ee40052b0, new_name=0x7f6ee40056b8, create_info=0x7f6f340b2cf0, table_list=0x7f6ee4013290, alter_info=0x7f6f340b2c30, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_table.cc:10119
 
#15 0x00005562cb26ba47 in Sql_cmd_alter_table::execute (this=0x7f6ee4013a20, thd=0x7f6ee4000af0) at /data/src/10.4/sql/sql_alter.cc:508
 
#16 0x00005562cb0ea221 in mysql_execute_command (thd=0x7f6ee4000af0) at /data/src/10.4/sql/sql_parse.cc:6102
 
#17 0x00005562cb0ef8e3 in mysql_parse (thd=0x7f6ee4000af0, rawbuf=0x7f6ee4013198 "ALTER TABLE t1 ADD PRIMARY KEY ( col2 )", length=39, parser_state=0x7f6f340b4160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7901
 
#18 0x00005562cb0daab0 in dispatch_command (command=COM_QUERY, thd=0x7f6ee4000af0, packet=0x7f6ee41371b1 "ALTER TABLE t1 ADD PRIMARY KEY ( col2 ) ", packet_length=40, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
 
#19 0x00005562cb0d913d in do_command (thd=0x7f6ee4000af0) at /data/src/10.4/sql/sql_parse.cc:1360
 
#20 0x00005562cb262357 in do_handle_one_connection (connect=0x5562ce2f9850) at /data/src/10.4/sql/sql_connect.cc:1412
 
#21 0x00005562cb2620a6 in handle_one_connection (arg=0x5562ce2f9850) at /data/src/10.4/sql/sql_connect.cc:1316
 
#22 0x00005562cbc6ab45 in pfs_spawn_thread (arg=0x5562ce218800) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#23 0x00007f6f3ba934a4 in start_thread (arg=0x7f6f340b5700) at pthread_create.c:456
 
#24 0x00007f6f39bc7d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Comment by Marko Mäkelä [ 2020-02-04 ]

Here is a slightly cleaner version of the test:

--source include/have_innodb.inc
 
 
 
--connect (con1,localhost,root,,test)
 
--connection default
 
CREATE  TABLE t1 (f GEOMETRY DEFAULT POINT(0,0), a INT, b INT, c INT, col INT) ENGINE=InnoDB;
 
INSERT INTO t1 () VALUES ();
 
ALTER TABLE t1 DROP a, DROP b, DROP c, DROP col;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP COLUMN col, ADD COLUMN b INT;
 
 
 
SET SQL_MODE= '';
 
send ALTER TABLE t1 ADD PRIMARY KEY(b);
 
 
 
--connection con1
 
PREPARE stmt FROM 'UPDATE t1 SET b = 1';
 
EXECUTE stmt;
 
 
 
DEALLOCATE PREPARE stmt;
 
--disconnect con1
 
--connection default
 
--reap
 
DROP TABLE t1;

It looks like the DB_TRX_ID,DB_ROLL_PTR values in the old_pk search tuple are off by 2 bytes (only 2 bytes of the 4-byte PRIMARY KEY are written).
Without the GEOMETRY column, I get a different assertion failure. This is a deterministic test:

--source include/have_innodb.inc
 
--source include/have_debug.inc
 
--source include/have_debug_sync.inc
 
 
 
--connect (con1,localhost,root,,test)
 
--connection default
 
CREATE  TABLE t1 (a INT, b INT, c INT, col INT) ENGINE=InnoDB;
 
INSERT INTO t1 () VALUES ();
 
ALTER TABLE t1 DROP b, DROP c, DROP col;
 
ALTER TABLE t1 ADD COLUMN col INT;
 
ALTER TABLE t1 DROP a, DROP col, ADD COLUMN b INT;
 
 
 
SET SQL_MODE= '';
 
SET DEBUG_SYNC = 'row_log_table_apply1_before SIGNAL scanned WAIT_FOR dml';
 
send ALTER TABLE t1 ADD PRIMARY KEY(b);
 
 
 
--connection con1
 
SET DEBUG_SYNC = 'now WAIT_FOR scanned';
 
UPDATE t1 SET b = 1;
 
SET DEBUG_SYNC = 'now SIGNAL dml';
 
--disconnect con1
 
--connection default
 
--reap
 
SET DEBUG_SYNC = 'RESET';
 
SELECT * FROM t1;
 
DROP TABLE t1;

10.4 46386661a2311cabd7bac914c44b1af0b4746e07

 
mysqld: storage/innobase/row/row0log.cc:2638: const mrec_t *row_log_table_apply_op(que_thr_t *, ulint, row_merge_dup_t *, dberr_t *, mem_heap_t *, mem_heap_t *, const mrec_t *, const mrec_t *, offset_t *): Assertion `extra_size || !is_instant' failed.

If I add ,FORCE to the penultimate ALTER TABLE, there will be no crash.

Comment by Marko Mäkelä [ 2020-02-04 ]

The problem seems to be in row_log_table_get_pk_col(), for translating the column b:

(gdb) p *log->defaults
 
$18 = {info_bits = 0, n_fields = 4, n_fields_cmp = 4, 
  fields = 0x7fffa0080ac0, n_v_fields = 0, v_fields = 0x0, tuple_list = {
 
    prev = 0x4000, next = 0x7fffa00809b0}, magic_n = 65478679}
 
(gdb) p *log->defaults->fields@4
 
$19 = {{data = 0x7fffa0080b40, ext = 0, spatial_status = 0, len = 4, type = {
 
      prtype = 1283, mtype = 6, len = 4, mbminlen = 0, mbmaxlen = 0}}, {
 
    data = 0x0, ext = 0, spatial_status = 0, len = 4294967295, type = {
 
      prtype = 256, mtype = 8, len = 6, mbminlen = 0, mbmaxlen = 0}}, {
 
    data = 0x0, ext = 0, spatial_status = 0, len = 4294967295, type = {
 
      prtype = 257, mtype = 8, len = 6, mbminlen = 0, mbmaxlen = 0}}, {
 
    data = 0x0, ext = 0, spatial_status = 0, len = 4294967295, type = {
 
      prtype = 258, mtype = 8, len = 7, mbminlen = 0, mbmaxlen = 0}}}
 
(gdb) i lo
 
n_default_cols = 5


		ulint n_default_cols = i - DATA_N_SYS_COLS;
 
 
 
		field = static_cast<const byte*>(
 
			log->defaults->fields[n_default_cols].data);

The n_default_cols is out of the array bounds.

Comment by Marko Mäkelä [ 2020-02-05 ]

When row_log_table_get_pk_col() is replacing a NULL value for online ADD PRIMARY KEY, it would wrongly assume that columns had not been instantly reordered or dropped. We must pass the altered clustered index definition to the function, so that it can look up the default value of that PRIMARY KEY column in the altered table definition.

Generated at Thu Feb 08 09:08:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.