[MDEV-17376] Server fails to set ADD_PK_INDEX, DROP_PK_INDEX if unique index nominated as PK Created: 2018-10-05  Updated: 2019-01-24  Resolved: 2019-01-24

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0.37, 10.1.35, 10.3.11, 10.2.19
Fix Version/s: 10.4.2, 10.1.38, 10.0.38, 10.2.22, 10.3.13

Type: Bug Priority: Critical
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: affects-tests, upstream
Environment:

Ubuntu 17.04 but most probably unimportant

Attachments: File MDEV-17376.tgz    
Issue Links:
Blocks
blocks MDEV-13301 Optimize DROP INDEX, ADD INDEX into R... Closed
Duplicate
is duplicated by MDEV-18165 ulint rec_get_converted_size_comp_pre... Closed

 Description    

GIT: HEAD -> 10.3, origin/HEAD, origin/10.3 fbee31418cf08c62d91195b04a9ed6a42c31bcec
 
        2018-10-04T11:26:42-04:00
 
Version: '10.3.11-MariaDB-debug-log'  
(/work_m/RQG_new/storage/1538676565/867.*)
 
 
 
mysqld: storage/innobase/row/row0log.cc:681: void row_log_table_delete(const rec_t*, dict_index_t*, const ulint*, const byte*): Assertion `new_index->n_uniq == index->n_uniq' failed.
 
Query (0x7f4af8012af0): ROLLBACK  /* E_R Thread10 QNO 1965 CON_ID 703 */
 
Status: NOT_KILLED
 
 
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6)
 
    at ../sysdeps/unix/sysv/linux/raise.c:58
 
#5  0x00007f4b8fa4637a in __GI_abort () 
    at abort.c:89
 
#6  0x00007f4b8fa3cb47 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5596740bc508 "new_index->n_uniq == index->n_uniq", file=file@entry=0x5596740bc088 "storage/innobase/row/row0log.cc", line=line@entry=681, function=function@entry=0x5596740be4c0 <row_log_table_delete(unsigned char const*, dict_index_t*, unsigned long const*, unsigned char const*)::__PRETTY_FUNCTION__> "void row_log_table_delete(const rec_t*, dict_index_t*, const ulint*, const byte*)") 
    at assert.c:92
 
#7  0x00007f4b8fa3cbf2 in __GI___assert_fail (assertion=0x5596740bc508 "new_index->n_uniq == index->n_uniq", file=0x5596740bc088 "storage/innobase/row/row0log.cc", line=681, function=0x5596740be4c0 <row_log_table_delete(unsigned char const*, dict_index_t*, unsigned long const*, unsigned char const*)::__PRETTY_FUNCTION__> "void row_log_table_delete(const rec_t*, dict_index_t*, const ulint*, const byte*)") 
    at assert.c:101
 
#8  0x0000559673947150 in row_log_table_delete (rec=0x7f4b750c4189 "\200", index=0x7f4aa00c3ca8, offsets=0x7f4af80b30e8, sys=0x0) 
    at storage/innobase/row/row0log.cc:681
 
#9  0x0000559673b8986b in row_undo_ins_remove_clust_rec (node=0x7f4af80ab0e8) 
    at storage/innobase/row/row0uins.cc:120
 
#10 0x0000559673b8afd8 in row_undo_ins (node=0x7f4af80ab0e8, thr=0x7f4af80aaf18) 
    at storage/innobase/row/row0uins.cc:612
 
#11 0x0000559673989447 in row_undo (node=0x7f4af80ab0e8, thr=0x7f4af80aaf18) 
    at storage/innobase/row/row0undo.cc:303
 
#12 0x00005596739896a8 in row_undo_step (thr=0x7f4af80aaf18) 
    at storage/innobase/row/row0undo.cc:362
 
#13 0x00005596738ddbf1 in que_thr_step (thr=0x7f4af80aaf18) 
    at storage/innobase/que/que0que.cc:1044
 
#14 0x00005596738dde45 in que_run_threads_low (thr=0x7f4af80aaf18) 
    at storage/innobase/que/que0que.cc:1108
 
#15 0x00005596738de039 in que_run_threads (thr=0x7f4af80aaf18) 
    at storage/innobase/que/que0que.cc:1148
 
#16 0x00005596739ea98a in trx_rollback_to_savepoint_low (trx=0x7f4b7e3afb10, savept=0x0) 
    at storage/innobase/trx/trx0roll.cc:145
 
#17 0x00005596739ead7a in trx_rollback_for_mysql_low (trx=0x7f4b7e3afb10) 
    at storage/innobase/trx/trx0roll.cc:214
 
#18 0x00005596739eb0cd in trx_rollback_for_mysql (trx=0x7f4b7e3afb10) 
    at storage/innobase/trx/trx0roll.cc:240
 
#19 0x00005596737d2c0b in innobase_rollback (hton=0x5596757c49b8, thd=0x7f4af8000a98, rollback_trx=true) 
    at storage/innobase/handler/ha_innodb.cc:4713
 
#20 0x00005596735ca522 in ha_rollback_trans (thd=0x7f4af8000a98, all=true) 
    at sql/handler.cc:1722
 
#21 0x000055967344db6f in trans_rollback (thd=0x7f4af8000a98) 
    at sql/transaction.cc:423
 
#22 0x00005596732e0e11 in mysql_execute_command (thd=0x7f4af8000a98) 
    at sql/sql_parse.cc:5832
 
#23 0x00005596732e7a92 in mysql_parse (thd=0x7f4af8000a98, rawbuf=0x7f4af8012af0 "ROLLBACK  /* E_R Thread10 QNO 1965 CON_ID 703 */", length=48, parser_state=0x7f4b7c2c2640, is_com_multi=false, is_next_command=false) 
    at sql/sql_parse.cc:8091
 
#24 0x00005596732d49e0 in dispatch_command (command=COM_QUERY, thd=0x7f4af8000a98, packet=0x7f4af800a7f9 " ROLLBACK  /* E_R Thread10 QNO 1965 CON_ID 703 */ ", packet_length=50, is_com_multi=false, is_next_command=false) 
    at sql/sql_parse.cc:1850
 
#25 0x00005596732d343f in do_command (thd=0x7f4af8000a98) 
    at sql/sql_parse.cc:1394
 
#26 0x000055967343999f in do_handle_one_connection (connect=0x559676378e78) 
    at sql/sql_connect.cc:1402
 
#27 0x0000559673439716 in handle_one_connection (arg=0x559676378e78) 
    at sql/sql_connect.cc:1308
 
#28 0x00007f4b906856da in start_thread (arg=0x7f4b7c2c3700) 
    at pthread_create.c:456
 
#29 0x00007f4b8fb17d7f in clone () 
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105


RQG setup (some of the settings are RQG run specific)
 
/mnt/r0/mleich/RQG_new/rqg.pl \ 
--mysqld=--innodb_lock_schedule_algorithm=fcfs \ 
--grammar=conf/mariadb/table_stress.yy \ 
--gendata=conf/mariadb/table_stress.zz \ 
--gendata_sql=conf/mariadb/table_stress.sql \ 
--engine=Innodb \ 
--reporters=Deadlock,ErrorLog,Backtrace \ 
--mysqld=--loose_innodb_use_native_aio=0 \ 
--mysqld=--connect_timeout=60 \ 
--mysqld=--net_read_timeout=30 \ 
--mysqld=--net_write_timeout=60 \ 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \ 
--mysqld=--loose-idle_transaction_timeout=0 \ 
--mysqld=--loose-idle_write_transaction_timeout=0 \ 
--mysqld=--interactive_timeout=28800 \ 
--mysqld=--lock_wait_timeout=86400 \ 
--mysqld=--innodb-lock-wait-timeout=50 \ 
--mysqld=--loose-table_lock_wait_timeout=50 \ 
--mysqld=--wait_timeout=28800 \ 
--mysqld=--slave_net_timeout=60 \ 
--mysqld=--log-output=none \ 
--duration=300 \ 
--seed=random \ 
--sqltrace=MarkErrors \ 
--threads=32 \ 
--mysqld=--innodb-flush-log-at-trx-commit=0 \ 
--mysqld=--transaction-isolation=READ-COMMITTED \ 
... (some RQG run specific settings like workdir etc.)
 
--no-mask
 
 
 
The RQG testing "campaign" consisted of 1120 RQG runs.
 
There was some variation of the parameters
 
- "--mysqld=--transaction-isolation"
 
- "--threads"
 
- "--mysqld=--innodb-flush-log-at-trx-commit=0".
 
56 RQG runs hit an assert and 27 of them the assert reported here.
 
 
 
I will try to simplify the RQG grammar.

Same problem occurs on

  • 10.2.19-MariaDB-debug-log
    10.2, origin/10.2 e9d9ca8c44c96e5943c0175177b3377a65b2d76f 2018-10-08T21:40:18+05:30
  • 10.1.35-MariaDB-debug
    10.1, origin/10.1 e08ddccc35f1c199f503861bb63c6f7bcef2a9f6 2018-07-16T12:22:36+03:00

 Comments   
Comment by Matthias Leich [ 2018-10-30 ] 

How to replay the problem?
 
1.  git clone https://github.com/mleich1/rqg --branch experimental RQG_MDEV-17376
 
2. cd RQG_MDEV-17376
 
3. tar xvzf MDEV-17376.tgz
 
    Content of the archive is
 
    MDEV-17376.yy -- shrinked RQG grammar
 
    MDEV-17376.cc -- config file for rqg_batch.pl
 
    MDEV-17376.sh -- shell script which will run the RQG test through rqg_batch.pl
 
    MDEV-17376.prt -- Protocol of one of my RQG replay runs
 
4. ./MDEV-17376.sh <path to binaries like /work_m/10.2/bld_debug/>
 
     The rqg_batch.pl stops immediate in case some replay was achieved.
 
     The file last_batch_workdir/result.txt  will show what the RQG runs achieved.
 
     Example:
 
     2018-10-30T15:58:09 | Number | Verdict  | RQG log    | OrderId | RunTime
 
     2018-10-30T15:59:33 |      1 | replay   |      1.log |      30 |      78
 
                    This RQG run replayed the problem.
 
                    There will be a
 
                            last_batch_workdir/1.log    == RQG log
 
                           last_batch_workdir/1.tgz    == Content of data dir of server, core, etc.
 
      2018-10-30T15:59:34 |      2 | stopped  |  <deleted> |      31 |      77
 
                     Some RQG run which was stopped by rqg_batch.pl because some other
 
                     RQG run had already replayed. Hence the log of this run (2) was deleted.

Comment by Marko Mäkelä [ 2018-10-31 ]

Deterministic (not yet fully simplified) test case:

--source include/have_innodb.inc
 
--source include/have_debug.inc
 
--source include/have_debug_sync.inc
 
 
 
CREATE TABLE t1 (col1 INT, col2 INT) ENGINE = InnoDB;
 
ALTER TABLE t1 ADD PRIMARY KEY(col1, col2);
 
ALTER TABLE t1 ADD UNIQUE INDEX uidx2 ( col1, col2 );
 
ALTER TABLE t1 ADD UNIQUE INDEX uidx1 (col2);
 
ALTER TABLE t1 DROP PRIMARY KEY;
 
SET DEBUG_SYNC = 'innodb_inplace_alter_table_enter SIGNAL conc_dml WAIT_FOR go_ahead';
 
--send
 
alter table t1 change column col1 coll1 int, algorithm=inplace;
 
connect (con1,localhost,root,,);
 
SET DEBUG_SYNC = 'now WAIT_FOR conc_dml';
 
insert into t1 values(1, 1), (1, 1);
 
SET DEBUG_SYNC = 'now SIGNAL go_ahead';
 
disconnect con1;
 
connection default;
 
reap;
 
CHECK TABLE t1;
 
DROP TABLE t1;

10.0 09e97299ba893b7578cac8160b3b687b0594aeee

 
#5  0x00007f76e11ce2f1 in __GI_abort () at abort.c:79
 
#6  0x00007f76dfc74a63 in row_log_table_delete (rec=0x7f76df50c07d "\200", index=0x7f76a40adf78, offsets=0x7f76a800d908, sys=0x0) at /mariadb/10.0/storage/innobase/row/row0log.cc:562
 
#7  0x00007f76dfc97605 in row_undo_ins_remove_clust_rec (node=0x7f76a800ef58) at /mariadb/10.0/storage/innobase/row/row0uins.cc:113
 
#8  0x00007f76dfc98119 in row_undo_ins (node=0x7f76a800ef58) at /mariadb/10.0/storage/innobase/row/row0uins.cc:466
 
#9  0x00007f76dfc9fc7f in row_undo (node=0x7f76a800ef58, thr=0x7f76a800d750) at /mariadb/10.0/storage/innobase/row/row0undo.cc:305
 
#10 0x00007f76dfc9fdf0 in row_undo_step (thr=0x7f76a800d750) at /mariadb/10.0/storage/innobase/row/row0undo.cc:359
 
#11 0x00007f76dfc27db0 in que_thr_step (thr=0x7f76a800d750) at /mariadb/10.0/storage/innobase/que/que0que.cc:1077
 
#12 0x00007f76dfc27fd2 in que_run_threads_low (thr=0x7f76a800d750) at /mariadb/10.0/storage/innobase/que/que0que.cc:1141
 
#13 0x00007f76dfc28161 in que_run_threads (thr=0x7f76a800d750) at /mariadb/10.0/storage/innobase/que/que0que.cc:1182
 
#14 0x00007f76dfcd9d97 in trx_rollback_to_savepoint_low (trx=0x7f76a800b968, savept=0x0) at /mariadb/10.0/storage/innobase/trx/trx0roll.cc:106
 
#15 0x00007f76dfcda065 in trx_rollback_for_mysql_low (trx=0x7f76a800b968) at /mariadb/10.0/storage/innobase/trx/trx0roll.cc:169
 
#16 0x00007f76dfcda395 in trx_rollback_for_mysql (trx=0x7f76a800b968) at /mariadb/10.0/storage/innobase/trx/trx0roll.cc:200
 
#17 0x00007f76dfb716e2 in innobase_rollback (hton=0x55d617d8f438, thd=0x55d618177188, rollback_trx=false) at /mariadb/10.0/storage/innobase/handler/ha_innodb.cc:4023
 
#18 0x000055d6152226c8 in ha_rollback_trans (thd=0x55d618177188, all=false) at /mariadb/10.0/sql/handler.cc:1644
 
#19 0x000055d61516745f in trans_rollback_stmt (thd=0x55d618177188) at /mariadb/10.0/sql/transaction.cc:441
 
#20 0x000055d61504281b in mysql_execute_command (thd=0x55d618177188) at /mariadb/10.0/sql/sql_parse.cc:5161
 
#21 0x000055d615045c1b in mysql_parse (thd=0x55d618177188, rawbuf=0x7f76a8004fc0 "insert into t1 values(1, 1), (1, 1)", length=35, parser_state=0x7f76dc1316a0) at /mariadb/10.0/sql/sql_parse.cc:6637

Comment by Thirunarayanan Balathandayuthapani [ 2018-11-01 ]

Patch is in[ bb-10.0-thiru|https://github.com/MariaDB/server/commit/dc9f113111ee4daf3964db938ef3ddd82c777328]

Comment by Thirunarayanan Balathandayuthapani [ 2018-11-01 ]

https://github.com/MariaDB/server/commit/dc9f113111ee4daf3964db938ef3ddd82c777328

Comment by Marko Mäkelä [ 2018-11-02 ]

Because this is only changing code outside InnoDB, I do not feel entitled to review this.
I think that a change in an error message should be explained.

Comment by Marko Mäkelä [ 2018-11-02 ]

I ported this to 10.2 for testing.
There are now result differences:
Edit: The second one is not a problem: UNIQUE KEY(f1, f2) should be promoted to PRIMARY KEY.
Here is a revised version of innodb.innodb-index, which also asserts that sorting will be skipped when replacing PRIMARY KEY(f1) with UNIQUE KEY(f1,f2).

diff --git a/mysql-test/suite/innodb/r/innodb-index.result b/mysql-test/suite/innodb/r/innodb-index.result
 
index df27769b810..79ed5270e09 100644
 
--- a/mysql-test/suite/innodb/r/innodb-index.result
 
+++ b/mysql-test/suite/innodb/r/innodb-index.result
 
@@ -481,7 +481,7 @@ change b beta int not null, change c charlie int not null;
 
 ERROR HY000: Column 'b' cannot be NOT NULL: needed in a foreign key constraint 
'test/t2_ibfk_1' SET NULL
 
 alter table t2 add primary key (alpha), change a alpha int,
 
 change c charlie int not null, change d delta int not null;
 
-ERROR HY000: Column 'd' cannot be NOT NULL: needed in a foreign key constraint 'test/t2_ibfk_3' SET NULL
 
+ERROR HY000: Cannot drop index 'dc': needed in a foreign key constraint
 
 alter table t2 add primary key (alpha), change a alpha int,
 
 change b beta int, modify c int not null;
 
 affected rows: 0
 
@@ -1539,8 +1539,8 @@ drop table t1;
 
 create table t1(f1 int not null, f2 int not null,
 
 primary key (f1), unique key(f1, f2))engine=innodb;
 
 insert into t1 values(1,3), (2,2);
 
+# MDEV-17376 FIXME: This should fail!!!
 
 alter table t1 drop primary key, lock=none;
 
-ERROR 0A000: LOCK=NONE is not supported. Reason: Dropping a primary key is not allowed without also adding a new primary key. Try LOCK=SHARED
 
 drop table t1;
 
 #
 
 #  BUG#21612714 ALTER TABLE SORTING SKIPPED WHEN CHANGE PK AND DROP

Comment by Matthias Leich [ 2018-11-05 ]

During RQG testing of bb-10.2-marko no problems which might be related to MDEV-13671 or MDEV-1376 found.

Comment by Marko Mäkelä [ 2019-01-11 ]

I believe that we could have multiple duplicates for this, so this bug is definitely affecting tests. At least MDEV-18165 is caused by this bug.

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