3

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.
4
  • You are very CORRECT, "Seems that using USING INDEX(class) is source of problems." ,,, Remove USING INDEX(anything) for a nice clean query will more often speed processing completion. For this specfic query, UPDATE items USE INDEX(class) SET price=price WHERE location='d' AND owner=8966252 AND klasa=17 you need to have the index made up of owner,location,klasa and get RID of the USING INDEX('class'). The sequence of WHERE needs to be rearranged into owner,location,klasa, please. – Wilson Hauck Dec 16 '20 at 20:23
  • Heads up! -- You have a limit on the size InnoDB can grow to. See the beginning of my long Answer. – Rick James Dec 19 '20 at 1:29
  • That limit is per extension, not total Innodb_buffer_pool_size as I read the reference manual. – Wilson Hauck Jan 18 at 13:55
  • @WilsonHauck - But there is only one file mentioned. – Rick James Jan 18 at 18:17
2

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.

11
  • thanks very much Wilson – Hannah Vernon Dec 15 '20 at 17:13
  • 1
    Changed. Dirty pages dropped 1h after change up to 12k. Queries are still slow and time is progressing. I'll wait 24h and see if it works or restart db with new values if long query became a problem. In a meanwhile I've updated question with new info. I'll be delighted if you could take a look onto it again, please. – DevilaN Dec 16 '20 at 9:03
  • Please post current text results of SHOW INDEX FROM items; PS SHOW INDEX also does refresh INDEXES. – Wilson Hauck Dec 16 '20 at 14:26
  • Please also post current text results of SHOW INDEX FROM itemy; Thanks – Wilson Hauck Dec 16 '20 at 14:34
  • 1
    I've created copy of problematic table in another database. It has the same problems even it is not used by any production service. That allows me to investigate problem further and create index, you've suggested. Index is working fine right now. Thank you for your input in fighting this problem. I will not close this question till I find reason behind lagging. Thanks one more time! – DevilaN Dec 22 '20 at 10:31
2
Innodb_buffer_pool_pages_dirty | 18857

That is probably quite large. Compare it to Innodb_buffer_pool_pages_total.

"Dirty" pages occur when any kind of write, including INDEX updates. Perhaps what happened was another query, probably an UPDATE or DELETE that modified or removed a very large number of rows.

Yes, your buffer_pool is huge (128GB), so it is only a small fraction of the space. Still, it may take more than 10 seconds to flush those out, even with SSDs.

The two queries (yours and the big update/delete) should be able to coexist and now slow down your query that much, but apparently they are having trouble.

See http://mysql.rjweb.org/doc.php/mysql_analysis for two things --

  • Analysis of GLOBAL STATUS and VARIABLES. There are a few settings that may help; and the status may help find what the problem is.
  • Slowlog analysis. That will help you find the competing query. Fixing it may be the best solution.

If that other query is a big DELETE, let's see it. There are several tips here: http://mysql.rjweb.org/doc.php/deletebig . Big UPDATEs can be helped with similar tricks.

Attempt at explanation

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

I think this estimates that 2390665/68838 ~= 35 from one index and about 2390665/27 ~= 88K from the other. "Intersect" builds two temp tables (or some other data structure), one with 35 rows and the other with 88K rows. Then it runs through them to see what matches ("intersects"). The space and time needed are such that if some other connection is busy doing something, resource contention is likely to interrupt or delay this action.

What could conflict?

(Some of these are not likely to apply in your case -- Your dataset is smaller than your buffer_pool.)

  • ALTER TABLE
  • A table scan on this table
  • The cache (buffer_pool) being flushed out due to some other table being involved in a big table scan.
  • Another connection doing a transaction that involves some of the same rows, and the deadlock-detection mechanism decided that the solution was to have this query wait until the other one finished.
  • Note that conflicts can occur between transactions even if none of the same rows are being touched. (Cf "gap locking".)

Most of those involve looking at what else is going on (the slowlog might be a good starting point). Look for other queries that stopped almost exactly at the same time as this query. (Note: the slowlog reports the ending time.)

Sorry, I can't exactly explain what you are seeing. There may be clues in SHOW GLOBAL STATUS and SHOW VARIABLES. For more on settings and slowlog: http://mysql.rjweb.org/doc.php/mysql_analysis

10
  • 1
    There are no big delete/updates during day. I am currently observing entries in slow_query_log right now and there are no other entries except those UPDATEs mentioned in question. I've been monitoring status and variables. Dirty pages got up to 26k and there were no entries in slow query log, and now dirty pages dropped to 20k and there are slow queries. Is there any method I can test dirty pages theory so we can determine whether it is source of slowness when intersect index has been choosen? – DevilaN Dec 16 '20 at 7:27
  • 1
    It is 1.00, I can provide entire config and globals+variables from time when everything is working and from now. 3-colum index indeed should provide intersect elimination, but I am more interested in understanding current (quite cryptic) behaviour than fixing problem with one query. – DevilaN Dec 16 '20 at 8:02
  • 1
    Added summary and profiling info for problematic queries. Maybe it will lighten up something. – DevilaN Dec 16 '20 at 8:46
  • 1
    @DevilaN - I find Profiling to be disappointingly useless. I added a stab at "explaining" the behavior in my Answer. – Rick James Dec 16 '20 at 18:42
  • 1
    There is no alter running, neigher are any of other mechanisms, because I suppose long query would not be repeatable each time (also there is no difference during high load peak and valleys during late night). It is consistently degrading in terms of time needed to finish query. Also there are no other queries in slow_log. By any chance you could take a look on my setup. devix.pl/tmp/mysqlinfo/config.cnf devix.pl/tmp/mysqlinfo/global_status.txt devix.pl/tmp/mysqlinfo/variables.txt Regards – DevilaN Dec 17 '20 at 14:41
1

HEADS UP: This limits you to 8GB of InnoDB data and indexes:

"innodb_data_file_path": "ibdata1:20M:autoextend:max:8196M"

Analysis of GLOBAL STATUS and VARIABLES:

Observations:

  • Version: 10.4.13-MariaDB-log
  • 256 GB of RAM
  • Uptime = 1d 03:19:21
  • You are not running on Windows.
  • Running 64-bit version
  • It appears that you are running both MyISAM and InnoDB.

The More Important Issues:

Either raise key_buffer_size to 1GB or migrate the MyISAM tables to InnoDB

Increase table_definition_cache to 5000.
Decrease table_open_cache to 10000.
(Opened_tables is only 8005 and Open_tables is only 6386.)

Max_used_connections is awfully high at 14844. Although you have the RAM to handle it, it may be stressing some caches, etc.

In particular, binlog_cache_size = 16M could blow out RAM. (Swapping is very bad for performance.) Suggest lowering that to 2M.

Lower either innodb_lru_scan_depth or innodb_buffer_pool_instances

I doubt if having such a tiny value for innodb_max_dirty_pages_pct and innodb_max_dirty_pages_pct_lwm is useful. Suggest simply 1. (It may even be an integer, hence "0.000100" would be improper.)

Suggest innodb_log_file_size = 2G

Is there some reason for innodb_flush_method = fsync? Consult: https://mariadb.com/kb/en/innodb-system-variables/#innodb_flush_method

1G for max_heap_table_size and tmp_table_size is excessive, even for your large RAM, especially with such a large max_connections. Drop it to, say, 100M. Meanwhile what the slowlog for specific queries that may need improving.

SHOW VARIABLES being run 45 times a second? What's up?

REPLACE (8/sec) is DELETE+INSERT; consider changing to INSERT ... ON DUPLICATE KEY UPDATE ...

80 KILLs per day?

A lot of "lost" values in the performance_schema. Maybe you should turn off the PS?

max_long_data_size was deprecated long ago; it is going away in 10.5. Just a heads up so you can remove it from the config file.

Details and other observations:

( Key_reads + Key_writes + Innodb_pages_read + Innodb_pages_written + Innodb_dblwr_writes + Innodb_buffer_pool_pages_flushed ) = (425006 + 20938286 + 2820318 + 24064234 + 11244235 + 24061393) / 98361 = 849 /sec -- IOPs? -- If the hardware can handle it, set innodb_io_capacity (now 2000) to about this value.

