Mariadb – Significant query performance degradation over time for only certain conditions

mariadbquery-performance

UPDATE: All problems described in this question disappeared after upgrade to MariaDB 10.4.17.

I've got strange situation with queries becoming increasingly slow over time.

Table with data in question has following structure:

CREATE TABLE `items` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` varchar(100) CHARACTER SET utf8 COLLATE utf8_polish_ci NOT NULL,
  `location` char(1) CHARACTER SET utf8 COLLATE utf8_polish_ci NOT NULL,
  `owner` int(11) NOT NULL DEFAULT 0,
  `class` tinyint(4) NOT NULL DEFAULT 0,
  `price` mediumint(8) unsigned NOT NULL DEFAULT 0,
  `created` timestamp NOT NULL DEFAULT current_timestamp(),
  PRIMARY KEY (`id`),
  KEY `location` (`location`,`owner`),
  KEY `name` (`name`),
  KEY `class` (`class`)
) ENGINE=InnoDB;

Trouble shows up when running query like that:

UPDATE `items` SET `price`=`price`+1 WHERE `location`='d' AND `owner`=5851775 AND `class`=17;
Query OK, 1 row affected (1.158 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Additional info for query above:

EXPLAIN UPDATE items SET price=price+1 WHERE location='d' AND owner=5851775 AND class=17;
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
| id   | select_type | table | type        | possible_keys  | key            | key_len | ref  | rows | Extra                                       |
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
|    1 | SIMPLE      | items | index_merge | location,class | location,class | 7,1     | NULL | 1    | Using intersect(location,class); Using where |
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
1 row in set (0.000 sec)

There are 67 items with owner=5851775

Running same query but with different owner value runs in almost no time:

UPDATE `items` SET `price`=`price`+1 WHERE `location`='d' AND `owner`=9406604 AND `class`=17;
Query OK, 1 row affected (0.001 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Additional info for query above:

EXPLAIN UPDATE `items` SET `price`=`price`+1 WHERE `location`='d' AND `owner`=9406604 AND `class`=17;
+------+-------------+-------+-------+----------------+----------+---------+------+------+-------------+
| id   | select_type | table | type  | possible_keys  | key      | key_len | ref  | rows | Extra       |
+------+-------------+-------+-------+----------------+----------+---------+------+------+-------------+
|    1 | SIMPLE      | items | range | location,class | location | 7       | NULL | 1    | Using where |
+------+-------------+-------+-------+----------------+----------+---------+------+------+-------------+

There is only 1 item with owner=9406604

Table contains over 2M records and this behaviour starts by showing problematic queries in slow query log after 2-3 days from restart of database. Query time for problematic values is increasing slowly and only restarting mysql daemon is fixing this for next few days.

Up to date I've done following checks:

  1. Running explain for both queries. It shows up difference between index selection. Fast query is using KEY(location), and slow one is using Using intersect(location,class);. It is weird as there is only one record in both cases (and there is no possibility it will be more than one)
  2. Running query on SLAVE instancje that is running for a long time with exact databases as on MASTER. There is similar situation with index choosing, but on SLAVE query is running very quickly (0.040s).
  3. Problematic query, according to SHOW PROFILE FOR QUERY, is spends almost all of it's time "Updating".
  4. Rarely when running query I've got ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction (about 1:5000 queries). There are no transactions in application at all for this table.
  5. For problematic query forcing index with USE INDEX(location) makes it running ultra quick (0.001s) both on master and slave.
  6. ANALYZE TABLE items does not make any difference.
  7. FLUSH TABLES makes no difference
  8. After server restart queries are running quite fast for some time. Right now 12h after restart and UPDATE takes 0.001s for queries that are using index merging.

I've checked data cardinality for KEY(owner) AND tried running query in question for those owner values:

  • owner=64399, 0.747 sec, 113 items in table with this owner value
  • owner=362379, 0.313 sec, 103 items in table with this owner value
  • owner=1077182, 0.102 sec, 163 items in table with this owner value
  • owner=1, 0.001 sec, 17 items in table with this owner value
  • owner=5851775, 1.158 sec, 67 items in table with this owner value

Result from SHOW INDEXES FROM items:

Key Name; Seq in index, Colum name, Collation, Cardinality
PRIMARY, 1, id, A, 2390665, BTREE
location, 1, location, A, 11, BTREE
location, 2, owner, A, 68838, BTREE
name, 1, name, A, 24464, BTREE
class, 1, class, A, 27, BTREE

Info from EXPLAIN:

EXPLAIN UPDATE items SET price=price+1 WHERE location='d' AND owner=64399 AND class=17;
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
| id   | select_type | table | type        | possible_keys  | key            | key_len | ref  | rows | Extra                                       |
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
|    1 | SIMPLE      | items | index_merge | location,class | location,class | 7,1     | NULL | 1    | Using intersect(location,class); Using where |
+------+-------------+-------+-------------+----------------+----------------+---------+------+------+----------------------------------------------+
1 row in set (0.000 sec)

For SELECT * with same conditions FORCING problematic INDEX:

EXPLAIN SELECT * FROM items USE INDEX(`class`) WHERE `location`='d' AND `owner`=9402368 AND `class`=17;
+------+-------------+-------+------+---------------+-------+---------+-------+-------+-------------+
| id   | select_type | table | type | possible_keys | key   | key_len | ref   | rows  | Extra       |
+------+-------------+-------+------+---------------+-------+---------+-------+-------+-------------+
|    1 | SIMPLE      | items | ref  | class         | class | 1       | const | 72744 | Using where |
+------+-------------+-------+------+---------------+-------+---------+-------+-------+-------------+

Also SELECT is running always ultra fast (0.001 sec), but UPDATE is slow AF.
NOTICE: After restart there is no query running slowly. Even those using intersect are fast (max 0.040 sec).

SHOW GLOBAL STATUS LIKE 'innodb_buffer_pool_pages_dirty';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| Innodb_buffer_pool_pages_dirty | 18857 |
+--------------------------------+-------+

SHOW GLOBAL STATUS LIKE 'uptime';
+---------------+--------+
| Variable_name | Value  |
+---------------+--------+
| Uptime        | 116348 |
+---------------+--------+

I am currently after restart. I suppose slow queries will show up in next 24h, so then I will update info with new values. I've also checked dirty pages count 7h after restart and it was about ~16k.

Right now there are no deadlocks pointed out by SHOW ENGINE INNODB STATUS;.

Query cache is disabled.

SHOW VARIABLES LIKE 'query_cache%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_strip_comments   | OFF     |
| query_cache_type             | OFF     |
| query_cache_wlock_invalidate | OFF     |
+------------------------------+---------+

Status update. I am observing described problem right now. InnoDB dirty pages got up to 20k, but yesterday it got up to 26k and there was no query in slow_query_log. Right now there are queries described in question (and no other).

SHOW GLOBAL STATUS LIKE 'innodb_buffer_pool_pages_%';
+----------------------------------+----------+
| Variable_name                    | Value    |
+----------------------------------+----------+
| Innodb_buffer_pool_pages_data    | 2978222  |
| Innodb_buffer_pool_pages_dirty   | 20852    |
| Innodb_buffer_pool_pages_flushed | 41865500 |
| Innodb_buffer_pool_pages_free    | 4833422  |
| Innodb_buffer_pool_pages_misc    | 395716   |
| Innodb_buffer_pool_pages_total   | 8207360  |
+----------------------------------+----------+

Full Profiling info for problematic query:

SHOW PROFILES;
+----------+------------+-------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                           |
+----------+------------+-------------------------------------------------------------------------------------------------+
|        1 | 0.04050855 | SELECT * FROM items USE INDEX(class) WHERE location='d' AND owner=4518486 AND class=17          |
|        2 | 1.11991697 | UPDATE itemy USE INDEX(class) SET price=price WHERE location='d' AND owner=4518486 AND class=17 |
+----------+------------+-------------------------------------------------------------------------------------------------+

SHOW PROFILE FOR QUERY 1;
+------------------------+----------+
| Status                 | Duration |
+------------------------+----------+
| Starting               | 0.000060 |
| Checking permissions   | 0.000011 |
| Opening tables         | 0.000020 |
| After opening tables   | 0.000014 |
| System lock            | 0.000009 |
| Table lock             | 0.000020 |
| Init                   | 0.000029 |
| Optimizing             | 0.000021 |
| Statistics             | 0.000076 |
| Preparing              | 0.000025 |
| Executing              | 0.000010 |
| Sending data           | 0.040111 |
| End of update loop     | 0.000020 |
| Query end              | 0.000007 |
| Commit                 | 0.000007 |
| Closing tables         | 0.000008 |
| Unlocking tables       | 0.000006 |
| Closing tables         | 0.000010 |
| Starting cleanup       | 0.000006 |
| Freeing items          | 0.000010 |
| Updating status        | 0.000016 |
| Reset for next command | 0.000014 |
+------------------------+----------+

SHOW PROFILE FOR QUERY 2;
+------------------------+----------+
| Status                 | Duration |
+------------------------+----------+
| Starting               | 0.000087 |
| Checking permissions   | 0.000010 |
| Opening tables         | 0.000022 |
| After opening tables   | 0.000010 |
| System lock            | 0.000012 |
| Table lock             | 0.000016 |
| Init for update        | 0.000073 |
| Updating               | 1.118274 |
| End of update loop     | 0.000017 |
| Query end              | 0.000008 |
| Commit                 | 0.000006 |
| Writing to binlog      | 0.000019 |
| Commit                 | 0.001209 |
| Closing tables         | 0.000020 |
| Unlocking tables       | 0.000010 |
| Closing tables         | 0.000012 |
| Starting cleanup       | 0.000010 |
| Freeing items          | 0.000013 |
| Updating status        | 0.000021 |
| Logging slow query     | 0.000052 |
| Reset for next command | 0.000014 |
+------------------------+----------+

AFTER RESTARTING:

+----------+------------+---------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                             |
+----------+------------+---------------------------------------------------------------------------------------------------+
|        1 | 0.24960048 | UPDATE items USE INDEX(`class`) SET price=price WHERE location='d' AND owner=8966252 AND klasa=17 |
+----------+------------+---------------------------------------------------------------------------------------------------+

SHOW PROFILE FOR QUERY 1;
+------------------------+----------+
| Status                 | Duration |
+------------------------+----------+
| Starting               | 0.000090 |
| Checking permissions   | 0.000010 |
| Opening tables         | 0.000022 |
| After opening tables   | 0.000009 |
| System lock            | 0.000009 |
| Table lock             | 0.000009 |
| Init for update        | 0.000061 |
| Updating               | 0.247580 |
| End of update loop     | 0.000068 |
| Query end              | 0.000007 |
| Commit                 | 0.000006 |
| Writing to binlog      | 0.000025 |
| Commit                 | 0.001622 |
| Closing tables         | 0.000014 |
| Unlocking tables       | 0.000007 |
| Closing tables         | 0.000010 |
| Starting cleanup       | 0.000009 |
| Freeing items          | 0.000008 |
| Updating status        | 0.000017 |
| Reset for next command | 0.000017 |
+------------------------+----------+

Could you point out any further tests so there is no need to restart database everyday to regain performance?

Additional info:

  • Server is dedicated only to DB: MariaDB 10.4.13
  • Machine has 256G RAM with 16 cores + HT
  • nvme SSD drive
  • InnoDB pool buffer is 128GB (64 instances_, and entire InnoDB data on machine is about 90GB.
  • Load on machine is quite high, but does not change over time to reflect this query time degradation.

As there is plenty of info in question I've summed up some conclusions here:

  • Certain UPDATEs are using intersect INDEX and it's performance progressively worsenes from mysql fresh start. Each time query is slow.
  • Same UPDATEs with different parameter values in the same time are working fine (but explain show that no intersect index is being used)
  • Problematic UPDATEs are working fine when forcing INDEX same as in non-problematic ones.
  • SELECT query with same WHERE conditions as problematic one runs without any problem (also using intersect index)
  • Seems that using INDEX(class) is source of problems. Somehow index performance degrades over time.
  • OPTIMIZE TABLE items; does not change query times
  • Adding new INDEX for (class) field and forcing query to use fresh index does not change anything comparing to original class INDEX.
  • Tested it during technical break (almost no apps using DB). There was no change in query time comparing to before technical break.
  • Tested it with making copy of table in new, unused database. New copy has exact same query time as original – it seems that it is not connected to other activities to this table, as there was none on new one.
  • After waiting long enough (6 days) entire mysql slows down on all non index queries and plenty of different ones are in slow_query_log. There are sometimes UPDATE's with condition only on PRIMARY KEY with one value.

Best Answer

Because your 'owner' column has the best cardinality for the multimillion row table, consider adding this multi column index

KEY `itemy_idx_own_loc_cla` (`owner`,`location`,`class`)

and in your update query change the sequence of the WHERE clauses to owner,location,class

for the optimizer to make a better choice.

If all indexes started with table name, you would minimize research time when digging.

2012-12-15 To deal with innodb_buffer_pool_dirty_pages, to reduce dirty pages, consider these suggestions.

innodb_flush_neighbors=2 # for all changes in current EXTENT to be dealt with now 
innodb_max_dirty_pages_pct_lwm=.0001 # to expedite reducing dirty pages 
innodb_max_dirty_pages_pct=.0001 # to expedite reducing dirty pages
innodb_flushing_avg_loops=5  # from 50 to minimize loop delay

Let us know where your dirty pages count is in 24 hours, please. These are ALL dynamic variables. SET GLOBAL (variable_name)=new_value may be used. After 24 hours and you have proven they work for your system, change your my.cnf to stay in this position of lower dirty pages every day.

Related Question