updating a unique key can cause parallel applying to hang

Bug #1280896 reported by Seppo Jaakola on 2014-02-16
48
This bug affects 7 people
Affects Status Importance Assigned to Milestone
MySQL patches by Codership
Status tracked in 5.6
5.5
High
Seppo Jaakola
5.6
High
Seppo Jaakola
Percona XtraDB Cluster
Status tracked in 5.6
5.5
Undecided
Unassigned
5.6
Undecided
Unassigned

Bug Description

updating a unique key value can cause server hang if slave node has enabled parallel slaves.
This seems to to be because such updates will require extra reads (with S locks) to make sure that there will be no duplicate keys with he new key value. These S locks were not taken in account when forming the write set, and we have a "asymmetric lock granularity" issue here.

To make this issue to surface, you will need high conflict rate updates on unique keys.

Changed in codership-mysql:
status: New → In Progress
importance: Undecided → High
assignee: nobody → Seppo Jaakola (seppo-jaakola)
milestone: none → 5.1.63-23.5
Seppo Jaakola (seppo-jaakola) wrote :

S locks for duplicate key checking is unnecessary for appliers, who run in high priority. Skipping these locks solves this issue.
Fixes pushed in:
wsrep-5.6: http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4043
wsrep-5.5: http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3952

jfr (j-francoz) wrote :
Download full text (5.6 KiB)

Hello

The problem seems to be still present.
I think that, due to the snapshot isolation between the nodes of the cluster, we can have two transactions doing an insert on the same table with the same data for the unique constraint.

Exemple :
create table uniq (u varchar(10), unique key `unique_key`(`u`));

echo "insert into uniq (u) values ('const');" | mysql -h maria01 &
echo "insert into uniq (u) values ('const');" | mysql -h maria02 &

I've got this error each time :
140328 15:42:38 [ERROR] Slave SQL: Could not execute Write_rows event on table test-lbn.uniq; Duplicate entry 'const' for key 'unique_key', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 85, Error_code: 1062
140328 15:42:38 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 5116
140328 15:42:38 [Warning] WSREP: Failed to apply app buffer: seqno: 5116, status: 1
         at galera/src/trx_handle.cpp:apply():340
Retrying 2th time
140328 15:42:38 [ERROR] Slave SQL: Could not execute Write_rows event on table test-lbn.uniq; Duplicate entry 'const' for key 'unique_key', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 85, Error_code: 1062
140328 15:42:38 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 5116
140328 15:42:38 [Warning] WSREP: Failed to apply app buffer: seqno: 5116, status: 1
         at galera/src/trx_handle.cpp:apply():340
Retrying 3th time
140328 15:42:38 [ERROR] Slave SQL: Could not execute Write_rows event on table test-lbn.uniq; Duplicate entry 'const' for key 'unique_key', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 85, Error_code: 1062
140328 15:42:38 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 5116
140328 15:42:38 [Warning] WSREP: Failed to apply app buffer: seqno: 5116, status: 1
         at galera/src/trx_handle.cpp:apply():340
Retrying 4th time
140328 15:42:38 [ERROR] Slave SQL: Could not execute Write_rows event on table test-lbn.uniq; Duplicate entry 'const' for key 'unique_key', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 85, Error_code: 1062
140328 15:42:38 [Warning] WSREP: RBR event 2 Write_rows apply warning: 121, 5116
140328 15:42:38 [Note] WSREP: commit failed for reason: 3
140328 15:42:38 [Note] WSREP: conflict state: 0
140328 15:42:38 [Note] WSREP: cluster conflict due to certification failure for threads:
140328 15:42:38 [Note] WSREP: Victim thread:
   THD: 13, mode: local, state: executing, conflict: cert failure, seqno: 5117
   SQL: insert into uniq (u) values ('const')
140328 15:42:38 [Note] WSREP: wsrep retrying AC query: insert into uniq (u) values ('const')
140328 15:42:38 [ERROR] WSREP: Failed to apply trx: source: dd3ef4a4-b686-11e3-9fec-67b866b47c4d version: 3 local: 0 state: APPLYING flags: 1 conn_id: 45 trx_id: 47302914 seqnos (l: 6, g: 5116, s: 5115, d: 5115, ts: 967608690227148)
140328 15:42:38 [ERROR] WSREP: Failed to apply trx 5116 4 times
140328 15:42:38 [ERROR] WSREP: Node consistency compromized, aborting...
140328 15:42:38 [Note] WSREP: Closing send monitor...
140328 15:42:38 [Note] WSREP...

Read more...

Alex Yurchenko (ayurchen) wrote :

I think this is another issue: wsrep replication does not support SNAPSHOT isolation (at least at the moment).

Teemu Ollakka (teemu-ollakka) wrote :

Hi jfr,

Thanks for the testcase, I was able to reproduce the crash. This does not look like applier-applier conflict though, will open a new ticket once there is more information available.

Seppo Jaakola (seppo-jaakola) wrote :

 The fix for this bug triggered bug lp:1299116, so these two are related. after all

Seppo Jaakola (seppo-jaakola) wrote :

The fix was to both skip check for duplicate keys in secondary indexes *and* also avoid duplicate key error. Fixes pushed in revisions:

wsrep-5.5: http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3983
wsrep-5.6: http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4078

jfr (j-francoz) wrote :

Hello

Are you sure that it will not violate the constraint if we skip duplicate keys checking ?

Exemple :
create table uniq (u varchar(10), v varchar(10), unique key `unique_key`(`u`));