( table_open_cache ) = 55,793 -- Number of table descriptors to cache -- Several hundred is usually good.

( binlog_cache_size * max_connections ) = (16M * 16384) / 262144M = 100.0% -- RAM used for caching transactions on the way to the binlog. -- Decrease binlog_cache_size (now 16777216) and/or max_connections (now 16384)

( Binlog_stmt_cache_disk_use ) = 37,483 / 98361 = 0.38 /sec -- Freq of non-transactional binlog cache spilling to disk during transactions -- Increase binlog_stmt_cache_size (now 32768).

( innodb_buffer_pool_instances ) = 64 -- For large RAM, consider using 1-16 buffer pool instances, not allowing less than 1GB each. Also, not more than, say, twice the number of CPU cores. -- Recommend no more than 16.

( innodb_lru_scan_depth * innodb_buffer_pool_instances ) = 1,024 * 64 = 65,536 -- A metric of CPU usage. -- Lower either number.

( innodb_lru_scan_depth * innodb_page_cleaners ) = 1,024 * 4 = 4,096 -- Amount of work for page cleaners every second. -- "InnoDB: page_cleaner: 1000ms intended loop took ..." may be fixable by lowering lru_scan_depth: Consider 1000 / innodb_page_cleaners (now 4). Also check for swapping.

( innodb_page_cleaners / innodb_buffer_pool_instances ) = 4 / 64 = 0.0625 -- innodb_page_cleaners -- Recommend setting innodb_page_cleaners (now 4) to innodb_buffer_pool_instances (now 64)

( innodb_lru_scan_depth ) = 1,024 -- "InnoDB: page_cleaner: 1000ms intended loop took ..." may be fixed by lowering lru_scan_depth

( innodb_max_dirty_pages_pct ) = 0.0001 -- When buffer_pool starts flushing to disk -- Are you experimenting?

( Innodb_buffer_pool_pages_free / Innodb_buffer_pool_pages_total ) = 4,930,137 / 8207360 = 60.1% -- Pct of buffer_pool currently not in use -- innodb_buffer_pool_size (now 137438953472) is bigger than necessary?

( (Innodb_buffer_pool_reads + Innodb_buffer_pool_pages_flushed) ) = ((2667073 + 24061393) ) / 98361 = 271 /sec -- InnoDB I/O -- Increase innodb_buffer_pool_size (now 137438953472)?

( Innodb_buffer_pool_pages_flushed ) = 24,061,393 / 98361 = 244 /sec -- Writes (flushes) -- Increase innodb_buffer_pool_size (now 137438953472)?

( Innodb_buffer_pool_bytes_data / innodb_buffer_pool_size ) = 47,540,731,904 / 131072M = 34.6% -- Percent of buffer pool taken up by data -- A small percent may indicate that the buffer_pool is unnecessarily big.

( Innodb_os_log_written ) = 63,089,610,752 / 98361 = 641408 /sec -- This is an indicator of how busy InnoDB is. -- Very busy InnoDB.

( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 98,361 / 60 * 512M / 63089610752 = 14 -- Minutes between InnoDB log rotations Beginning with 5.6.8, this can be changed dynamically; be sure to also change my.cnf. -- (The recommendation of 60 minutes between rotations is somewhat arbitrary.) Adjust innodb_log_file_size (now 536870912). (Cannot change in AWS.)

( innodb_flush_method ) = innodb_flush_method = fsync -- How InnoDB should ask the OS to write blocks. Suggest O_DIRECT or O_ALL_DIRECT (Percona) to avoid double buffering. (At least for Unix.) See chrischandler for caveat about O_ALL_DIRECT

( default_tmp_storage_engine ) = default_tmp_storage_engine =

( Innodb_dblwr_writes ) = 11,244,235 / 98361 = 114 /sec -- "Doublewrite buffer" writes to disk. "Doublewrites" are a reliability feature. Some newer versions / configurations don't need them. -- (Symptom of other issues)

( innodb_flush_neighbors ) = 2 -- A minor optimization when writing blocks to disk. -- Use 0 for SSD drives; 1 for HDD.

( sync_binlog ) = 0 -- Use 1 for added security, at some cost of I/O =1 may lead to lots of "query end"; =0 may lead to "binlog at impossible position" and lose transactions in a crash, but is faster.

( innodb_print_all_deadlocks ) = innodb_print_all_deadlocks = OFF -- Whether to log all Deadlocks. -- If you are plagued with Deadlocks, turn this on. Caution: If you have lots of deadlocks, this may write a lot to disk.

( max_connections ) = 16,384 -- Maximum number of connections (threads). Impacts various allocations. -- If max_connections (now 16384) is too high and various memory settings are high, you could run out of RAM.

( character_set_server ) = character_set_server = utf8 -- Charset problems may be helped by setting character_set_server (now utf8) to utf8mb4. That is the future default.

( local_infile ) = local_infile = ON -- local_infile (now ON) = ON is a potential security issue

( Key_writes / Key_write_requests ) = 20,938,286 / 26442309 = 79.2% -- key_buffer effectiveness for writes -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 268435456).

( Key_reads ) = 425,006 / 98361 = 4.3 /sec -- MyISAM index read (from disk) rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 268435456).

( Key_writes ) = 20,938,286 / 98361 = 212 /sec -- MyISAM index write (to disk) rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 268435456).

( Key_reads + Key_writes ) = (425006 + 20938286) / 98361 = 217 /sec -- MyISAM index I/O rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 268435456).

( Questions ) = 749,163,347 / 98361 = 7616 /sec -- Queries (outside SP) -- "qps" -- >2000 may be stressing server

( Queries ) = 755,386,446 / 98361 = 7679 /sec -- Queries (including inside SP) -- >3000 may be stressing server

( Created_tmp_tables ) = 4,830,757 / 98361 = 49 /sec -- Frequency of creating "temp" tables as part of complex SELECTs.

( tmp_table_size ) = 1024M -- Limit on size of MEMORY temp tables used to support a SELECT -- Decrease tmp_table_size (now 1073741824) to avoid running out of RAM. Perhaps no more than 64M.

( Com_show_variables ) = 4,466,209 / 98361 = 45 /sec -- SHOW VARIABLES ... -- Why are you requesting the VARIABLES so often?

( Select_scan ) = 12,236,248 / 98361 = 124 /sec -- full table scans -- Add indexes / optimize queries (unless they are tiny tables)

( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (24617970 + 4964261 + 329 + 802085 + 95033009 + 34179) / 98361 = 1275 /sec -- writes/sec -- 50 writes/sec + log flushes will probably max out I/O write capacity of normal drives

( Com_replace ) = 802,085 / 98361 = 8.2 /sec -- Consider changing to INSERT ... ON DUPLICATE KEY UPDATE.

( binlog_format ) = binlog_format = MIXED -- STATEMENT/ROW/MIXED. -- ROW is preferred by 5.7 (10.3)

( Max_used_connections ) = 14,844 -- High-water mark for connections -- Lots of inactive connections is OK; over 100 active connections is likely to be a problem. Max_used_connections (now 14844) does not distinguish them; Threads_running (now 17) is instantaneous.

( Max_used_connections / host_cache_size ) = 14,844 / 1422 = 1043.9% -- Increase host_cache_size (now 1422)

( Com_change_db ) = 39,619,526 / 98361 = 402 /sec -- Probably comes from USE statements. -- Consider connecting with DB, using db.tbl syntax, eliminating spurious USE statements, etc.

( Connections ) = 52,662,800 / 98361 = 535 /sec -- Connections -- Increase wait_timeout (now 10800); use pooling?

Abnormally small:

Innodb_dblwr_pages_written / Innodb_dblwr_writes = 2.14
Innodb_log_writes / Innodb_log_write_requests = 0.21%
Key_blocks_unused = 0
innodb_flushing_avg_loops = 5
innodb_spin_wait_delay = 4
lock_wait_timeout = 86,400

Abnormally large:

1.2 * Key_blocks_used * 1024 = 251.2MB
Acl_column_grants = 39
Acl_database_grants = 154
Acl_table_grants = 1,005
Acl_users = 159
Binlog_cache_use = 1117 /sec
Binlog_commits = 1260 /sec
Binlog_group_commits = 1258 /sec
Binlog_stmt_cache_use = 143 /sec
Bytes_sent = 14140223 /sec
Com_delete = 50 /sec
Com_insert = 250 /sec
Com_kill = 3.5 /HR
Com_replace_select = 0.29 /HR
Com_select = 4942 /sec
Com_set_option = 411 /sec
Com_show_profile = 0.073 /HR
Com_show_profiles = 0.11 /HR
Com_show_warnings = 14 /HR
Com_truncate = 36 /HR
Com_update = 966 /sec
Com_update_multi = 0.35 /sec
Executed_triggers = 63 /sec
Feature_check_constraint = 0.037 /HR
Feature_trigger = 14 /HR
Handler_commit = 6863 /sec
Handler_delete = 153 /sec
Handler_prepare = 2156 /sec
Handler_read_last = 515 /sec
Handler_read_next = 1528765 /sec
Handler_read_rnd = 25538 /sec
Handler_tmp_update = 793 /sec
Innodb_buffer_pool_bytes_data = 483329 /sec
Innodb_buffer_pool_pages_data = 2.9e+6
Innodb_buffer_pool_pages_free = 4.93e+6
Innodb_buffer_pool_pages_misc = 375,567
Innodb_buffer_pool_pages_total = 8.21e+6
Innodb_buffer_pool_read_requests = 866755 /sec
Innodb_buffer_pool_write_requests = 12406 /sec
Innodb_data_fsyncs = 349 /sec
Innodb_data_writes = 361 /sec
Innodb_data_writes - Innodb_log_writes - Innodb_dblwr_writes = 244 /sec
Innodb_data_written = 8657946 /sec
Innodb_dblwr_pages_written = 244 /sec
Innodb_log_write_requests = 1317 /sec
Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group = 1,101.1MB
Innodb_pages_written = 244 /sec
Innodb_rows_deleted = 152 /sec
Innodb_rows_read = 1828262 /sec
Innodb_rows_updated = 891 /sec
Innodb_secondary_index_triggered_cluster_reads = 153577 /sec
Key_blocks_used = 214,334
Key_blocks_warm = 211,902
Key_read_requests = 22903 /sec
Key_write_requests = 268 /sec
Open_files = 1,473
Open_table_definitions = 3,161
Open_tables = 6,386
Performance_schema_accounts_lost = 3.36e+7
Performance_schema_digest_lost = 9.45e+6
Performance_schema_file_instances_lost = 167,028
Performance_schema_table_handles_lost = 7.29e+7
Performance_schema_users_lost = 369,575
Select_range = 218 /sec
Slaves_connected = 0.037 /HR
Slaves_running = 8
Sort_priority_queue_sorts = 18 /sec
Sort_range = 390 /sec
Sort_rows = 50173 /sec
Sort_scan = 53 /sec
Table_open_cache_hits = 6376 /sec
Threadpool_idle_threads = 158
Threadpool_threads = 162
Threads_connected = 1,478
Threads_running = 17
binlog_cache_size = 1.68e+7
host_cache_size = 1,422
innodb_open_files = 55,793
max_heap_table_size = 1024MB
max_long_data_size = 1024MB
max_relay_log_size = 1024MB
max_user_connections = 8,192
min(max_heap_table_size, tmp_table_size) = 1024MB
net_buffer_length = 131,072
performance_schema_events_stages_history_size = 20
performance_schema_events_statements_history_size = 20
performance_schema_events_waits_history_size = 20
performance_schema_max_cond_classes = 90
performance_schema_max_cond_instances = 66,836
performance_schema_max_socket_instances = 32,788
performance_schema_max_thread_instances = 32,868
pseudo_thread_id = 5.27e+7
tmp_memory_table_size = 1024MB

Abnormal strings:

Innodb_have_bzip2 = ON
aria_recover_options = BACKUP,QUICK
disconnect_on_expired_password = OFF
gtid_slave_pos = 0-16-432105589
histogram_type = DOUBLE_PREC_HB
innodb_fast_shutdown = 1
log_slow_admin_statements = ON
log_slow_verbosity = query_plan,explain
myisam_stats_method = NULLS_UNEQUAL
old_alter_table = DEFAULT
opt_s__optimize_join_buffer_size = on
optimizer_trace = enabled=off
thread_handling = pool-of-threads
use_stat_tables = PREFERABLY_FOR_QUERIES
4
  • ibdata1 file is currently 652MB large, so I didn't suspected this would affect anything at all right now. I've removed max anyway. innodb_flush_method = fsync is default value on linux machines I'll look onto it how it could be optimized better. SHOW VARIABLES 45 times per second is mysql-connector-c++ fault which runs it for each connection. I've applied your suggestions and restarted mysql - now waiting whether it changes. Thank you very much for your effort and time! :) – DevilaN Dec 21 '20 at 9:44
  • Hi! After few days everything not using indexes started to show up in slow_query_log and day by day query time increases for those queries. Maybe it will hint on anything here? I am about to upgrade mariadb to 10.5 to check whether this issue has been resolved in newer version. Regards. – DevilaN Dec 29 '20 at 15:41
  • @DevilaN - I don't like to use the setting about queries not using indexes. The flag is somewhat useful when the dataset is tiny but becomes irrelevant as the data grows. Having an index does not help a ten-row table, so being in the log is 'noise'. Lower long_query_time as you fix the slow queries. – Rick James Dec 29 '20 at 17:19
  • @DevilaN - (continued) So, it sounds like the table is growing and the flag is useful. But eventually long_query_time will catch such queries, making that setting unnecessary. – Rick James Dec 29 '20 at 17:21
