Cluster hang with wsrep: initiating replication for write set

I have a 3 node cluster. This morning the cluster wasn’t working. In SHOW PROCESSLIST, 2 of the 3 nodes had many instances of requests showing:

wsrep: initiating replication for write set

I had to shut the cluster down and rebootstrap. Any suggestions?

Saw another occurrence of this. Anyone?

Seeing the same issue the 2nd time in 2 days, 3 nodes cluster (2 db + 1 arbitrator). At the moment can’t write to any of the databases, any insert stalls.

Running on CentOS 7.4 with:
Percona-XtraDB-Cluster-server-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-garbd-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-shared-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-test-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-devel-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-client-57-5.7.19-29.22.1.el7.x86_64
Percona-XtraDB-Cluster-shared-compat-57-5.7.19-29.22.1.el7.x86_64

mysql> show variables like ‘%version%’;
±------------------------±------------------------------------------------------------------------------------------------+
| Variable_name | Value |
±------------------------±------------------------------------------------------------------------------------------------+
| innodb_version | 5.7.19-17 |
| protocol_version | 10 |
| slave_type_conversions | |
| tls_version | TLSv1,TLSv1.1,TLSv1.2 |
| version | 5.7.19-17-57-log |
| version_comment | Percona XtraDB Cluster (GPL), Release rel17, Revision c10027a, WSREP version 29.22, wsrep_29.22 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
±------------------------±------------------------------------------------------------------------------------------------+

show processlist:
Id User Host db Command Time State Info Rows_sent Rows_examined
1 system user NULL Sleep 85394 wsrep: applier idle NULL 0 0
2 system user NULL Sleep 85394 wsrep: aborter idle NULL 0 0
5 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
6 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
7 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
8 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
9 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
10 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
11 system user NULL Sleep 85392 wsrep: applier idle NULL 0 0
56821 mydb1_testdb 10.3.0.205:53618 mydb1_live_testdb Query 4100 wsrep: initiating replication for write set (-1) INSERT INTO tblactivitylog (date,description,user,userid,ipaddr) VALUES (‘20171013111426’, 0 0
56822 mydb1_testdb 10.3.0.205:53620 mydb1_live_testdb Sleep 4100 NULL 0 0
56856 mydb1_testdb 10.3.0.205:53694 mydb1_live_testdb Sleep 4086 NULL 0 0
56857 mydb1_testdb 10.3.0.205:53696 mydb1_live_testdb Query 4086 wsrep: initiating replication for write set (-1) UPDATE modlivehelp_requests SET useragent = 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 0 1
56872 mydb1_testdb 10.3.0.205:53698 mydb1_live_testdb Query 4065 wsrep: initiating replication for write set (-1) UPDATE tbltransientdata SET data=‘2017-10-13 11:15:01’,expires=‘1508026501’ WHERE name='lastCron 0 1
56873 mydb1_testdb 10.3.0.205:53700 mydb1_live_testdb Sleep 4065 NULL 0 0
56915 mydb1_testdb 10.3.0.205:53704 mydb1_live_testdb Execute 3954 wsrep: initiating replication for write set (-1) update tbltask_status set last_run = ?, updated_at = ? where id = ? 0 1
57013 newdb2_testdb 10.3.0.63:54696 newdb2_testdb Query 557 wsrep: initiating replication for write set (-1) insert into tblcustomfieldsvalues (fieldid, relid, value) value (11902, 1704, ‘123456789’) 0 0
58419 db2_testdb 10.3.0.247:43538 db2_testdb Query 1890 wsrep: initiating replication for write set (-1) INSERT INTO ddns_externalcalls_tracking (module, action, item_id, reference, request, s00 58422 newdb2_testdb 10.3.0.230:58806 newdb2_testdb Execute 1889 wsrep: initiating replication for write set (-1) INSERT INTO tbladminlog (adminusername,logintime,lastvisit,ipaddress,sessionid) VALUES ('y00 58465 newdb2_testdb 10.3.0.230:58904 newdb2_testdb Execute 1835 wsrep: initiating replication for write set (-1) INSERT INTO tbladminlog (adminusername,logintime,lastvisit,ipaddress,sessionid) VALUES ('i00 58699 db2_testdb 10.3.0.247:43590 db2_testdb Query 1549 wsrep: initiating replication for write set (-1) INSERT INTO tblactivitylog (date,description,user,userid,ipaddr) VALUES ('20171013115657',00 58763 db2_testdb 10.3.0.66:56243 db2_testdb Query 1491 wsrep: initiating replication for write set (-1) /* ApplicationName=PhpStorm 2017.2.4 */ INSERT INTO ddns_externalcalls_tracking(module, actio 0 0
58766 root localhost mydb1_testdb Query 1432 wsrep: initiating replication for write set (-1) INSERT INTO tblactivitylog (date,description,user,userid,ipaddr) VALUES (‘20171013111426’, 0 0
59520 newdb2_testdb 10.3.0.230:33130 newdb2_testdb Execute 384 wsrep: initiating replication for write set (-1) update tblclients set lastlogin = ?, updated_at = ?, pwresetexpiry = ? where id = ? 0 1
59583 newdb2_testdb 10.3.0.63:55244 newdb2_testdb Sleep 89 NULL 0 0
59584 newdb2_testdb 10.3.0.63:55246 newdb2_testdb Sleep 89 NULL 3 15
59789 root localhost NULL Query 0 starting show processlist 0 0

Using “wsrep_debug=ON” I see:
[…]
2017-10-13T12:24:27.675260+10:00 59856 [Note] WSREP: set_query_id(), assigned new next trx id: 234483
2017-10-13T12:24:27.715554+10:00 59857 [Note] WSREP: set_query_id(), assigned new next trx id: 234486
2017-10-13T12:24:28.150407+10:00 59584 [Note] WSREP: set_query_id(), assigned new next trx id: 234489
2017-10-13T12:24:28.151376+10:00 59584 [Note] WSREP: Cleaning up wsrep-transaction for local query: SELECT a.id, c.email, a.domain, d.id, e.value FROM tblhosting a
LEFT JOIN tblproducts b ON b.id = a.packageid
LEFT JOIN tblclients c ON a.userid = c.id
LEFT JOIN tblcustomfields d ON a.packageid = d.relid and d.type = ‘product’ and d.fieldname = ‘Weebly Site ID’
LEFT JOIN tblcustomfieldsvalues e ON e.fieldid = d.id and e.relid = a.id
WHERE b.gid = 5 AND a.id in (12701,12732)
LIMIT 0, 1000
2017-10-13T12:24:30.680499+10:00 59858 [Note] WSREP: set_query_id(), assigned new next trx id: 234493
2017-10-13T12:24:30.714697+10:00 59859 [Note] WSREP: set_query_id(), assigned new next trx id: 234496
2017-10-13T12:24:33.677191+10:00 59860 [Note] WSREP: set_query_id(), assigned new next trx id: 234499
2017-10-13T12:24:33.716849+10:00 59861 [Note] WSREP: set_query_id(), assigned new next trx id: 234502
2017-10-13T12:24:36.676546+10:00 59862 [Note] WSREP: set_query_id(), assigned new next trx id: 234505
[…]

Seems like nothing is progressing. Do you want to check innodb show status output and findout what is blocking things.

Sure, the locking problem is very easy to replicate using WHMCS 7.1.2, every time I’m loading the admin area I see 2 transactions that are taking tens of seconds to execute:

| InnoDB | |

2017-10-25 10:15:06 0x7fb5680ae700 INNODB MONITOR OUTPUT

Per second averages calculated from the last 24 seconds

BACKGROUND THREAD

srv_master_thread loops: 155 srv_active, 0 srv_shutdown, 2729 srv_idle
srv_master_thread log flush and writes: 2884

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 4520
OS WAIT ARRAY INFO: signal count 4299
RW-shared spins 0, rounds 2654, OS waits 1558
RW-excl spins 0, rounds 1228, OS waits 61
RW-sx spins 24, rounds 720, OS waits 18
Spin rounds per wait: 2654.00 RW-shared, 1228.00 RW-excl, 30.00 RW-sx

TRANSACTIONS

Trx id counter 8980906
Purge done for trx’s n:o < 8980904 undo n:o < 0 state: running but idle
History list length 34
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 421894274614296, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274613088, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274611880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274610672, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274609464, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274608256, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274607048, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274605840, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274604632, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 8980905, ACTIVE 11 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 2248, OS thread handle 140418998040320, query id 10008 192.168.1.205 cheaper_whmcs updating
UPDATE tbladdonmodules SET value=‘a:17:{i:12;i:1376287256;i:11;i:1494835472;i:9;i:1497308070;i:2;i:1494808535;i:10;i:1500273990;i:3;i:1503278454;i:4;i:1493868026;i:14;i:1395814433;i:15;i:1364342130;i:16;i:1494554870;i:17;i:1381364192;i:7;i:1447996150;i:18;i:1406093635;i:19;i:1508886895;i:21;i:1473544536;i:20;i:1508796162;i:22;i:1493860993;}’ WHERE module=‘staffboard’ AND setting=‘lastviewed’
------- TRX HAS BEEN WAITING 11 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6491 page no 3 n bits 160 index GEN_CLUST_INDEX of table cheaper_live_whmcs.tbladdonmodules trx id 8980905 lock_mode X locks rec but not gap waiting

—TRANSACTION 8970244, ACTIVE 2827 sec
5 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 5
MySQL thread id 2, OS thread handle 140419312752384, query id 7043 wsrep: committed write set (2489081)

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
5805 OS file reads, 37808 OS file writes, 9132 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.46 writes/s, 0.37 fsyncs/s

INSERT BUFFER AND ADAPTIVE HASH INDEX

Ibuf: size 1, free list len 12, seg size 14, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 398491, node heap has 24 buffer(s)
Hash table size 398491, node heap has 27 buffer(s)
Hash table size 398491, node heap has 8 buffer(s)
Hash table size 398491, node heap has 21 buffer(s)
Hash table size 398491, node heap has 35 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 4 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
0.75 hash searches/s, 0.37 non-hash searches/s

LOG

Log sequence number 18972910373
Log flushed up to 18972910373
Pages flushed up to 18972910373
Last checkpoint at 18972910364
Max checkpoint age 80826164
Checkpoint age target 78300347
Modified age 0
Checkpoint age 9
0 pending log flushes, 0 pending chkp writes
5877 log i/o’s done, 0.25 log i/o’s/second

BUFFER POOL AND MEMORY

Total large memory allocated 1676673024
Dictionary memory allocated 3511796
Internal hash tables (constant factor + variable factor)
Adaptive hash index 27519552 (25503424 + 2016128)
Page hash 1594504 (buffer pool 0 only)
Dictionary cache 9887652 (6375856 + 3511796)
File system 1140504 (812272 + 328232)
Lock system 3997640 (3985144 + 12496)
Recovery system 0 (0 + 0)
Buffer pool size 98292
Buffer pool size, bytes 1610416128
Free buffers 67973
Database pages 30198
Old database pages 11127
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4808, created 25390, written 29275
0.00 reads/s, 0.00 creates/s, 0.17 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 30198, 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
2 RW transactions active inside InnoDB
Process ID=2116, Main thread ID=140419006433024, state: sleeping
Number of rows inserted 715931, updated 1469, deleted 0, read 1652559
0.00 inserts/s, 0.04 updates/s, 0.00 deletes/s, 3380.15 reads/s

END OF INNODB MONITOR OUTPUT

The 2nd transaction in the next post.

| InnoDB | |

2017-10-25 10:16:34 0x7fb5680ae700 INNODB MONITOR OUTPUT

Per second averages calculated from the last 26 seconds

BACKGROUND THREAD

srv_master_thread loops: 157 srv_active, 0 srv_shutdown, 2814 srv_idle
srv_master_thread log flush and writes: 2971

SEMAPHORES

OS WAIT ARRAY INFO: reservation count 4528
OS WAIT ARRAY INFO: signal count 4307
RW-shared spins 0, rounds 2660, OS waits 1561
RW-excl spins 0, rounds 1258, OS waits 62
RW-sx spins 24, rounds 720, OS waits 18
Spin rounds per wait: 2660.00 RW-shared, 1258.00 RW-excl, 30.00 RW-sx

TRANSACTIONS

Trx id counter 8980913
Purge done for trx’s n:o < 8980911 undo n:o < 0 state: running but idle
History list length 37
LIST OF TRANSACTIONS FOR EACH SESSION:
—TRANSACTION 421894274614296, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274613088, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274611880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274610672, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274609464, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274608256, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274607048, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274605840, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 421894274604632, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
—TRANSACTION 8980912, ACTIVE 44 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 2248, OS thread handle 140418998040320, query id 10336 192.168.1.205 cheaper_whmcs updating
UPDATE tbltransientdata SET data='{“result”:“success”,“checks”:{“success”:[{“name”:“phpSettings”,“type”:“PHP”,“severityLevel”:“notice”,“body”:“Your PHP environment uses a valid timezone.”},{“name”:“installedCurlVersion”,“type”:“PHP”,“severityLevel”:“notice”,“body”:“You currently have version 7.56.0<\/strong> of cURL installed. This version uses a secure cipher list.”},{“name”:“curlSecureTLS”,“type”:“WHMCS”,“severityLevel”:“notice”,“body”:“

cURL reports that it does support Secure TLS 1.1 and 1.2<\/p>”},{“name”:"sessionSup
------- TRX HAS BEEN WAITING 44 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6618 page no 6 n bits 80 index PRIMARY of table cheaper_live_whmcs.tbltransientdata trx id 8980912 lock_mode X locks rec but not gap waiting

—TRANSACTION 8970244, ACTIVE 2915 sec
5 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 5
MySQL thread id 2, OS thread handle 140419312752384, query id 7043 wsrep: committed write set (2489081)

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
5805 OS file reads, 37839 OS file writes, 9150 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, 0 merges
merged operations:
insert 0, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 398491, node heap has 24 buffer(s)
Hash table size 398491, node heap has 27 buffer(s)
Hash table size 398491, node heap has 8 buffer(s)
Hash table size 398491, node heap has 21 buffer(s)
Hash table size 398491, node heap has 35 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 4 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s

LOG

Log sequence number 18972914466
Log flushed up to 18972914466
Pages flushed up to 18972914466
Last checkpoint at 18972914457
Max checkpoint age 80826164
Checkpoint age target 78300347
Modified age 0
Checkpoint age 9
0 pending log flushes, 0 pending chkp writes
5887 log i/o’s done, 0.00 log i/o’s/second

BUFFER POOL AND MEMORY

Total large memory allocated 1676673024
Dictionary memory allocated 3511796
Internal hash tables (constant factor + variable factor)
Adaptive hash index 27519552 (25503424 + 2016128)
Page hash 1594504 (buffer pool 0 only)
Dictionary cache 9887652 (6375856 + 3511796)
File system 1140504 (812272 + 328232)
Lock system 3997640 (3985144 + 12496)
Recovery system 0 (0 + 0)
Buffer pool size 98292
Buffer pool size, bytes 1610416128
Free buffers 67973
Database pages 30198
Old database pages 11127
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 4808, created 25390, written 29293
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: 30198, 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
2 RW transactions active inside InnoDB
Process ID=2116, Main thread ID=140419006433024, state: sleeping
Number of rows inserted 715933, updated 1472, deleted 0, read 1733581
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

END OF INNODB MONITOR OUTPUT

Another deadlock today, same nodes. Might be related to a brief loss of power in the test environment this cluster is running. rpm -qa Percona-XtraDB-Cluster* 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 | InnoDB | | ===================================== 2017-11-15 11:19:24 0x7f5d53fbe700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 36 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 276 srv_active, 0 srv_shutdown, 2670 srv_idle srv_master_thread log flush and writes: 2946 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 1475 OS WAIT ARRAY INFO: signal count 1462 RW-shared spins 0, rounds 1172, OS waits 585 RW-excl spins 0, rounds 570, OS waits 19 RW-sx spins 0, rounds 0, OS waits 0 Spin rounds per wait: 1172.00 RW-shared, 570.00 RW-excl, 0.00 RW-sx ------------ TRANSACTIONS ------------ Trx id counter 9148965 Purge done for trx’s n:o < 9148462 undo n:o < 0 state: running but idle History list length 31 LIST OF TRANSACTIONS FOR EACH SESSION: —TRANSACTION 421516122552848, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122548016, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122545600, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122516608, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122531104, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122543184, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122537144, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122589088, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122587880, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122586672, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122585464, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122584256, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122583048, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122581840, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122580632, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122579424, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122578216, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122577008, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122538352, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122528688, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122523856, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122550432, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122549224, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122574592, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122570968, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122568552, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122566136, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122563720, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122561304, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122558888, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122556472, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122554056, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122551640, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122539560, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122546808, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122544392, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122541976, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122534728, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122532312, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122529896, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122527480, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122525064, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122522648, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122519024, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122514192, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122512984, not started 0 lock struct(s), heap size 1136, 0 row lock(s) —TRANSACTION 421516122511776, not started 0 lock struct(s), heap size 1136, 0 row lock(s) (continues in the next post)

—TRANSACTION 9148963, ACTIVE 22 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 3317, OS thread handle 140038812378880, query id 38646 192.168.1.205 cheaper_whmcs updating
UPDATE tbltransientdata SET data=‘2017-11-15 11:19:02’,expires=‘1510877942’ WHERE name=‘lastCronInvocationTime’
------- TRX HAS BEEN WAITING 22 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6621 page no 4 n bits 88 index name of table cheaper_live_whmcs.tbltransientdata trx id 9148963 lock_mode X locks rec but not gap waiting

—TRANSACTION 9148961, ACTIVE 31 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 3245, OS thread handle 140038885476096, query id 38594 192.168.1.205 cheaper_whmcs updating
UPDATE tbltransientdata SET data=‘2017-11-15 11:18:53’,expires=‘1510706593’ WHERE name=‘lastNotificationDailyCronOutOfSync’
------- TRX HAS BEEN WAITING 31 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6621 page no 4 n bits 88 index name of table cheaper_live_whmcs.tbltransientdata trx id 9148961 lock_mode X locks rec but not gap waiting

—TRANSACTION 9148517, ACTIVE 605 sec
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 2827, OS thread handle 140038810781440, query id 33524 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
UPDATE modlivehelp_requests SET useragent = ‘Mozilla/5.0 (iPad; CPU OS 11_0 like Mac OS X) AppleWebKit/604.1.38 (KHTML, like Gecko) Version/11.0 Mobile/15A372 Safari/604.1’, refresh = ‘2017-11-15 11:09:19’ WHERE id = ‘1013’
—TRANSACTION 9148499, ACTIVE 745 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 2696, OS thread handle 140038886541056, query id 32792 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
INSERT INTO tbladminlog (adminusername,logintime,lastvisit,ipaddres s,sessionid) VALUES (‘admin_cheaper’,‘20171115110659’,‘2017111511065 9’,‘192.168.1.66’,‘474ec96a56fb0a9fcb15632e1553511 2’)
—TRANSACTION 9148478, ACTIVE 991 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 2476, OS thread handle 140038887073536, query id 31702 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
UPDATE tbltransientdata SET data=‘2017-11-15 11:02:53’,expires=‘1510705633’ WHERE name=‘lastNotificationDailyCronOutOfSync’
—TRANSACTION 9148472, ACTIVE 1102 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 2430, OS thread handle 140038888670976, query id 31330 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
UPDATE tbltransientdata SET data=‘2017-11-15 11:01:02’,expires=‘1510876862’ WHERE name=‘lastCronInvocationTime’
—TRANSACTION 9148469, ACTIVE 1114 sec
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 2419, OS thread handle 140038899459840, query id 31262 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
UPDATE modlivehelp_requests SET useragent = ‘Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36’, refresh = ‘2017-11-15 11:00:50’ WHERE id = ‘1072’
—TRANSACTION 9148467, ACTIVE 1118 sec
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 2414, OS thread handle 140039019747072, query id 31230 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
UPDATE modlivehelp_requests SET useragent = ‘Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:57.0) Gecko/20100101 Firefox/57.0’, refresh = ‘2017-11-15 11:00:46’ WHERE id = ‘1069’
—TRANSACTION 9148465, ACTIVE 1127 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 2328, OS thread handle 140038899193600, query id 31186 192.168.1.205 cheaper_whmcs wsrep: initiating replication for write set (-1)
INSERT INTO tblactivitylog (date,description,user,userid,ipaddr) VALUES (‘20171115110037’,‘Cron Job: Suspending Service - Service ID: 2040’,‘System’,‘0’,‘’)

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
29698 OS file reads, 4709 OS file writes, 2461 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, 80 merges
merged operations:
insert 91, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 398491, node heap has 6 buffer(s)
Hash table size 398491, node heap has 3 buffer(s)
Hash table size 398491, node heap has 33 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 23 buffer(s)
Hash table size 398491, node heap has 4 buffer(s)
Hash table size 398491, node heap has 1 buffer(s)
Hash table size 398491, node heap has 32 buffer(s)
0.00 hash searches/s, 0.50 non-hash searches/s

LOG

Log sequence number 19319919024
Log flushed up to 19319919024
Pages flushed up to 19319919024
Last checkpoint at 19319919015
Max checkpoint age 80826164
Checkpoint age target 78300347
Modified age 0
Checkpoint age 9
0 pending log flushes, 0 pending chkp writes
1834 log i/o’s done, 0.00 log i/o’s/second

BUFFER POOL AND MEMORY

Total large memory allocated 1676673024
Dictionary memory allocated 1851224
Internal hash tables (constant factor + variable factor)
Adaptive hash index 27224640 (25503424 + 1721216)
Page hash 1594504 (buffer pool 0 only)
Dictionary cache 8227080 (6375856 + 1851224)
File system 1141928 (812272 + 329656)
Lock system 4048760 (3985144 + 63616)
Recovery system 0 (0 + 0)
Buffer pool size 98292
Buffer pool size, bytes 1610416128
Free buffers 68622
Database pages 29567
Old database pages 10934
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 29465, created 102, written 2660
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 29567, 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
9 RW transactions active inside InnoDB
Process ID=12778, Main thread ID=140040915093248, state: sleeping
Number of rows inserted 4314, updated 434, deleted 0, read 933014
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.81 reads/s

END OF INNODB MONITOR OUTPUT

… and another deadlock, same cluster, one of those days I guess :slight_smile:

| 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:o < 0 undo n:o < 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.168.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”,“languageCod e”:“ar”,“countryCode”:“AR”,“localisedName”:“\u062 7\u0644\u0639\u0631\u0628\u064a\u0629”},{“lo cale”:“az_AZ”,“language”:“azerbaijani”,“languageCo de”:“az”,“countryCode”:“AZ”,“localisedName”:“Azerb 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