[MDEV-25639] Performance degradation - Select query Statistics phase exponential performance degradation Created: 2021-05-10  Updated: 2021-05-11

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.7, 10.5.9, 10.6.0
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Paul Veldema Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: innodb, performance, regression
Environment:

Debian 10, Both on VM's and Baremetal installs. Tried on fast SSD storage and spinning Disks. Also tried on Machines with memory > diskspace.

Attachments: Text File mariadb_10.5.show_variables.txt    

 Description   

On our production systems we deployed MariaDB 10.5.9 after extensive testing without problems. However sometimes when the Rubber meets the road you still encounter something that forces you to revert to the previous version (10.1) where the problem did not occur.

The problem is 100% reproducible and took it some time to create a test case without our proprietary data structures. I will do some additional testing on other versions also to see which version introduced the regression also and add that to the affected version list.

Here the simplified problem case:

Table definition:

DROP DATABASE IF EXISTS `testcase`;
 
CREATE DATABASE `testcase`;
 
 
 
USE `testcase`;
 
 
 
CREATE TABLE `contacts` (
 
  `systemid` int(11) NOT NULL AUTO_INCREMENT,
 
  `inactive` tinyint(1) NOT NULL,
 
  `company` varchar(255) DEFAULT NULL,
 
  `account` varchar(10) DEFAULT NULL,
 
  `ostreet` varchar(60) DEFAULT NULL,
 
  `ostreet2` varchar(60) DEFAULT NULL,
 
  `ocountry` varchar(35) DEFAULT NULL,
 
  `ocity` varchar(35) DEFAULT NULL,
 
  `ohouseno` varchar(15) DEFAULT NULL,
 
  `ohousenoext` varchar(7) DEFAULT NULL,
 
  `mstreet` varchar(60) DEFAULT NULL,
 
  `mstreet2` varchar(60) DEFAULT NULL,
 
  `mcountry` varchar(35) DEFAULT NULL,
 
  `mcity` varchar(35) DEFAULT NULL,
 
  `mhouseno` varchar(15) DEFAULT NULL,
 
  `mhousenoext` varchar(7) DEFAULT NULL,
 
  `tel1` varchar(80) DEFAULT NULL,
 
  `tel2` varchar(80) DEFAULT NULL,
 
  `tel3` varchar(80) DEFAULT NULL,
 
  `tel4` varchar(80) DEFAULT NULL,
 
  `mobile` varchar(80) DEFAULT NULL,
 
  `fax` varchar(80) DEFAULT NULL,
 
  `notes` longtext DEFAULT NULL,
 
  `hstreet` varchar(60) DEFAULT NULL,
 
  `hstreet2` varchar(60) DEFAULT NULL,
 
  `hcountry` varchar(35) DEFAULT NULL,
 
  `hcity` varchar(35) DEFAULT NULL,
 
  `hhouseno` varchar(15) DEFAULT NULL,
 
  `hhousenoext` varchar(7) DEFAULT NULL,
 
  `ozipcode` varchar(15) DEFAULT NULL,
 
  `mzipcode` varchar(15) DEFAULT NULL,
 
  `hzipcode` varchar(15) DEFAULT NULL,
 
  `birthday` date DEFAULT NULL,
 
  `initials` varchar(20) DEFAULT NULL,
 
  `middlename` varchar(20) DEFAULT NULL,
 
  `title` varchar(70) DEFAULT NULL,
 
  `lastname` varchar(100) DEFAULT NULL,
 
  `relationtype` varchar(128) DEFAULT NULL,
 
  `relationtypefunction` varchar(128) DEFAULT NULL,
 
  `email` varchar(255) DEFAULT NULL,
 
  `nationality` varchar(50) DEFAULT NULL,
 
  `saluation` varchar(80) DEFAULT NULL,
 
  `surtitle` varchar(15) DEFAULT NULL,
 
  `lastupdate` datetime DEFAULT NULL,
 
  `datein` datetime NOT NULL,
 
  `firstname` varchar(100) DEFAULT NULL,
 
  `hcity2` varchar(35) DEFAULT NULL,
 
  `mailing1st` int(11) DEFAULT NULL,
 
  `partsameadr` int(11) DEFAULT NULL,
 
  `partcode` varchar(10) DEFAULT NULL,
 
  `christianname` varchar(60) DEFAULT NULL,
 
  `telintern` varchar(80) DEFAULT NULL,
 
  PRIMARY KEY (`systemid`),
 
  KEY `groupby_relationtype` (`relationtype`),
 
  KEY `groupby_relationtype_saluation` (`relationtype`,`saluation`),
 
  KEY `relationtype_lastname` (`relationtype`,`lastname`),
 
  KEY `partcode` (`partcode`),
 
  KEY `ozipcode` (`ozipcode`),
 
  KEY `hzipcode_hhouseno` (`hzipcode`,`hhouseno`),
 
  KEY `company` (`company`),
 
  KEY `mcity` (`mcity`),
 
  KEY `lastname` (`lastname`),
 
  KEY `firstname` (`firstname`),
 
  KEY `email` (`email`),
 
  KEY `mobile` (`mobile`),
 
  KEY `tel1` (`tel1`),
 
  KEY `tel2` (`tel2`),
 
  KEY `tel3` (`tel3`),
 
  KEY `tel4` (`tel4`),
 
  KEY `telintern` (`telintern`)
 
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

Generate about 80000 rows of generic test data for this table, make sure there are e-mail addresses in the rows and that more than a few of the fields where there are also indexes on have data in there.

Script to create the problematic queries

#!/bin/bash
 
 
 
MINVALUE=5000
 
LIMITVALUE=20000
 
#LIMITVALUE=10000
 
#LIMITVALUE=200
 
 
 
set -x
 
# The 'select systemid from'  to get a list of systemid's simulates a fulltext search as a source of the systemid list
 
SYSTEMIDLIST="
 
 `echo "select systemid from testcase.contacts where systemid > ${MINVALUE} LIMIT ${LIMITVALUE}" | mysql -h localhost -N | xargs | sed 's/ /, /g'`
 
"
 
 
 
echo "
 
USE testcase;
 
 
 
SET profiling=1;
 
SELECT * FROM contacts WHERE systemid in ( ${SYSTEMIDLIST} ) or email = 'blaa@notexisting.nl';
 
 
 
SHOW PROFILE;
 
"

The Statistics Duration results of these queries with the different sizes:

Length of systemid list Duration output 'Statistics' in the profiling
200 0.00038.0
10000 1.087868
20000 4.831477

The bigger the systemid list the exponentially worse the time it takes to do the Statistics phase.
Running the same query multiple times in a row does not make the Statistics phase faster.

On our production environment we have a much bigger table with extra complexities and the actual query there took up to a 1000 seconds. After a little while there were so many of these queries that the database server became unresponsive (even before the max amount of connections was reached) and we had to revert to the former version.

Note: I will test some more versions to see if they also have this problem (see the comments) and add that to the affects version list if that also has this. Things like show variables output I will add to the attachments.

All mariadb 10.5 version debian packages were retrieved from here:
http://mirror.i3d.net/pub/mariadb/repo/10.5/debian buster/main amd64 Packages

 Comments   
Comment by Paul Veldema [ 2021-05-10 ]

Tested on Mariadb 10.5.7:

Status  Duration
 
Starting        0.007894
 
checking permissions    0.000007
 
Opening tables  0.000017
 
After opening tables    0.000004
 
System lock     0.000018
 
table lock      0.000008
 
init    0.002910
 
Optimizing      0.001566
 
Statistics      27.818529
 
Preparing       0.000723
 
Executing       0.000006
 
Sending data    0.274139
 
End of update loop      0.000015
 
Query end       0.000003
 
Commit  0.000005
 
closing tables  0.000004
 
Unlocking tables        0.000002
 
closing tables  0.000008
 
Starting cleanup        0.000003
 
Freeing items   0.000477
 
Updating status 0.000826
 
Logging slow query      0.000204
 
Reset for next command  0.000022

With a Statistics duration of 27.818529 with 20000 systemid's version 10.5.7 is almost a factor 7 worse than version 10.5.9.
Seems some improvement has been made from version 10.5.7 to version 10.5.9 although the problem persists.

(127)#: dpkg -l|grep mariadb
 
ii  libdbd-mariadb-perl                  1.11-3                       amd64        Perl5 database interface to the MariaDB/MySQL databases
 
ii  libmariadb3:amd64                    1:10.5.7+maria~buster        amd64        MariaDB database client library
 
ii  mariadb-backup                       1:10.5.7+maria~buster        amd64        Backup tool for MariaDB server
 
ii  mariadb-client-10.5                  1:10.5.7+maria~buster        amd64        MariaDB database client binaries
 
ii  mariadb-client-core-10.5             1:10.5.7+maria~buster        amd64        MariaDB database core client binaries
 
ii  mariadb-common                       1:10.5.7+maria~buster        all          MariaDB common configuration files
 
ii  mariadb-server-10.5                  1:10.5.7+maria~buster        amd64        MariaDB database server binaries
 
ii  mariadb-server-10.5-dbgsym           1:10.5.7+maria~buster        amd64        debug symbols for mariadb-server-10.5
 
ii  mariadb-server-core-10.5             1:10.5.7+maria~buster        amd64        MariaDB database core server files
 
ii  mariadb-server-core-10.5-dbgsym      1:10.5.7+maria~buster        amd64        debug symbols for mariadb-server-core-10.5

Comment by Paul Veldema [ 2021-05-10 ]

Tested MariaDB 10.5.8:

Status  Duration
 
Starting        0.005923
 
checking permissions    0.000010
 
Opening tables  0.000024
 
After opening tables    0.000005
 
System lock     0.000018
 
table lock      0.000008
 
init    0.002622
 
Optimizing      0.001601
 
Statistics      0.025825
 
Preparing       0.000808
 
Executing       0.000007
 
Sending data    0.225768
 
End of update loop      0.000018
 
Query end       0.000003
 
Commit  0.000007
 
closing tables  0.000005
 
Unlocking tables        0.000003
 
closing tables  0.000011
 
Starting cleanup        0.000004
 
Freeing items   0.000742
 
Updating status 0.000775
 
Reset for next command  0.000016

With a Statistics of 0.025825 on version 10.5.8 that is similar or a bit better than what we see on mariadb version 10.1.
So it seems this bug is a bit flapping between versions for some reason.

(0)#: dpkg -l|grep mariadb
 
ii  libdbd-mariadb-perl                  1.11-3                       amd64        Perl5 database interface to the MariaDB/MySQL databases
 
ii  libmariadb3:amd64                    1:10.5.8+maria~buster        amd64        MariaDB database client library
 
ii  mariadb-backup                       1:10.5.8+maria~buster        amd64        Backup tool for MariaDB server
 
ii  mariadb-client-10.5                  1:10.5.8+maria~buster        amd64        MariaDB database client binaries
 
ii  mariadb-client-core-10.5             1:10.5.8+maria~buster        amd64        MariaDB database core client binaries
 
ii  mariadb-common                       1:10.5.8+maria~buster        all          MariaDB common configuration files
 
ii  mariadb-server-10.5                  1:10.5.8+maria~buster        amd64        MariaDB database server binaries
 
ii  mariadb-server-10.5-dbgsym           1:10.5.8+maria~buster        amd64        debug symbols for mariadb-server-10.5
 
ii  mariadb-server-core-10.5             1:10.5.8+maria~buster        amd64        MariaDB database core server files
 
ii  mariadb-server-core-10.5-dbgsym      1:10.5.8+maria~buster        amd64        debug symbols for mariadb-server-core-10.5

Comment by Paul Veldema [ 2021-05-10 ]

Tested MariaDB 10.6.0:

Status  Duration
 
Starting        0.005805
 
checking permissions    0.000005
 
Opening tables  0.000013
 
After opening tables    0.000004
 
System lock     0.000017
 
table lock      0.000006
 
init    0.002681
 
Optimizing      0.001546
 
Statistics      4.442504
 
Preparing       0.000771
 
Executing       0.000005
 
Sending data    0.268246
 
End of update loop      0.000014
 
Query end       0.000003
 
Commit  0.000005
 
closing tables  0.000004
 
Unlocking tables        0.000002
 
closing tables  0.000009
 
Starting cleanup        0.000003
 
Freeing items   0.000447
 
Updating status 0.000988
 
Logging slow query      0.000134
 
Reset for next command  0.000009

Also affected: Statistics 4.442504, just about the same result as version 10.5.9

(0)#: dpkg -l|grep mariadb
 
ii  libdbd-mariadb-perl                  1.11-3                       amd64        Perl5 database interface to the MariaDB/MySQL databases
 
ii  libmariadb3:amd64                    1:10.6.0+maria~buster        amd64        MariaDB database client library
 
ii  mariadb-backup                       1:10.6.0+maria~buster        amd64        Backup tool for MariaDB server
 
ii  mariadb-client-10.6                  1:10.6.0+maria~buster        amd64        MariaDB database client binaries
 
ii  mariadb-client-core-10.6             1:10.6.0+maria~buster        amd64        MariaDB database core client binaries
 
ii  mariadb-common                       1:10.6.0+maria~buster        all          MariaDB common configuration files
 
ii  mariadb-server-10.6                  1:10.6.0+maria~buster        amd64        MariaDB database server binaries
 
ii  mariadb-server-10.6-dbgsym           1:10.6.0+maria~buster        amd64        debug symbols for mariadb-server-10.6
 
ii  mariadb-server-core-10.6             1:10.6.0+maria~buster        amd64        MariaDB database core server files
 
ii  mariadb-server-core-10.6-dbgsym      1:10.6.0+maria~buster        amd64        debug symbols for mariadb-server-core-10.6

Comment by Paul Veldema [ 2021-05-10 ]

For completeness the entire profile output for version 10.5.9 (with a list of 20000 systemid's like the other versions):

Status  Duration
 
Starting        0.005601
 
checking permissions    0.000008
 
Opening tables  0.000018
 
After opening tables    0.000004
 
System lock     0.000017
 
table lock      0.000006
 
init    0.002785
 
Optimizing      0.001656
 
Statistics      4.785894
 
Preparing       0.000788
 
Executing       0.000007
 
Sending data    0.279728
 
End of update loop      0.000015
 
Query end       0.000003
 
Commit  0.000005
 
closing tables  0.000004
 
Unlocking tables        0.000002
 
closing tables  0.000009
 
Starting cleanup        0.000003
 
Freeing items   0.000474
 
Updating status 0.001799
 
Logging slow query      0.000184
 
Reset for next command  0.000013

And the package list:

(0)#: dpkg -l|grep mariadb
 
ii  libdbd-mariadb-perl                  1.11-3                       amd64        Perl5 database interface to the MariaDB/MySQL databases
 
ii  libmariadb3:amd64                    1:10.5.9+maria~buster        amd64        MariaDB database client library
 
ii  mariadb-backup                       1:10.5.9+maria~buster        amd64        Backup tool for MariaDB server
 
ii  mariadb-client-10.5                  1:10.5.9+maria~buster        amd64        MariaDB database client binaries
 
ii  mariadb-client-core-10.5             1:10.5.9+maria~buster        amd64        MariaDB database core client binaries
 
ii  mariadb-common                       1:10.5.9+maria~buster        all          MariaDB common configuration files
 
ii  mariadb-server-10.5                  1:10.5.9+maria~buster        amd64        MariaDB database server binaries
 
ii  mariadb-server-10.5-dbgsym           1:10.5.9+maria~buster        amd64        debug symbols for mariadb-server-10.5
 
ii  mariadb-server-core-10.5             1:10.5.9+maria~buster        amd64        MariaDB database core server files
 
ii  mariadb-server-core-10.5-dbgsym      1:10.5.9+maria~buster        amd64        debug symbols for mariadb-server-core-10.5

Generated at Thu Feb 08 09:39:13 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.