Cluster hang with wsrep: initiating replication for write set

[Edward_Hibbert]

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?

[Edward_Hibbert]

Saw another occurrence of this. Anyone?

[burnley]

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
[…]

[krunalbauskar]

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

[burnley]

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.

[burnley]

| 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

[burnley]

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)

[burnley]

—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

[burnley]

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

| 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