Percona-XtraDB Cluster server-57 5.7.19 deadlocks with WHMCS 7

Bug #1732313 reported by Burnley on 2017-11-15
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Fix Committed
Undecided
Unassigned

Bug Description

CentOS 7.4 running as Xen domUs. Latest packages set:
Percona-XtraDB-Cluster-server-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-garbd-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-shared-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-test-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-shared-compat-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-client-57-5.7.19-29.22.3.el7.x86_64
Percona-XtraDB-Cluster-devel-57-5.7.19-29.22.3.el7.x86_64

Two nodes and an arbitrator, all using ext4 with the default mount options:
/dev/xvda1 on / type ext4 (rw,relatime,data=ordered)

Several posts including "SHOW ENGINE InnoDB STATUS" here:
https://www.percona.com/forums/questions-discussions/percona-xtradb-cluster/48497-cluster-hang-with-wsrep-initiating-replication-for-write-set

The deadlocks are random, here's the latest one:

| InnoDB | |
=====================================
2017-11-15 12:17:41 0x7fc9cc0a7700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 10 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 10 srv_active, 0 srv_shutdown, 2805 srv_idle
srv_master_thread log flush and writes: 2815
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 15
OS WAIT ARRAY INFO: signal count 15
RW-shared spins 0, rounds 23, OS waits 11
RW-excl spins 0, rounds 1, OS waits 1
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 23.00 RW-shared, 1.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 9150116
Purge done for trx's n < 0 undo n < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421981788381968, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 9149460, ACTIVE 781 sec
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
MySQL thread id 1379, OS thread handle 140504688125696, query id 4286 192.168.1.230 newib_whmcs wsrep: initiating replication for write set (-1)
INSERT INTO tbladminlog (`adminusername`,`logintime`,`lastvisit`,`ipaddres s`,`sessionid`) VALUES ('ib_admin','20171115120440','20171115120440','1 92.168.1.66','06984989bc1ab463aa79ff046f988964')
---TRANSACTION 9149454, ACTIVE 838 sec
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1
MySQL thread id 1336, OS thread handle 140504688924416, query id 4068 192.168.1.230 newib_whmcs wsrep: initiating replication for write set (-1)
INSERT INTO tbladminlog (`adminusername`,`logintime`,`lastvisit`,`ipaddres s`,`sessionid`) VALUES ('admin2','20171115120343','20171115120343','192.1 68.1 .63','4b9a16fb34dfbb87d5e0ee7d0c714c18')
---TRANSACTION 9149448, ACTIVE 909 sec
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 1286, OS thread handle 140504688658176, query id 3858 192.168.1.230 newib_whmcs wsrep: initiating replication for write set (-1)
UPDATE tbltransientdata SET `data`='{"hash":"1a5852cff3a5895f4137334d4a3d1b93" ,"locales":[{"locale":"ar_AR","language":"arabic","language Cod e":"ar","countryCode":"AR","localisedName":"\\u 062 7\\u0644\\u0639\\u0631\\u0628\\u064a\\u0629"},{"lo cale":"az_AZ","language":"azerbaijani","languageCo de":"az","countryCode":"AZ","localisedName":"Aze rb aijani"},{"locale":"ca_AD","language":"catalan","l anguageCode":"ca","countryCode":"AD","localisedNam e":"Catal\\u00e0"},{"locale":"zh_TW","language" :"c hinese","languageCode":"zh","co
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
18003 OS file reads, 113 OS file writes, 48 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 12, seg size 14, 1 merges
merged operations:
insert 1, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 398491, node heap has 2 buffer(s)
Hash table size 398491, node heap has 2 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 0 buffer(s)
Hash table size 398491, node heap has 0 buffer(s)
Hash table size 398491, node heap has 0 buffer(s)
Hash table size 398491, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 19319928631
Log flushed up to 19319928631
Pages flushed up to 19319928631
Last checkpoint at 19319928622
Max checkpoint age 80826164
Checkpoint age target 78300347
Modified age 0
Checkpoint age 9
0 pending log flushes, 0 pending chkp writes
34 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 1676673024
Dictionary memory allocated 1928014
Internal hash tables (constant factor + variable factor)
Adaptive hash index 25668160 (25503424 + 164736)
Page hash 1594504 (buffer pool 0 only)
Dictionary cache 8303870 (6375856 + 1928014)
File system 1141928 (812272 + 329656)
Lock system 3989688 (3985144 + 4544)
Recovery system 0 (0 + 0)
Buffer pool size 98292
Buffer pool size, bytes 1610416128
Free buffers 80678
Database pages 17606
Old database pages 6519
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 17569, created 37, written 62
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 17606, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
3 RW transactions active inside InnoDB
Process ID=13419, Main thread ID=140504839718656, state: sleeping
Number of rows inserted 4323, updated 1, deleted 0, read 172076
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

affects: percona-server → percona-xtradb-cluster
Krunal Bauskar (krunal-bauskar) wrote :

From the description, it sounds like you are hitting following issue
https://jira.percona.com/browse/PXC-877

The issue is already fixed on trunk and will be part of next PXC release.

Changed in percona-xtradb-cluster:
status: New → Fix Committed

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-2017

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

Other bug subscribers