# Getting latency in write operations under heavy load
**URL:** https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345
**Category:** Percona XtraDB Cluster 5.x
**Tags:** percona
**Created:** [April 22, 2022, 12:24pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345 "2022-04-22T12:24:12Z")
**Posts on this page:** 20
**Page:** 1
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 12:24pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/1 "2022-04-22T12:24:12Z")
Hi, I am using Percona Xtradb Cluster 5.7.
We have 3 node server on GCP with 70cores & 560 GB RAM on each node.
What we see is during heavy load on server, we see Insert/update queries taking more time, some time it goes above 1 min.
We are using ProxySQL to do load balancing, with all write operations going on single node, we don’t write on multiple nodes.
Configuration on each node is as below
[client]
port = 3306
socket=/data/mysql/mysql.sock
[mysqld]
# GENERAL
user = mysql
default-storage-engine = InnoDB
socket = /data/mysql/mysql.sock
pid-file = /data/mysql/mysql.pid
server-id = 1
skip-name-resolve
# MyISAM
key-buffer-size = 32M
# SAFETY
max-allowed-packet = 2048M
max-connect-errors = 1000000
sql\_mode = NO\_ENGINE\_SUBSTITUTION
# DATA STORAGE
datadir = /data/mysql/
# BINARY LOGGING
log-bin = /data/mysql/mysql-bin
expire-logs-days = 7
sync-binlog = 0
log\_slave\_updates
#sync-binlog is changed to 0 from 1
# CACHES AND LIMITS
tmp-table-size = 32M
max-heap-table-size = 32M
query-cache-type = 0
query-cache-size = 0
max-connections = 6000
thread-cache-size = 150
open-files-limit = 1024000
table-definition-cache = 5120
table-open-cache = 10240
# INNODB
innodb-flush-method = O\_DIRECT
innodb-log-files-in-group = 4
innodb-log-file-size = 5G
innodb-file-per-table = 1
innodb-buffer-pool-size = 350G
innodb\_buffer\_pool\_chunk\_size = 256M
innodb\_io\_capacity = 20000
innodb\_io\_capacity\_max = 80000
innodb\_read\_io\_threads = 12
innodb\_thread\_concurrency = 0
innodb\_write\_io\_threads = 12
innodb\_flush\_log\_at\_trx\_commit = 2
# LOGGING
log-error = /data/mysql/mysql-error.log
log-queries-not-using-indexes = 0
slow-query-log = 0
slow-query-log-file = /data/mysql/mysql-slow.log
group\_concat\_max\_len = 10485760
# WSREP configuration
wsrep\_provider=/usr/lib64/galera3/libgalera\_smm.so
wsrep\_provider\_options=“gcache.size=15G;gcs.fc\_limit=600; gcs.fc\_master\_slave=YES; gcs.fc\_factor=1.0”
[mysqld]
# In order for Galera to work correctly binlog format should be ROW
binlog\_format=ROW
# MyISAM storage engine has only experimental support
default\_storage\_engine=InnoDB
# Slave thread to use
wsrep\_slave\_threads= 70
wsrep\_certification\_rules=OPTIMIZED
wsrep\_log\_conflicts
# This changes how InnoDB autoincrement locks are managed and is a requirement for Galera
innodb\_autoinc\_lock\_mode=2
# SST method
wsrep\_sst\_method=xtrabackup-v2
# Below is the wsrep status on node3 (master)
±---------------------------------±---------------+
| Variable\_name | Value |
±---------------------------------±---------------+
| wsrep\_flow\_control\_paused\_ns | 678859607091 |
| wsrep\_flow\_control\_paused | 0.040823 |
| wsrep\_flow\_control\_sent | 0 |
| wsrep\_flow\_control\_recv | 1352 |
| wsrep\_flow\_control\_interval | [1200, 1200] |
| wsrep\_flow\_control\_interval\_low | 1200 |
| wsrep\_flow\_control\_interval\_high | 1200 |
| wsrep\_flow\_control\_status | OFF |
±---------------------------------±---------------+
8 rows in set (0.00 sec)
±---------------------------±-------------------------------------+
| Variable\_name | Value |
±---------------------------±-------------------------------------+
| wsrep\_local\_state\_uuid | 4ac77c71-4d37-11e8-a591-26cd1b1f321b |
| wsrep\_local\_commits | 3677445 |
| wsrep\_local\_cert\_failures | 0 |
| wsrep\_local\_replays | 0 |
| wsrep\_local\_send\_queue | 0 |
| wsrep\_local\_send\_queue\_max | 866 |
| wsrep\_local\_send\_queue\_min | 0 |
| wsrep\_local\_send\_queue\_avg | 1.161227 |
| wsrep\_local\_recv\_queue | 0 |
| wsrep\_local\_recv\_queue\_max | 2 |
| wsrep\_local\_recv\_queue\_min | 0 |
| wsrep\_local\_recv\_queue\_avg | 0.002228 |
| wsrep\_local\_cached\_downto | 9412001488 |
| wsrep\_local\_state | 4 |
| wsrep\_local\_state\_comment | Synced |
| wsrep\_local\_bf\_aborts | 0 |
| wsrep\_local\_index | 1 |
±---------------------------±-------------------------------------+
17 rows in set (0.01 sec)
±------------------------±------+
| Variable\_name | Value |
±------------------------±------+
| Threadpool\_idle\_threads | 0 |
| Threadpool\_threads | 0 |
| Threads\_cached | 20 |
| Threads\_connected | 2951 |
| Threads\_created | 3032 |
| Threads\_running | 18 |
±------------------------±------+
6 rows in set (0.00 sec)
±-------------------------±----------+
| Variable\_name | Value |
±-------------------------±----------+
| wsrep\_cert\_deps\_distance | 80.328236 |
±-------------------------±----------+
1 row in set (0.00 sec)
# Below is the wsrep status on node2( slave)
±---------------------------------±---------------+
| Variable\_name | Value |
±---------------------------------±---------------+
| wsrep\_flow\_control\_paused\_ns | 703714065012 |
| wsrep\_flow\_control\_paused | 0.040810 |
| wsrep\_flow\_control\_sent | 529 |
| wsrep\_flow\_control\_recv | 1352 |
| wsrep\_flow\_control\_interval | [1200, 1200] |
| wsrep\_flow\_control\_interval\_low | 1200 |
| wsrep\_flow\_control\_interval\_high | 1200 |
| wsrep\_flow\_control\_status | OFF |
±---------------------------------±---------------+
8 rows in set (0.00 sec)
±---------------------------±-------------------------------------+
| Variable\_name | Value |
±---------------------------±-------------------------------------+
| wsrep\_local\_state\_uuid | 4ac77c71-4d37-11e8-a591-26cd1b1f321b |
| wsrep\_local\_commits | 23492 |
| wsrep\_local\_cert\_failures | 0 |
| wsrep\_local\_replays | 0 |
| wsrep\_local\_send\_queue | 0 |
| wsrep\_local\_send\_queue\_max | 1 |
| wsrep\_local\_send\_queue\_min | 0 |
| wsrep\_local\_send\_queue\_avg | 0.000000 |
| wsrep\_local\_recv\_queue | 0 |
| wsrep\_local\_recv\_queue\_max | 1231 |
| wsrep\_local\_recv\_queue\_min | 0 |
| wsrep\_local\_recv\_queue\_avg | 27.537734 |
| wsrep\_local\_cached\_downto | 9412001742 |
| wsrep\_local\_state | 4 |
| wsrep\_local\_state\_comment | Synced |
| wsrep\_local\_bf\_aborts | 0 |
| wsrep\_local\_index | 2 |
±---------------------------±-------------------------------------+
17 rows in set (0.00 sec)
±------------------------±------+
| Variable\_name | Value |
±------------------------±------+
| Threadpool\_idle\_threads | 0 |
| Threadpool\_threads | 0 |
| Threads\_cached | 150 |
| Threads\_connected | 36 |
| Threads\_created | 749 |
| Threads\_running | 1 |
±------------------------±------+
6 rows in set (0.00 sec)
±-------------------------±----------+
| Variable\_name | Value |
±-------------------------±----------+
| wsrep\_cert\_deps\_distance | 80.322232 |
±-------------------------±----------+
1 row in set (0.00 sec)
# Below is the status of wsrep on node1 (slave)
±---------------------------------±---------------+
| Variable\_name | Value |
±---------------------------------±---------------+
| wsrep\_flow\_control\_paused\_ns | 679410518302 |
| wsrep\_flow\_control\_paused | 0.040840 |
| wsrep\_flow\_control\_sent | 824 |
| wsrep\_flow\_control\_recv | 1358 |
| wsrep\_flow\_control\_interval | [1200, 1200] |
| wsrep\_flow\_control\_interval\_low | 1200 |
| wsrep\_flow\_control\_interval\_high | 1200 |
| wsrep\_flow\_control\_status | OFF |
| wsrep\_flow\_control\_active | false |
| wsrep\_flow\_control\_requested | false |
±---------------------------------±---------------+
10 rows in set (0.00 sec)
±---------------------------±-------------------------------------+
| Variable\_name | Value |
±---------------------------±-------------------------------------+
| wsrep\_local\_state\_uuid | 4ac77c71-4d37-11e8-a591-26cd1b1f321b |
| wsrep\_local\_commits | 0 |
| wsrep\_local\_cert\_failures | 0 |
| wsrep\_local\_replays | 0 |
| wsrep\_local\_send\_queue | 0 |
| wsrep\_local\_send\_queue\_max | 1 |
| wsrep\_local\_send\_queue\_min | 0 |
| wsrep\_local\_send\_queue\_avg | 0.000000 |
| wsrep\_local\_recv\_queue | 1191 |
| wsrep\_local\_recv\_queue\_max | 1228 |
| wsrep\_local\_recv\_queue\_min | 0 |
| wsrep\_local\_recv\_queue\_avg | 35.918619 |
| wsrep\_local\_cached\_downto | 9412001742 |
| wsrep\_local\_state | 4 |
| wsrep\_local\_state\_comment | Synced |
| wsrep\_local\_bf\_aborts | 0 |
| wsrep\_local\_index | 0 |
±---------------------------±-------------------------------------+
17 rows in set (0.00 sec)
±------------------------±------+
| Variable\_name | Value |
±------------------------±------+
| Threadpool\_idle\_threads | 0 |
| Threadpool\_threads | 0 |
| Threads\_cached | 28 |
| Threads\_connected | 46 |
| Threads\_created | 74 |
| Threads\_running | 1 |
±------------------------±------+
6 rows in set (0.00 sec)
±-------------------------±----------+
| Variable\_name | Value |
±-------------------------±----------+
| wsrep\_cert\_deps\_distance | 80.309898 |
±-------------------------±----------+
1 row in set (0.00 sec)
Can someone help on what is going wrong here?
---
### Author:  [@Wayne\_Leutwyler](https://forums.percona.com/u/Wayne_Leutwyler)
#### Post date: [April 22, 2022, 1:27pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/2 "2022-04-22T13:27:08Z")
I have seen problems with the wsrep\_slave\_threads being to high to cause issues. Check out this link: [Setting Parallel Slave Threads — Galera Cluster Documentation](https://galeracluster.com/library/kb/parallel-applier-threads.html). What does you show processlist look like when you are seeing the 1 min response time?
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 1:49pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/3 "2022-04-22T13:49:32Z")
Hi,
I tried setting ‘wsrep\_slave\_threads’ value to 8, 16, 32, 70, 80, 120.
All the times same issue was faced.
Under heavy load process list shows above 4K connections & all wsrep threads writing
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 1:51pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/4 "2022-04-22T13:51:04Z")
Also, My master node has CPU usage of around 70% under heavy load and other 2 slave servers has CPU load of 1% or 2%
---
### Author:  [@Wayne\_Leutwyler](https://forums.percona.com/u/Wayne_Leutwyler)
#### Post date: [April 22, 2022, 1:53pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/5 "2022-04-22T13:53:52Z")
Are your cluster nodes in different locations. If so look at network latency. Also check to see if you are facing disk I/O issues. How does ProxySQL look under the heavy loads?
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 2:00pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/6 "2022-04-22T14:00:45Z")
All nodes are in same location, network latency is \<1ms.
Not facing disk I/O issues,
ProxySQL looks normal no wired behaviour in terms of CPU/RAM
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 2:12pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/7 "2022-04-22T14:12:41Z")
Does difference in mysql version creates issue
Master node: **mysql Ver 14.14 Distrib 5.7.30-33, for Linux (x86\_64) using 6.2**
Slave1: **mysql Ver 14.14 Distrib 5.7.36-39, for Linux (x86\_64) using 6.2**
Slave2: **mysql Ver 14.14 Distrib 5.7.24-26, for Linux (x86\_64) using 6.2**
---
### Author:  [@Wayne\_Leutwyler](https://forums.percona.com/u/Wayne_Leutwyler)
#### Post date: [April 22, 2022, 2:22pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/8 "2022-04-22T14:22:23Z")
So for me that is not best practice. All nodes should be on same version. Couple more things we have been focused on MySQL settings, yet we have not looked at the database it self. Check to see that all you tables have primary keys, also review you slow query log.
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 2:41pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/9 "2022-04-22T14:41:39Z")
We have primary keys in all tables. Also we have tables with composite primary keys.
We have multi tenant application and for each tenant we have different databases.
For slow query does Query Time listed in logs, are the query time after replication or before replication
---
### Author:  [@Wayne\_Leutwyler](https://forums.percona.com/u/Wayne_Leutwyler)
#### Post date: [April 22, 2022, 2:58pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/10 "2022-04-22T14:58:28Z")
Before you do anything else, I would get all your servers on the same version. Then we can continue to try and solve the issue if it continues.
---
### Author:  [@matthewb](https://forums.percona.com/u/matthewb)
#### Post date: [April 22, 2022, 3:25pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/11 "2022-04-22T15:25:45Z")
> [@dipesh.patel](#):
>
> For slow query does Query Time listed in logs, are the query time after replication or before replication
Query time in the slow log does not include replication. This is especially true for SELECTs which don’t replicate. Since you have the query log enabled, what do the stats say for where the time is being spent? Do you have each node monitored by PMM? When your primary node is at 70%, what do you see with regards to disk and network? Is all 70% of that consumed by MySQL, or do you have lots of await%?
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 4:01pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/12 "2022-04-22T16:01:12Z")
We have PMM installed before couple of hours
As we are talking we are seeing slow write queries, attached is the screenshot from PMM
Let me know if you need anything else, i am happy to provide
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 22, 2022, 9:27pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/13 "2022-04-22T21:27:15Z")
@matthewb Slow log is majorly coming for INSERT/UPDATE/DELETE statements, e.g is as below
#Time: 2022-04-22T21:19:15.052186Z
#User@Host: XXXXXXX @ [10.32.14.19] Id: 23239
#Schema: XXXXXX Last\_errno: 0 Killed: 0
#Query\_time: 10.107317 Lock\_time: 0.000171 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1
#Bytes\_sent: 52
use XXXXX;
SET timestamp=1650662355;
UPDATE emails SET `emailMode` = ‘opened’ WHERE id=‘2540993’;
#Time: 2022-04-22T21:19:15.052269Z
#User@Host: XXXXXX @ [10.32.14.19] Id: 22299
#Schema: XXXXXX Last\_errno: 0 Killed: 0
#Query\_time: 10.020400 Lock\_time: 0.000307 Rows\_sent: 0 Rows\_examined: 0 Rows\_affected: 1
#Bytes\_sent: 19
use XXXXX;
SET timestamp=1650662355;
INSERT INTO `microsoft_synced_email_changes` (`id`,`hostname`,`accountId`,`owner`,`emailId`,`event`,`processingStatus`,`retryCount`,`enqueuedAt`) VALUES (DEFAULT,‘XXXXX’,‘XXXXXXX’,25,‘XXXXXXXX’,‘Updated’,‘InQueue’,0,1650662345);
#Time: 2022-04-22T21:19:15.052395Z
#User@Host: XXXXXX @ [10.32.0.23] Id: 23240
#Schema: XXXXXX Last\_errno: 1265 Killed: 0
#Query\_time: 10.001954 Lock\_time: 0.000049 Rows\_sent: 0 Rows\_examined: 1 Rows\_affected: 1
#Bytes\_sent: 52
use XXXXXX;
SET timestamp=1650662355;
UPDATE emails SET `emailMode` = ‘sending’ WHERE id = 7406615;
If there are lot of such queries. Interesting thing is that even query with where condition on primary key is taking 10s and more.
### One observation from my side
What i have observed is that, during SST when only one node is Synced/Primary and other 2 are in Donor and Joiner state, I don’t see slow logs for INSERT/UPDATE/DELETE statements. i.e when certification process is not happening between nodes
---
### Author:  [@matthewb](https://forums.percona.com/u/matthewb)
#### Post date: [April 23, 2022, 7:55pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/14 "2022-04-23T19:55:13Z")
> [@dipesh.patel](#):
>
> during SST when only one node is Synced/Primary and other 2 are in Donor and Joiner state, I don’t see slow logs for INSERT/UPDATE/DELETE statements
That makes perfect sense. If there’s only 1 node in the cluster, then there’s nothing to replicate and thus things process very fast.
When you took that PMM screenshot, were you seeing slow writes at that time? What about flow control during these slow events?
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 25, 2022, 7:36am UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/15 "2022-04-25T07:36:05Z")
Hi @matthewb
Here is the PMM screenshot of Galera Node Compare, during the period when we see such behaviour. Here at 11:31 AM we saw latency of more than 10s in write queries.
What is see is when the replication queue goes high it creates a problem.
FYI
We have updated all our MySQL nodes to 5.7.36-39-57.
Also as suggested in one comment, we updated the wsrep\_slave\_threads to 16 on all the servers.
We have changed the servers to n2-highmem-80 of GCP which is (80 cores, 629GB RAM). Changed the disk to Extreme Persistent disk with 10000 IOPS (dedicated).
# Below is the screenshot of Galera Node Compare
# Below is the screenshot of InnoDB Details of master node on which write is happening
Let me know if you need any other details
---
### Author:  [@matthewb](https://forums.percona.com/u/matthewb)
#### Post date: [April 25, 2022, 5:25pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/16 "2022-04-25T17:25:44Z")
> [@dipesh.patel](#):
>
> What is see is when the replication queue goes high it creates a problem.
Yes, this is known as “flow control.” [Managing Flow Control — Galera Cluster Documentation](https://galeracluster.com/library/documentation/managing-fc.html)
I can see on the graphs flow control kicking in every now and then. You might want to adjust `gc.fc_limit` to something higher than the default. Try using 300 or 400, and set gcs.fc\_factor=0.9
I’m also seeing lots of InnoDB Transaction History. This is usually caused by long running queries. Make sure your queries are short as possible and don’t hold open transactions. I would also recommend `innodb_flush_log_at_trx_commit=0`
Beyond this, you might benefit from a [Percona Database Consulting - Percona](https://www.percona.com/services/mysql-consulting/mysql-health-audit) that can go into more details.
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 25, 2022, 5:31pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/17 "2022-04-25T17:31:56Z")
@matthewb Let me set the params as you suggested and see, does it improve performance.
Does increasing wsrep\_slave\_threads will help?
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 25, 2022, 5:44pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/18 "2022-04-25T17:44:13Z")
@matthewb Flow control is already at higher value as below
wsrep\_flow\_control\_interval | [624, 693]
wsrep\_flow\_control\_interval\_low | 624
wsrep\_flow\_control\_interval\_high | 693
And i have already signed the Advance Support Contract with Percona Today
---
### Author:  [@dipesh.patel](https://forums.percona.com/u/dipesh.patel)
#### Post date: [April 25, 2022, 7:02pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/19 "2022-04-25T19:02:27Z")
@matthewb After setting these params still getting issue
---
### Author:  [@matthewb](https://forums.percona.com/u/matthewb)
#### Post date: [April 27, 2022, 3:25pm UTC](https://forums.percona.com/t/getting-latency-in-write-operations-under-heavy-load/15345/20 "2022-04-27T15:25:50Z")
What does PMM show on one of the reader nodes during these scenarios? Pull up CPU/Disk during these events. There is _something_ which is causing these nodes to lag behind which is then causing them to issue flow control messages which causes the writer to slow down.