MariaDB - Mysterious Delay at Each Query

Question

I have 2 tables on MariaDB (10.5.16-MariaDB-log) where I query table A, and then loop over the roughly 4000 results and for each one do a query on table B. (This is inherited code and this will be replaced with a join once the below problem is resolved, but for now it's useful for illustrating the problem.)

I have 3 servers (1 testing with 32 GB RAM, and 2 production servers each with 64 GB RAM; all storage is enterprise SSDs; all have 12 cpu cores). All 3 behaved similarly with the 4,000 queries finishing in about 0.3 seconds.

All 3 servers had the same unoptimized configuration (all but a handful of tables are InnoDB) as the production server:

Production variables

Production status

I made the following changes to our test server in an attempt to optimize, which did make the database much faster for our particular workload:

Testing variables

Testing Status

innodb_buffer_pool_size = 4G (was 128M)
innodb_io_capacity = 1000 (was 200)
innodb_io_capacity_max = 4000 (was 2000)
table_open_cache = 5000 (was 400; we have over 30k tables)
innodb_open_files = 5000 (was 400)
innodb_log_file_size = 2G (was 96M)
key_buffer_size = 2G (was 4G)
innodb_flush_method = O_DIRECT (was fsync)

However, it has had the odd side-effect that the loop of 4000 queries now takes about 20 seconds instead of 0.3. So while most queries are much faster, a whole bunch of tiny queries all at once is much slower. It appears that something is adding 0.005 seconds (average) to each query up-front, that doesn't affect the overall performance of the query itself.

0.005 seconds per query doesn't sound like much but these are heavily used servers averaging about 1300 queries per second (which means this adds over 6 seconds of total delay per second). And going from 0.3 seconds to 20 seconds on this page is very noticeable.

I need to solve this before I can roll out the changes to our production servers, which could really benefit from the overall performance boost we've seen from the changes (aside from this one odd slowdown).

Which of the changes could be causing this? Any ideas to debug it? Thanks!

Update 1 (2023-02-13)

Rolling back the changes made the problem worse (as well as overall performance). Using the exact same settings as the production servers also made the problem worse (even though on those servers it takes 0.2 - 0.3 seconds consistently, every time). The best combination was additional optimizations based on the information from @rick-james which make it so it takes 0.2 - 0.3 seconds about half the time, in waves, and other times takes 12 - 45+ seconds.

innodb_io_capacity = 20000
innodb_io_capacity_max = 40000
innodb_flush_neighbors = 0

I have a cron timing this and recording the results every 5 minutes on both the testing and production servers. I'm currently recording SHOW GLOBAL STATUS before each test to try to look for patterns when it's slow.

For now I'm still completely stumped.

Answer 1

Analysis of GLOBAL STATUS and VARIABLES for "Production".
(Testing may need similar changes)
 

Observations:

• Version: 10.5.16-MariaDB
• 32 GB of RAM
• Uptime = 112d 20:06:09
• 2.58e+3 Queries/sec : 2.29e+3 Questions/sec

The More Important Issues:

Recommended changes:

key_buffer_size = 1G            -- used only by ENGINE=MyISAM
innodb_io_capacity = 20000
innodb_io_capacity_max = 40000
query_cache_type = OFF
query_cache_size = 0            -- to fully turn it off
max_connections = 1000          -- see Max_used_connections
innodb_buffer_pool_size = 20G   -- unless lots of apps running on same machine
innodb_log_file_size = 1G       -- (check manual on how to change)
innodb_flush_neighbors = 0      -- if disk is SSD
max_heap_table_size = 200M
tmp_table_size = 200M

Sounds bad but I don't have advice:

Access_denied_errors = 241,147

Be aware that init_connect = ... is not executed when logging in as "root".

Details and other observations:

( key_buffer_size ) = 4,096 / 32768M = 12.5% -- % of RAM used for key_buffer (for MyISAM indexes) -- 20% is ok if you are not using InnoDB.

( (key_buffer_size - 1.2 * Key_blocks_used * 1024) ) = ((4096M - 1.2 * 0 * 1024)) / 32768M = 12.5% -- Percent of RAM wasted in key_buffer. -- Decrease key_buffer_size (now 4294967296).

( Key_blocks_used * 1024 / key_buffer_size ) = 0 * 1024 / 4096M = 0 -- Percent of key_buffer used. High-water-mark. -- Lower key_buffer_size (now 4294967296) to avoid unnecessary memory usage.

( Key_reads + Key_writes + Innodb_pages_read + Innodb_pages_written + Innodb_dblwr_writes + Innodb_buffer_pool_pages_flushed ) = (0 + 0 + 489772056109 + 14295446637 + 353895848 + 14295446637) / 9749169 = 53206 /sec -- IOPs? -- If the hardware can handle it, set innodb_io_capacity (now 1000) to about this value.

( ( Key_reads + Key_writes + Innodb_pages_read + Innodb_pages_written + Innodb_dblwr_writes + Innodb_buffer_pool_pages_flushed ) / innodb_io_capacity / Uptime ) = ( 0 + 0 + 489772056109 + 14295446637 + 353895848 + 14295446637 ) / 1000 / 9749169 = 5320.6% -- This may be a metric indicating what innodb_io_capacity is set reasonably. -- Increase innodb_io_capacity (now 1000) if the hardware can handle it.

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

( innodb_buffer_pool_size ) = 5,120 / 32768M = 15.6% -- % of RAM used for InnoDB buffer_pool -- Set to about 70% of available RAM. (To low is less efficient; too high risks swapping.)

( innodb_buffer_pool_size / innodb_buffer_pool_instances ) = 5120M / 1 = 5120MB -- Size of each buffer_pool instance. -- An instance should be at least 1GB. In very large RAM, have 16 instances.

( innodb_lru_scan_depth * innodb_page_cleaners ) = 1,536 * 1 = 1,536 -- 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 1). Also check for swapping.

( innodb_lru_scan_depth ) = 1,536 -- innodb_lru_scan_depth is a very poorly named variable. A better name would be innodb_free_page_target_per_buffer_pool. It is a number of pages InnoDB tries to keep free in each buffer pool instance to speed up read and page creation operations. -- "InnoDB: page_cleaner: 1000ms intended loop took ..." may be fixed by lowering lru_scan_depth

( Innodb_buffer_pool_pages_old / Innodb_buffer_pool_pages_total ) = 119,064 / 322600 = 36.9% -- Pct of buffer_pool that is "old".

( innodb_io_capacity_max / innodb_io_capacity ) = 4,000 / 1000 = 4 -- Capacity: max/plain -- Recommend 2. Max should be about equal to the IOPs your I/O subsystem can handle. (If the drive type is unknown 2000/200 may be a reasonable pair.)

( Innodb_buffer_pool_reads / Innodb_buffer_pool_read_requests ) = 488,639,965,007 / 18077939624146 = 2.7% -- Read requests that had to hit disk -- Increase innodb_buffer_pool_size (now 5368709120) if you have enough RAM.

( Innodb_pages_read / Innodb_buffer_pool_read_requests ) = 489,772,056,109 / 18077939624146 = 2.7% -- Read requests that had to hit disk -- Increase innodb_buffer_pool_size (now 5368709120) if you have enough RAM.

( Innodb_buffer_pool_read_ahead_evicted / Innodb_buffer_pool_read_ahead ) = 792,262,991 / 866418869 = 91.4% -- Utility of read_ahead. -- Turn off innodb_random_read_ahead (now OFF).

( innodb_change_buffering ) = innodb_change_buffering = none -- Pre-5.6.11 / 5.5.31, there was a bug that made ="changes" a safer option. MariaDB 10.5.15 is moving toward "none" and deprecating in 10.9

( innodb_log_files_in_group ) = 1 -- Number of InnoDB log files -- 2 is probably the only reasonable value. A large number may cause performance problems.

( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 69,113,677,853,184 / (9749169 / 3600) / 1 / 96M = 253 -- Ratio -- (see minutes)

( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 9,749,169 / 60 * 96M / 69113677853184 = 0.237 -- Minutes between InnoDB log rotations Beginning with 5.6.8, innodb_log_file_size can be changed dynamically; I don't know about MariaDB. Be sure to also change my.cnf -- (The recommendation of 60 minutes between rotations is somewhat arbitrary.) Adjust innodb_log_file_size (now 100663296). (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_row_lock_time_max ) = 62,008 -- Max time to lock a row (millisec) -- Possibly conflicting queries; possibly table scans.

( Innodb_row_lock_waits/Innodb_rows_inserted ) = 120,835,999/9751508599 = 1.2% -- Frequency of having to wait for a row.

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

( ( Innodb_pages_read + Innodb_pages_written ) / Uptime / innodb_io_capacity ) = ( 489772056109 + 14295446637 ) / 9749169 / 1000 = 5170.4% -- If > 100%, need more io_capacity. -- Increase innodb_io_capacity (now 1000) if the drives can handle it.

( innodb_flush_log_at_trx_commit ) = 1 -- 1 = secure; 2 = faster -- (You decide) Use 1, along with sync_binlog (now 0)=1 for the greatest level of fault tolerance. 0 is best for speed. 2 is a compromise between 0 and 1.

( 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. 0 is OK for Galera.

( 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 ) = 5,000 -- Maximum number of connections (threads). Impacts various allocations. -- If max_connections (now 5000) is too high and various memory settings are high, you could run out of RAM.

( min( tmp_table_size, max_heap_table_size ) ) = (min( 2048M, 2048M )) / 32768M = 6.2% -- Percent of RAM to allocate when needing MEMORY table (per table), or temp table inside a SELECT (per temp table per some SELECTs). Too high may lead to swapping. -- Decrease tmp_table_size (now 2147483648) and max_heap_table_size (now 2147483648) to, say, 1% of ram.

( 176000 * max_connections ) = (176000 * 5000) / 32768M = 2.6% -- Estimate of ram usage due to the size of max_connections. -- max_connections (now 5000) is somewhat high

( character_set_client ) = character_set_client = utf8 -- -- If you will be using text from places other than Western Europe, consider switching to utf8mb4. (Beyond the scope of this discussion.)

( character_set_connection ) = character_set_connection = utf8 --

( character_set_results ) = character_set_results = utf8 --

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

( bulk_insert_buffer_size ) = 2,048 / 32768M = 6.2% -- Buffer for multi-row INSERTs and LOAD DATA -- Too big could threaten RAM size. Too small could hinder such operations.

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

( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (5997232968 + 1523681278 + 5273208332 + 0) / 9 = 1.42e+9 -- Statements per Commit (assuming all InnoDB) -- Low: Might help to group queries together in transactions; High: long transactions strain various things.

( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (5997232968 + 5273208332 + 0 + 0 + 1523681278 + 0) / 9749169 = 1312 /sec -- writes/sec -- 50 writes/sec + log flushes will probably max out I/O write capacity of normal drives

( Com_admin_commands / Queries ) = 22,212,460,278 / 25134920899 = 88.4% -- Percent of queries that are "admin" commands. -- What's going on?

( Com__biggest ) = Com__biggest = Com_admin_commands -- Which of the "Com_" metrics is biggest. -- Normally it is Com_select (now 9416507112). If something else, then it may be a sloppy platform, or may be something else.

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

( slow_query_log ) = slow_query_log = OFF -- Whether to log slow queries. (5.1.12)

( long_query_time ) = 10 -- Cutoff (Seconds) for defining a "slow" query. -- Suggest 2

( Max_used_connections / max_connections ) = 795 / 5000 = 15.9% -- Peak % of connections -- Since several memory factors can expand based on max_connections (now 5000), it is good not to have that setting too high.

( Max_used_connections ) = 795 -- 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 795) does not distinguish them; Threads_running (now 2) is instantaneous.

( max_connect_errors ) = 100,000 -- A small protection against hackers. -- Perhaps no more than 200.

( thread_pool_max_threads ) = 65,536 -- One of many settings for MariaDB's thread pooling -- Lower the value.

You have the Query Cache half-off. You should set both query_cache_type = OFF and query_cache_size = 0 . There is (according to a rumor) a 'bug' in the QC code that leaves some code on unless you turn off both of those settings.

VSClasses.inc.254 Error with eval('((1048576 - 1031304) / 0) / 4096') expr=[[((query_cache_size - Qcache_free_memory) / Qcache_queries_in_cache) / query_cache_min_res_unit]] VSClasses.inc.254 Error with eval('(1048576 - 1031304) / 0 / 16384') expr=[[(query_cache_size - Qcache_free_memory) / Qcache_queries_in_cache / query_alloc_block_size]]

Abnormally small:

Innodb_buffer_pool_pages_misc = 0
Innodb_buffer_pool_pages_misc * 16384 / innodb_buffer_pool_size = 0
Innodb_buffer_pool_read_requests / (Innodb_buffer_pool_read_requests + Innodb_buffer_pool_reads ) = 97.4%
Innodb_master_thread_idle_loops = 1.8 /HR
innodb_adaptive_max_sleep_delay = 0

Abnormally large:

( Innodb_pages_read + Innodb_pages_written ) / Uptime = 51,703
Access_denied_errors = 241,147
Bytes_received = 3714128 /sec
Com_alter_table + Com_flush = 0.18 /sec
Com_alter_user = 0.0018 /HR
Com_create_index = 2.5 /HR
Com_delete = 540 /sec
Com_insert = 615 /sec
Com_rename_table = 1.7 /HR
Com_reset = 0.00037 /HR
Com_revoke = 0.0018 /HR
Com_show_slave_status = 89 /HR
Com_stmt_close = 142 /sec
Com_stmt_execute = 142 /sec
Com_stmt_prepare = 142 /sec
Connection_errors_peer_address = 0.00074 /HR
Handler_delete = 577 /sec
Handler_read_next = 844544 /sec
Handler_update = 2348 /sec
Innodb_adaptive_hash_non_hash_searches = 240229 /sec
Innodb_buffer_pool_pages_lru_flushed = 1.06e+10
Innodb_buffer_pool_pages_made_not_young = 690560 /sec
Innodb_buffer_pool_pages_made_young = 1735 /sec
Innodb_buffer_pool_read_ahead = 8.66e+8
Innodb_buffer_pool_read_requests = 1854305 /sec
Innodb_buffer_pool_reads * innodb_page_size / innodb_buffer_pool_size = 149121083.1%
Innodb_buffer_pool_write_requests = 19226 /sec
Innodb_data_fsyncs = 948 /sec
Innodb_data_read = 823464523 /sec
Innodb_data_reads = 50294 /sec
Innodb_data_writes = 2267 /sec
Innodb_data_writes - Innodb_log_writes - Innodb_dblwr_writes = 1466 /sec
Innodb_data_written = 24025202 /sec
Innodb_dblwr_pages_written = 1322 /sec
Innodb_deadlocks / Com_commit = 1464911.1%
Innodb_instant_alter_column = 1.5 /HR
Innodb_log_write_requests = 2084 /sec
Innodb_master_thread_active_loops = 9.73e+6
Innodb_num_open_files = 5,000
Innodb_os_log_fsyncs = 764 /sec
Innodb_os_log_pending_writes = 110
Innodb_pages_created = 156 /sec
Innodb_pages_read = 50237 /sec
Innodb_pages_read + Innodb_pages_written = 51703 /sec
Innodb_pages_written = 1466 /sec
Innodb_rows_deleted = 567 /sec
Innodb_rows_deleted + Innodb_rows_inserted = 1567 /sec
Innodb_rows_inserted = 1000 /sec
Innodb_rows_read = 965713 /sec
Innodb_rows_updated = 2293 /sec
Innodb_secondary_index_triggered_cluster_reads = 218627 /sec
Key_blocks_unused = 3.43e+6
Memory_used_initial = 757.1MB
Open_streams = 4
Open_table_definitions = 6,236
Open_tables = 10,000
Threads_cached = 351
Update_scan = 6.18e+8
back_log / max_connections = 204.8%
max_heap_table_size = 2048MB
min(max_heap_table_size, tmp_table_size) = 2048MB
performance_schema_max_statement_classes = 222
tmp_memory_table_size = 2048MB

Abnormal strings:

Innodb_buffer_pool_resize_status = Completed resizing buffer pool at 230106 16:45:24.
Slave_heartbeat_period = 0
Slave_received_heartbeats = 0
aria_recover_options = BACKUP,QUICK
disconnect_on_expired_password = OFF
init_connect = SET NAMES utf8
innodb_fast_shutdown = 1
myisam_stats_method = NULLS_UNEQUAL
old_alter_table = DEFAULT
optimizer_trace = enabled=off
sql_slave_skip_counter = 0

Answer 2

query table A, and then loop over the roughly 4000 results and for each one do a query on table B.

Classic "1+N Query" scenario.
Unperformant. Untunable. Untenable.

... this will be replaced with a join once the below problem is resolved ...

Forget it. There is nothing that you, as a DBA, can do to improve this.
It must be rewritten.

Why?

To anything takes a finite amount of time.
To do the same thing a thousand times takes [at least] a thousand times as long.

And that's what the database is doing.
It goes and gets record #1 from your set.
Then it goes and gets record #2.
Then it goes and gets record #3.
Then it goes and gets record #4.
Then it goes and gets record #5.
And so on ...

To retrieve 4000 records in series in this way will takes ages, as you've discovered.
Perversely, though, the database is [probably] perfectly happy with this. It's [probably] being asked to get data from a record based on a single [ID] value in a unique indexed [Primary Key] field. Life simply doesn't get much better for an Application Database!
But to the User, the Application is running like a slug.

You listed a whole bunch of server parameters and such-like.
In my experience:

• Twiddling with these settings might get you 2 or 3 Percentage Points improvement.
• Rewriting the query (using the join you're already considering) could get you 2 or 3 Orders of Magnitude improvement.

YMMV.