Certification failures on a simple update with more than one node active

MySQL & MariaDB Percona XtraDB Cluster 5.x
1

We have an enterprise customer running a three-node XtraDB Cluster 5.6.34 installation which has now been in service for several months. We have recently run into a bug with a simple update.

The customer’s DB includes a table ‘user’ which has around 120 columns. The primary key is an auto_increment INT(11) field. There are no foreign keys, and no foreign key constraints against the table. The table contains a column ‘google_admin’ VARCHAR(50) NOT NULL. Executing the following command, whether the key is found or not, causes a certification failure, reported by the MySQL client as a deadlock but InnoDB reports no deadlocks:

mysql> update user set google_admin=‘’ where google_admin=‘example@host.org’;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
After some experiment and testing, we determined that if we bring the cluster down to a single node and execute this transaction, it succeeds (if the key is found) or fails (if it is not found) without error:

mysql> update user set google_admin=‘’ where google_admin=‘example@host.org’;Query OK, 1 row affected (4.08 sec)
Rows matched: 1 Changed: 1 Warnings: 0

mysql> update user set google_admin=‘’ where google_admin=‘example@host.org’;Query OK, 0 rows affected (3.04 sec)
Rows matched: 0 Changed: 0 Warnings: 0
As soon as we rejoin a second node to the cluster, this exact transaction against this exact table begins failing certification again. Again, the certification failure occurs regardless of whether or not any table rows are even matched (let alone changed).

Is anyone able to explain this behavior? We do have a workaround, but it is cumbersome, involving a BEGIN TRANSACTION; SELECT … FOR UPDATE; UPDATE … ; COMMIT sequence. However, the very fact that this cumbersome workaround does work seems to suggest that there is not in fact any certification conflict preventing the update. The certification failure is a false alarm.

What we would of course like to determine is why this is happening, and what we can do to prevent it.

Further information:
In the course of attempting to troubleshoot this problem, we attempted to clone the table. This, too, failed certification:

mysql> create table user2 like user;
Query OK, 0 rows affected (0.07 sec)

mysql> insert into user2 select * from user;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

I suspect, but have not yet verified, that somehow the three copies of the table on the three nodes have discrepancies in their actual contents. I have no theory as to how this may have happened.

2

It would be helpful of you can provide error.log files from all nodes during this failure.

Also if you are flexible with starting nodes, you can start nodes with --wsrep-debug=1, it will put more debug information into error.log

3

I will try wsrep-debug. I assume I can put that in the config file? At present, there is absolutely nothing logged to the error log.

4

yes, put wsrep-debug=1 into config file.
you also may add wsrep_log_conflicts=1

5

OK, this got us some information. The node attempting to execute the transaction logs the following:

*** Priority TRANSACTION:
TRANSACTION 4148936891, ACTIVE 0 sec starting index read
mysql tables in use 2, locked 2
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 3, OS thread handle 0x7f257c169700, query id 241383301 System lock

*** Victim TRANSACTION:
TRANSACTION 4148936633, ACTIVE 0 sec fetching rows, thread declared inside InnoDB 4721
mysql tables in use 2, locked 2
11790 lock struct(s), heap size 1046056, 57076 row lock(s)
MySQL thread id 62598200, OS thread handle 0x7f242fe79700, query id 241381963 localhost root updating
update brainpop.user set google_admin = ‘’ where google_admin = ‘example@host.org’
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3869 page no 2552 n bits 72 index PRIMARY of table brainpop.user trx id 4148936633 lock_mode X
2017-03-14 16:35:38 19657 [Note] WSREP: cluster conflict due to high priority abort for threads:
2017-03-14 16:35:38 19657 [Note] WSREP: Winning thread:
THD: 3, mode: applier, state: executing, conflict: no conflict, seqno: 124189853
SQL: (null)
2017-03-14 16:35:38 19657 [Note] WSREP: Victim thread:
THD: 62598200, mode: local, state: executing, conflict: no conflict, seqno: -1
SQL: update brainpop.user set google_admin = ‘’ where google_admin = ‘example@host.org’

*** Priority TRANSACTION:
TRANSACTION 4148937890, ACTIVE 0 sec starting index read
mysql tables in use 2, locked 2
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 5, OS thread handle 0x7f257c128700, query id 241388303 System lock

*** Victim TRANSACTION:
TRANSACTION 4148936895, ACTIVE 1 sec fetching rows, thread declared inside InnoDB 3273
mysql tables in use 2, locked 2
44057 lock struct(s), heap size 3913256, 345842 row lock(s)
MySQL thread id 62598200, OS thread handle 0x7f242fe79700, query id 241381963 localhost root updating
update brainpop.user set google_admin = ‘’ where google_admin = ‘example@host.org’
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3869 page no 3785 n bits 72 index PRIMARY of table brainpop.user trx id 4148936895 lock_mode X
2017-03-14 16:35:39 19657 [Note] WSREP: cluster conflict due to high priority abort for threads:
2017-03-14 16:35:39 19657 [Note] WSREP: Winning thread:
THD: 5, mode: applier, state: executing, conflict: no conflict, seqno: 124189923
SQL: (null)
2017-03-14 16:35:39 19657 [Note] WSREP: Victim thread:
THD: 62598200, mode: local, state: executing, conflict: no conflict, seqno: -1
SQL: update brainpop.user set google_admin = ‘’ where google_admin = ‘example@host.org’

Nothing of interest appears in the logs of the other two nodes. Threads 3 and 5 are replication applier threads, but I can find nothing in the logs to tell me what the replicated transaction is that is causing the local cert failure.

TX isolation was set to REPEATABLE READ. We tried changing to READ COMMITTED but it made no difference.

Again I note that this transaction is being killed for conflict even when it matches no rows.

6

can you “show create table brainpop.user” ?

7

Vadim,
The customer is not willing to have the table schema posted in a public forum due to information leakage. However, looking again at the table today I identified some indexing issues. In particular, the google_admin column was not indexed, so mysqld was performing a full scan of the table (677,000 rows), and presumably pessimistically requesting a lock on the entire table since it didn’t know until the scan was complete which rows it would need to update. So when other better-indexed queries ran against the table on other nodes, they committed first and won the lock race, causing a spurious local failure on the node running this transaction.

The solution turned out to be to create an index over the google_admin column. With that change, the problem query runs nearly instantly and completes with no issues.

8

That’s what I’ve suspected - you did not have the index on google_admin column, I asked SHOW CREATE TABLE to confirm that.