0

As nbk mentioned, it sounds like you have a cardinality estimate issue. You can try UPDATING STATISTICS on the Table itself or the individual Index as sometimes statistics are outdated, otherwise you may need to use the index hint to maintain performance.

This is probably why restarting the MySQL instance is temporarily fixing the issue (because it likely resets the statistics each time).

You can read up more on on cardinality estimate issues in this similar StackExchange question I answered here.

Quoting the most important part for historical redundancy:

When you write a query, the predicates (values of the conditions in your WHERE and JOIN clauses) are used to filter the data of the Table based on those values. So the SQL engine uses its statistics for those particular values from your predicates to decide what kind of Execution Plan would be most performant, for example something with a low cardinality (low uniqueness, so high number of records contain that value) a full scan makes sense as opposed to an index seek (on a B-Tree) which would occur for a value with high cardinality (high uniqueness, not a lot of rows contain that value).

To summarize the above link, different values in WHERE (and JOIN) clauses have different uniqueness within the Table those columns belong to. The SQL engine stores statistics on every value in the table to determine the best execution plan for serving the data (since a value in a low number of rows is more efficiently served differently than a value in a high number of rows). That's why you can see two different execution plans (and different indexes) used for the same query by just changing the values in the WHERE and JOIN clauses. Sometimes the statistics are outdated or can be off and they need to be updated, or a query rewrite can be tried (though in your case there's not much to rewrite for a simple UPDATE statement), or an index hint needs to be used.

6
  • It does not seem to depend on cardinality or I am not interpreting it correctly. I've added additional info to my question. – DevilaN Dec 13 '20 at 18:50
  • "statistics for every value" -- No. Just "statistics for each index". It will, however, probe the table to get an estimate of the number of rows for the current condition in the where clause. – Rick James Dec 14 '20 at 1:01
  • @RickJames Poorly worded I suppose, but somewhat true as you clarified that it probes the table for the cardinality. – J.D. Dec 14 '20 at 1:18
  • 1
    @J.D. - Some other vendors do have more stats. MariaDB 10.0 has "histograms" which is somewhat like that. 10.4 collects stats for histograms by default in 10.4. – Rick James Dec 14 '20 at 1:27
  • 1
    It's been 11 days since upgrade to 10.4.17 and despite not changing anything else all described problems seems to go away. Thank you very much for your effort and contribution to solve my problems! – DevilaN Jan 18 at 11:35

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.