echo "insert into uniq (u,v) values ('const','value1');" | mysql -h maria01 &
echo "insert into uniq (u,v) values ('const','value2');" | mysql -h maria02 &

select * from uniq where u='const';

Seppo Jaakola (seppo-jaakola) wrote :

It turned out that the regression test did not do a good job, and also that skipping UK duplicate key check was not safe in all cases. Regression test just did not bring enough situations where the problems would arise.

Opened the bug to track the progress with better fix for this issue.

Seppo Jaakola (seppo-jaakola) wrote :

Pushed in a fix for wsrep-5.6 in revision: http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4095

Here applier runs the UK duplicate value check, but avoids taking GAP locks during this check.

Pushed also new regression test with 3 different test modes for this issue

This (with latest revision merged) crashes as:

granted: (26 seqno -1 wsrep (0, 1, 1) cmd 3 6 INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`)
2014-06-09 22:52:47 13680 [Note] WSREP: MDL ticket: type: shared write space: TABLE db: test name: e
2014-06-09 22:52:47 13680 [Note] WSREP: wsrep_abort_thd, by: 140059626616576, victim: 140059891640064
2014-06-09 22:52:47 13680 [Note] WSREP: abort transaction: BF: ALTER TABLE e RENAME `table1000_innodb_int` victim: INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`
2014-06-09 22:52:47 13680 [Note] WSREP: cluster conflict due to high priority abort for threads:
2014-06-09 22:52:47 13680 [Note] WSREP: Winning thread:
   THD: 44, mode: total order, state: executing, conflict: no conflict, seqno: 365
   SQL: ALTER TABLE e RENAME `table1000_innodb_int`
2014-06-09 22:52:47 13680 [Note] WSREP: Victim thread:
   THD: 26, mode: local, state: executing, conflict: must abort, seqno: -1
   SQL: INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`
2014-06-09 22:52:47 13680 [Note] WSREP: BF kill (1, seqno: 365), victim: (26) trx: 2773
2014-06-09 22:52:47 13680 [Note] WSREP: Aborting query: INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`
2014-06-09 22:52:47 13680 [Note] WSREP: victim 2773 in MUST ABORT state
2014-06-09 22:52:47 13680 [Note] WSREP: MDL victim killed at add_ticket
2014-06-09 22:52:47 13680 [Note] WSREP: TO BEGIN: -1, 0 : DROP TABLE IF EXISTS l
2014-06-09 22:52:48 13680 [Note] WSREP: client rollback due to BF abort for (26), query: INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`
2014-06-09 22:52:48 13680 [Note] WSREP: abort in exec query state, avoiding autocommit
2014-06-09 22:52:48 13680 [Note] WSREP: wsrep retrying AC query: INSERT INTO e SELECT * FROM `table500_innodb_bigint_autoinc`
2014-06-09 22:52:48 13680 [Note] WSREP: MDL conflict db=test table=e ticket=8 solved by abort
2014-06-09 22:52:48 7f622c4ab700 InnoDB: Assertion failure in thread 140059626616576 in file lock0lock.cc line 2311
InnoDB: Failing assertion: !(type_mode & 1024)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

The assertion hits here:

 type_mode |= LOCK_REC;

 /* If rec is the supremum record, then we can reset the gap bit, as
 all locks on the supremum are automatically of the gap type, and we
 try to avoid unnecessary memory consumption of a new record lock
 struct for a gap type lock */

 if (UNIV_UNLIKELY(heap_no == PAGE_HEAP_NO_SUPREMUM)) {
  ut_ad(!(type_mode & LOCK_REC_NOT_GAP));

  /* There should never be LOCK_REC_NOT_GAP on a supremum
  record, but let us play safe */

  type_mode = type_mode & ~(LOCK_GAP | LOCK_REC_NOT_GAP);
 }

The above is with UNIV_DEBUG build.

Also, with

bzr diff
=== modified file 'storage/innobase/lock/lock0lock.cc'
--- storage/innobase/lock/lock0lock.cc 2014-06-08 19:48:57 +0000
+++ storage/innobase/lock/lock0lock.cc 2014-06-09 17:31:56 +0000
@@ -2308,7 +2308,8 @@
        struct for a gap type lock */

        if (UNIV_UNLIKELY(heap_no == PAGE_HEAP_NO_SUPREMUM)) {
- ut_ad(!(type_mode & LOCK_REC_NOT_GAP));
+ ut_ad(!(type_mode & LOCK_REC_NOT_GAP) ||
+ wsrep_thd_is_BF(trx->mysql_thd, FALSE));

                /* There should never be LOCK_REC_NOT_GAP on a supremum
                record, but let us play safe */

I have not been able to get a crash. (missing the ifdef WSREP parts though).

Seppo Jaakola (seppo-jaakola) wrote :

Regression test for lp:928150 has been failing after this fix was pushed in, re-opening the bug

Seppo Jaakola (seppo-jaakola) wrote :

Fix for the lp:928150 regression was pushed for wsrep-5.6, in revision
http://bazaar.launchpad.net/~codership/codership-mysql/5.6/revision/4097

Relating to this issue, I see

static Sys_var_mybool Sys_wsrep_slave_UK_checks(

       "wsrep_slave_UK_checks", "Should slave thread do "

       "secondary index uniqueness chesks",

       GLOBAL_VAR(wsrep_slave_UK_checks),

       CMD_LINE(OPT_ARG), DEFAULT(FALSE));

added.

But, this changes from the default unlike wsrep_slave_FK_checks.

tags: added: i43277
Davide Bozzelli (buzzz) wrote :

When fixes for 5.5 will be released ?

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers