[xtradb] multi node write deadlock issue
1,634 views
Skip to first unread message
김진경
Apr 3, 2018, 9:01:51 PM4/3/18
to Percona Discussion
Hi,
i have multi node write deadlock/conflict problem.
environment is two mysql node / multi master clustering use percona xtradb
table A schema
- field A : long-int, auto-increment, pk index field
- field B : int
then, show node #1 logs
[Note] WSREP: cluster conflict due to high priority abort for threads:
[Note] WSREP: Winning thread:
THD: 10, mode: applier, state: executing, conflict: no conflict, seqno: 37097095
SQL: (null)
[Note] WSREP: Victim thread:
THD: 18, mode: local, state: idle, conflict: no conflict, seqno: -1
SQL: (null)
Node #1 (victim thread transaction)
- UPDATE `table A` SET `field B` = 1 WHERE `field A`= 7302
- ROLLBACK
Node #2 (winning thread transaction : write set seq 37097095)
- INSERT INTO `table A`(`field B`) VALUES (1);
note that, seq 37097094 write-set is
- INSERT INTO `table A`(`field B`) VALUES (1)"
write set 37097095 result is (7301, 1)
write set 37097094 result is (7303, 1)
Be sure that, record 7302 is exists.
I cannot find deadlock/conflict reason.
please help me.
krunal....@percona.com
Apr 3, 2018, 11:51:46 PM4/3/18
to Percona Discussion
Sounds bit strange.
1. Which version of PXC are you using
2. Can you share error log from both the nodes
3. Can you share configuration from both the nodes
4. Do you have reproducible test-case?
Regards,
Krunal
김진경
Apr 4, 2018, 2:45:33 AM4/4/18
to percona-d...@googlegroups.com
To. Krunal
[Schema]
Table A
- FieldA LONG, AUTO-INCREMENT, PK
- FieldB LONG, IndexA field
- FieldC INT
[PXC version]
5.7
5.7
[Log]
Node #1
mysqld.log
2018-04-04T06:04:35.693029Z 4 [Note] WSREP: wsrep: applying write-set (56593786)
2018-04-04T06:04:35.693067Z 4 [Note] WSREP: wsrep: writing row for write-set (56593786)
2018-04-04T06:04:35.693107Z 4 [Note] WSREP: wsrep: applied write set (56593786)
2018-04-04T06:04:35.693115Z 4 [Note] WSREP: wsrep: committing write set (56593786)
2018-04-04T06:04:35.693128Z 4 [Note] WSREP: wsrep: committed write set (56593786)
2018-04-04T06:04:35.696431Z 39 [Note] WSREP: wsrep: replicating commit (-1)
2018-04-04T06:04:35.696439Z 39 [Note] WSREP: wsrep: initiating replication for write set (-1)
2018-04-04T06:04:35.696914Z 39 [Note] WSREP: wsrep: write set replicated (56593787)
2018-04-04T06:04:35.696930Z 39 [Note] WSREP: wsrep: initiating pre-commit for write set (56593787)
2018-04-04T06:04:35.696953Z 39 [Note] WSREP: wsrep: pre-commit/certification passed (56593787)
2018-04-04T06:04:35.698399Z 38 [Note] WSREP: set_query_FieldA(), assigned new next trx FieldA: 852473
2018-04-04T06:04:35.698488Z 39 [Note] WSREP: set_query_FieldA(), assigned new next trx FieldA: 852474
2018-04-04T06:04:35.699824Z 6 [Note] WSREP: wsrep: applying write-set (56593788)
2018-04-04T06:04:35.699891Z 6 [Note] WSREP: wsrep: updating row for write-set (56593788)
general log
2018-04-04T06:04:35.685099Z 39 Query BEGIN
2018-04-04T06:04:35.687321Z 39 Query INSERT INTO `TableA`(`FieldB`, `FieldC`) VALUES (62, 0)
2018-04-04T06:04:35.696417Z 39 Query COMMIT
* Record Result = (FieldA = 1210, FieldB = 62, FieldC = 0)
Node #2
mysqld.log
2018-04-04T06:04:35.700608Z 3 [Note] WSREP: wsrep: writing row for write-set (56593787)
*** Priority TRANSACTION:
TRANSACTION 91556508, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
MySQL thread id 3, OS thread handle 140516297950976, query id 838273 wsrep: writing row for write-set (56593787)
*** Victim TRANSACTION:
TRANSACTION 91556506, ACTIVE 0 sec
, undo log entries 1
MySQL thread id 36, OS thread handle 140516169017088, query id 838270 172.19.140.168 admin
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 43 page no 8 n bits 272 index PRIMARY of table `TestDB`.`TableA` trx id 91556506 lock_mode X
2018-04-04T06:04:35.700685Z 3 [Note] WSREP: --------- CONFLICT DETECTED --------
2018-04-04T06:04:35.700701Z 3 [Note] WSREP: cluster conflict due to high priority abort for threads:
2018-04-04T06:04:35.700689Z 32 [Note] WSREP: set_query_id(), assigned new next trx id: 838274
2018-04-04T06:04:35.700706Z 3 [Note] WSREP: Winning thread:
THD: 3, mode: applier, state: executing, conflict: no conflict, seqno: 56593787
SQL: (null)
2018-04-04T06:04:35.700724Z 3 [Note] WSREP: Victim thread:
THD: 36, mode: local, state: idle, conflict: no conflict, seqno: -1
SQL: (null)
2018-04-04T06:04:35.700728Z 3 [Note] WSREP: BF thread 3 (with write-set: 56593787) aborting Victim thread 36 with transaction (91556506)
2018-04-04T06:04:35.700731Z 3 [Note] WSREP: Aborting query: void
2018-04-04T06:04:35.700734Z 3 [Note] WSREP: Killing Transaction (91556506) in QUERY_IDLE state
2018-04-04T06:04:35.700738Z 3 [Note] WSREP: Enqueue transaction for force-abort 36
2018-04-04T06:04:35.700740Z 3 [Note] WSREP: Signal Rollback/Aborter
2018-04-04T06:04:35.700779Z 1 [Note] WSREP: Rollback/Aborter thread wakes for signal. Has some transaction rollback work to do.
2018-04-04T06:04:35.700791Z 36 [Note] WSREP: Initiating rollback. Transaction (query: (null)) triggered by thread 36 was BF aborted
general log
2018-04-04T06:04:35.698995Z 36 Query BEGIN
2018-04-04T06:04:35.699641Z 36 Query UPDATE `TableA` SET `FieldC`=1 WHERE `FieldA`=1211
2018-04-04T06:04:35.700493Z 36 Query SELECT * FROM `TableA` WHERE `FieldA`=1211
2018-04-04T06:04:36.294376Z 36 Query ROLLBACK
Victim transaction's thead id is 36, Node#2 general log is transaction that run thread 36
Winning transaction wsrep seqno is 56593787. Thus, Node #1 general log is transaction that run thread 39
[Configuration]
Node #1
symbolic-links=0
wsrep_provider=/usr/lib/galera3/libgalera_smm.so
wsrep_debug=ON
wsrep_cluster_name=test_cluster
wsrep_cluster_address=gcomm://172.20.86.102,172.20.85.211
binlog_format=ROW
default_storage_engine=InnoDB
wsrep_slave_threads= 8
wsrep_log_conflicts
innodb_autoinc_lock_mode=2
wsrep_node_address=172.20.86.102
wsrep_node_name=firstnode
pxc_strict_mode=ENFORCING
wsrep_sst_method=xtrabackup-v2
wsrep_sst_auth="sstuser:sstuser"
wsrep_retry_autocommit=3
Node #2
symbolic-links=0
wsrep_provider=/usr/lib/galera3/libgalera_smm.so
wsrep_debug=ON
wsrep_cluster_name=test_cluster
wsrep_cluster_address=gcomm://172.20.86.102,172.20.85.211
binlog_format=ROW
default_storage_engine=InnoDB
wsrep_slave_threads= 8
wsrep_log_conflicts
innodb_autoinc_lock_mode=2
wsrep_node_address=172.20.85.211
wsrep_node_name=secondnode
pxc_strict_mode=ENFORCING
# SST method
wsrep_sst_method=xtrabackup-v2
wsrep_sst_auth="sstuser:sstuser"
wsrep_retry_autocommit=3
I run test by own test-client, but it's simple.
test client A (thread 8) ------------ Node #1
test client B (thread 8) ------------ Node #2
Each thread did not access same record.
Each thread access just their own record.
[Environment]
- Cluster size is just 2 nodes
- I don't use Proxy. Each test clients direct access each nodes.
Thank, Krunal
krunal....@percona.com
Apr 5, 2018, 1:02:35 AM4/5/18
to Percona Discussion
Hi,
* I tried reproducing it but couldn't get the said error.
* I have a few more followup questions:
- which sub-version of 5.7 are you using (5.7.x)
- In your example, 56593787 is inserting a row with fieldA=1210 from node-1.
On node-2, the row with fieldA=1211 is already present. Which transaction inserted it?
- there is also an applier trx (with write-set-id 56593788). what is this write-set carrying?
Regards,
Krunal
김진경
Apr 5, 2018, 4:10:52 AM4/5/18
to Percona Discussion
Hi,
Well, I don't know what raise deadlock/conflict.
Because both query didn't access same row. You know, insert query(seqno 56593787) use just insert intension lock. it did not use gap-lock. And Node#2's update query also use pk index record lock. it did not use nextkey-lock.
But, In addition, this issue did not raise when running same mysql single instance.
Anyway, answer to your question.
1. which sub-version of 5.7 are you using (5.7.x)
OS : Ubuntu 16.04.3 LTS
Xtradb : Percona XtraDB Cluster 5.7.21-29.26-1.xenial
2. In your example, 56593787 is inserting a row with fieldA=1210 from node-1. On node-2, the row with fieldA=1211 is already present. Which transaction inserted it?
This is Node #2's log
2018-04-04T06:04:35.694395Z 36 Query BEGIN
2018-04-04T06:04:35.695211Z 36 Query INSERT INTO `TableA`(`FieldB`,`FieldC`) VALUES (79,0)
2018-04-04T06:04:35.696325Z 36 Query COMMIT
2018-04-04T06:04:35.696338Z 36 [Note] WSREP: wsrep: replicating commit (-1)
2018-04-04T06:04:35.696349Z 36 [Note] WSREP: wsrep: initiating replication for write set (-1)COMMIT
2018-04-04T06:04:35.696537Z 36 [Note] WSREP: wsrep: write set replicated (56593786)
2018-04-04T06:04:35.696568Z 36 [Note] WSREP: wsrep: initiating pre-commit for write set (56593786)
2018-04-04T06:04:35.696589Z 36 [Note] WSREP: wsrep: pre-commit/certification passed (56593786)
This is Node #1's log
2018-04-04T06:04:35.693029Z 4 [Note] WSREP: wsrep: applying write-set (56593786)
2018-04-04T06:04:35.693067Z 4 [Note] WSREP: wsrep: writing row for write-set (56593786)
2018-04-04T06:04:35.693107Z 4 [Note] WSREP: wsrep: applied write set (56593786)
2018-04-04T06:04:35.693115Z 4 [Note] WSREP: wsrep: committing write set (56593786)
2018-04-04T06:04:35.693128Z 4 [Note] WSREP: wsrep: committed write set (56593786)
Request by Node #2. And Node #1 applied normally.
3. there is also an applier trx (with write-set-id 56593788). what is this write-set carrying?
This is Node #2's log.
2018-04-04T06:04:35.698130Z 30 Query BEGIN
2018-04-04T06:04:35.698678Z 30 Query UPDATE `TableB` SET `FieldC`=1 WHERE `FieldA`=93
2018-04-04T06:04:35.699640Z 30 Query SELECT * FROM `TableB` WHERE `FieldA`=93
2018-04-04T06:04:35.701209Z 30 Query COMMIT
2018-04-04T06:04:35.701219Z 30 [Note] WSREP: wsrep: replicating commit (-1)
2018-04-04T06:04:35.701234Z 30 [Note] WSREP: wsrep: initiating replication for write set (-1)
2018-04-04T06:04:35.703594Z 30 [Note] WSREP: wsrep: write set replicated (56593788)
2018-04-04T06:04:35.703631Z 30 [Note] WSREP: wsrep: initiating pre-commit for write set (56593788)
2018-04-04T06:04:35.703645Z 30 [Note] WSREP: wsrep: pre-commit/certification passed (56593788)
But, this transaction access TableB. So. I think that it has any relationship for this issue.
Thanks, Krunal.
Reply all
Reply to author
Forward
0 new messages