8.0 vs 5.7 INSERTs Performance issues

MySQL & MariaDB Percona XtraDB Cluster 5.x
1

Hi,

Me and my team are noticing quite a significant performance degradation from Percona 5.7 to 8.0 in terms of INSERTs/UPDATEs. Here is a test I’m using (straight from bash):

  1. Create a test DB and a test table
mysql -sN -u root -e "DROP DATABASE IF EXISTS test; CREATE DATABASE test;"
mysql -sN -u root test -e "CREATE TABLE test (signature varbinary(767) NOT NULL DEFAULT '', id bigint NOT NULL AUTO_INCREMENT, count int NOT NULL, PRIMARY KEY (id), UNIQUE KEY idx_signature (signature)) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb3"
  1. Run 10000 samples of INSERTs with increasing signature 1-10000. Then sum all “update” results from the profiling and divide them to the samples amount (10000) to get the average processing (bash):

(single node Percona Cluster 8.0.29)

for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-12 09:36:45 0.000084
  1. The first loop uses only the INSERTs. The second run on the same loop is to trigger ON DUPLICATE KEY UPDATE:
for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-12 09:38:32 0.000120
  1. The same on single node Percona Cluster 5.7.39 - INSERTs:
for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-12 09:42:36 0.000051
  1. ON DUPLICATE KEY UPDATE:
for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-12 09:44:06 0.000086

There is about 0.000030s degradation in the performance. We have tried a lot of different options - to disable/lower fsyncs, different flush methods, disable-log-bin, but none helped.

In the InnoDB engine statuses we see a significant (double) increase of the file reads/writes:
5.7.39:

641 OS file reads, 20966 OS file writes, 20392 OS fsyncs
0.22 reads/s, 16384 avg bytes/read, 240.10 writes/s, 219.65 fsyncs/s

8.0.29:

1602 OS file reads, 43182 OS file writes, 24269 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 158.70 writes/s, 47.10 fsyncs/s

Has anyone tackled this issue? Any suggestions are warmly welcomed.

Thanks,
Avgustin

1 Like
2

Hi @avgustin , welcome to the Percona forums!

First off, what a great test case you’ve developed :slight_smile: Offhand I don’t see a quick explanation, however do be aware that across major releases the lines of code for the query to pass increases, and so you can expect that single-query performance to in fact degrade. Where the effort by upstream MySQL + Percona is in the concurrency, for example in 5.5 you’d be lucky to get a few hundred concurrent queries, whereas in 8.0 you’ll be in the thousands, thanks to the development efforts of the engineers.

In terms of deciphering what is going on in your test case - may I suggest that you deploy PMM and attach it to these two instances? In particular I would encourage you to also use slow log so that we can review individual query response time, and where any bottlenecks/waits are occurring. With PMM you’ll get historical views of performance during the tests. I would want to see the rate of

A couple of other things to isolate the issue here:

  1. trying starting PXC with wsrep disabled. Of course you’ll need wsrep in prod but this helps to identify local write throughput. If you see then that the performance is close, then lets re-enable wsrep and examine the performance of the cluster as a whole by examining the PMM PXC graphs.
  2. Don’t enable profiling, that is additional overhead, and unlikely something you’d be doing in Production on a regular basis
2 Likes
3

Thanks a lot for the suggestions Michael,

Here is what I did, on default configs for both 8.0.29 and 5.7.39 I added the following options to disable wsrep and enable slow query log with threshold of 0:

wsrep_on=OFF
slow_query_log=ON
slow_query_log_file=/var/log/mysqld-slow.log
long_query_time=0

Then run the tests without profiling, separated the slow logs for INSERTs and UPDATEs, and calculated the averages:

haqa1 - RHEL8.5/PXC 8.0.29
haqa2 - RHEL8.5/PXC 5.7.39

root@haqa1~# for c in $(seq 1 10000); do mysql -sN -u root test -e "INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;"; done
root@haqa1~# cp /var/log/mysqld-slow.log /var/log/mysqld-slow.log-inserts
root@haqa1~# echo > /var/log/mysqld-slow.log
root@haqa1~# for c in $(seq 1 10000); do mysql -sN -u root test -e "INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;"; done
root@haqa1~# cp /var/log/mysqld-slow.log /var/log/mysqld-slow.log-updates

root@haqa1~# grep INSERT -B2 /var/log/mysqld-slow.log-updates|grep Query_time|wc -l
10000
root@haqa1~# grep INSERT -B2 /var/log/mysqld-slow.log-inserts|grep Query_time|wc -l
10000

root@haqa1~# grep INSERT -B2 /var/log/mysqld-slow.log-inserts|grep Query_time|awk 'BEGIN{sum=0;cnt=0;}{sum+=$3;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-15 06:07:38 0.000637

root@haqa1~# grep INSERT -B2 /var/log/mysqld-slow.log-updates|grep Query_time|awk 'BEGIN{sum=0;cnt=0;}{sum+=$3;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-15 06:07:44 0.000791

root@haqa2~# for c in $(seq 1 10000); do mysql -sN -u root test -e "INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;"; done
root@haqa2~# cp /var/log/mysqld-slow.log /var/log/mysqld-slow.log-inserts
root@haqa2~# echo > /var/log/mysqld-slow.log
root@haqa2~# for c in $(seq 1 10000); do mysql -sN -u root test -e "INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;"; done
root@haqa2~# cp /var/log/mysqld-slow.log /var/log/mysqld-slow.log-updates

root@haqa2~# grep INSERT -B2 /var/log/mysqld-slow.log-inserts|grep Query_time|wc -l
10000
root@haqa2~# grep INSERT -B2 /var/log/mysqld-slow.log-updates|grep Query_time|wc -l
10000

root@haqa2~# grep INSERT -B2 /var/log/mysqld-slow.log-inserts|grep Query_time|awk 'BEGIN{sum=0;cnt=0;}{sum+=$3;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-15 08:58:10 0.000344

root@haqa2~# grep INSERT -B2 /var/log/mysqld-slow.log-updates|grep Query_time|awk 'BEGIN{sum=0;cnt=0;}{sum+=$3;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-15 08:58:19 0.000401

The results are confirming what was seen before. May be even worse as it looks like double the amount of time here.

I created PMM Snapshot which is available here:

https://snapshots-g710.percona.com/graph/dashboard/snapshot/9uN73yrWoJE8AEiVoM1fw5A944l5Z1tg

It consists of the same INSERT/UPDATE tests running once with 10 000 samples, then with 100 000 samples.

Regards,
Avgustin

1 Like
4

Hi @avgustin
Thank you for sharing your results. We have also recently received this report regarding performance degradation in 8.0.30 due to an increase in semafore waits. Does it apply in your case?
https://jira.percona.com/browse/PS-8406

1 Like
5

Hi @Michael_Coburn,

I’m not sure it applies here as my results are the same in 8.0.28 and 8.0.29. But what I just found after comparing pure MySQL 8.0.26 vs 5.7.39 is that disable-log-bin actually works there, while on PXC it is either ignored or it doesn’t have the same effect.

So I went for some workaround option to do the same on Percona and found binlog-ignore-db. When set in this test as:

binlog-ignore-db=test

the results on PXC 8.0.29 become as follows:

root@haqa1~# mysql -sN -u root -e "DROP DATABASE IF EXISTS test; CREATE DATABASE test;"
root@haqa1~# mysql -sN -u root test -e "CREATE TABLE test (signature varbinary(767) NOT NULL DEFAULT '', id bigint NOT NULL AUTO_INCREMENT, count int NOT NULL, PRIMARY KEY (id), UNIQUE KEY idx_signature (signature)) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb3"
root@haqa1~# for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-21 07:26:25 0.000050
root@haqa1~# for c in $(seq 1 10000); do     mysql -sN -u root test -e "set global profiling_history_size=100;set profiling=1;INSERT INTO test VALUES ('signature$c', 0, 1) ON DUPLICATE KEY UPDATE count = count + 1;set profiling=0;SHOW PROFILE FOR QUERY 1"; done | grep update | awk 'BEGIN{sum=0;cnt=0;}{sum+=$2;cnt++;}END{printf(strftime("%Y-%m-%d %H:%M:%S")" %.6f\n", (sum/cnt))}'
2022-09-21 07:28:09 0.000100

Do you know if disable-log-bin has some other function in PXC?

2 Likes
6

Hi @avgustin

PXC does not need the binary log enabled for normal operations. Keep in mind that PXC tracks changes through the galera writeset cache which does in fact use the binlog row format, but that is stored in a separate file (not the mysql-bin files!)

So you should be able to specify the following in order to disable the binary log:

log_bin=OFF
1 Like
7

Hi @Michael_Coburn

I’m sorry to report that this is also acting as disable-log-bin on PXC - ignored or no effect of it. The only difference so far is with binlog-ignore-db.

1 Like