[MDEV-25127] Strange performance issues with 10.5.9 Created: 2021-03-12  Updated: 2021-04-14

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.5.9
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Denis Chernyaev Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Environment:

CentOS Linux release 8.3.2011
4.18.0-240.15.1.el8_3.x86_64
The data is stored on NVMe disk.


 Description   

We are facing strange performance issues after upgrading our DBMS to 10.5.9
Sometimes, with no obvious reasons, simple update queries get very slow, over 10 seconds.
The slow query log shows entries like the following:

# User@Host: user[user] @  [ip]
 
# Thread_id: 1000143  Schema: test  QC_hit: No
 
# Query_time: 13.510165  Lock_time: 0.000017  Rows_sent: 0  Rows_examined: 2
 
# Rows_affected: 1  Bytes_sent: 59
 
SET timestamp=1615541184;
 
update users set last_act = now(), some_field = 0 where primary_key = 99999;
 
...
 
# Time: 700101  3:00:31
 
# User@Host: user[user] @  [ip]
 
# Thread_id: 1004560  Schema: test  QC_hit: No
 
# Query_time: 31.031085  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
# Rows_affected: 0  Bytes_sent: 18446744073709547359
 
SET timestamp=31;
 
# administrator command: Change user;

So far I can't quite understand how to debug this situation. The server runs ~90 updates per second.

 Comments   
Comment by Denis Chernyaev [ 2021-04-08 ]

Essentially, random InnoDB updates get unreasonably slow.
Here is another example:

# User@Host: user[user] @  [ip]
 
# Thread_id: 1389291  Schema: db  QC_hit: No
 
# Query_time: 13.635773  Lock_time: 0.000025  Rows_sent: 0  Rows_examined: 2251799813685246
 
# Rows_affected: 50  Bytes_sent: 61
 
SET timestamp=1617855914;
 
UPDATE `users` SET last_act = NOW(), last_action_time = NOW(), field1 = 1, field2 = 'string' WHERE `primary_key` IN(<50 IDs>)

What's with that `Rows_examined` number?

Comment by Denis Chernyaev [ 2021-04-14 ]

Looks like it was a misconfiguration issue with innodb_io_capacity and innodb_io_capacity_max set way too high.
After resetting those to default values the issue is gone. I wonder though, why this didn't show up in earlier versions and why rows_examined used to get so high.

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