MySQL V8 replication lagging waiting for handler commit

Question

let me start with some background.

We've decided to upgrade our Master DB to a more performant machine. We got a server with 1.5TB of RAM, Quad Intel(R) Xeon(R) Gold 6254 and IO is all NVMe drives. Our current environment is on MySQL 5.7.30 which is what I installed on this new server. I activated it as a READ server first just to see how it behaves. I based my config on existing master server with added slave flags. After a few days we get complaints of random slow downs in our main application. What we discovered is that slave was lagging but that drop tables seemed to be locking the environment. Took it off the read pool to see if I can figure out the issue

After doing some research we thought the issue was this bug. We were always planning on upgrading to V8 so figured I may as well do it now and get it over with. We upgraded to V8.0.22 and again re-activated the new server on the network. Again after a few days it starts to slow down dropping tables and inserts. Since this is V8 we're seeing a lot of waiting for handler commit. After researching that state we found some docs saying it may be range_optimizer_max_mem_size the issue. We set it to 0, restarted mysql and waited. A day later slow downs again.

Started looking at the OS (centos 7.8), maybe open files is not enough. Looked and we did set it to over 1M open files. We did notice that we set the rule on the mysql user but systemctl has it's own setting. Set it at systemctl level (/lib/systemd/system/mysqld.service && /etc/systemd/system/mysqld.service.d/limits.conf) and restarted mysql. A day passes and slow down re-appears. Now though the server can't even keep up with the replication let alone additional traffic.

I thought it was my multi threaded replication (as we have 4 primary databases) so I dropped it to single threaded. All that did was make show slave status always show Slave_SQL_Running_State: waiting for handler commit.

At this stage I'm just stumped at what's happening. The new server replication just falling behind more and more and show full processlist always has queries with either waiting for handler commit or checking permissions. What seems the slowest is drop tables though. I can see a drop tables hanging in the process list for 3-5 seconds

State: waiting for handler commit
Info: DROP TABLE IF EXISTS crm.invalidPhoneNumbersCompiled_TMP,crm.invalidPhoneNumbersCompiled_OLD /* generated by server */

We also found this on stackoverflow and went ahead and set all the variables on our server but same result.

On my PMM I can't see anything out of the ordinary on either OS overview or MySQL overview. The server is practically idle and replication just lagging. IO is idle 99.9% of the time and the load is not even a blip on it.

my.cnf

INNO Engine Status

Sample log

UPDATE 1

Here's the status Here are the variable

Replication finally caught up as the load of the day subsided. Table size doesn't seem to impact drop length. A lot of the time it's just a temp table as an intermediate for a batch update.

UPDATE 2

File limits was one of the first things I looked at. Here's the ulimit data

 ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 6184343
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 100000
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

Also since it's on centos7, here's the systemctl limits (I tried 100K all the way to 10M)

[Service]
LimitNOFILE=10000000

Here is /etc/security/limits.conf

mysql soft nofile 200000
mysql hard nofile 10000000

Here is lsof -u mysql | wc -l => 6200 and slave lag is at 3635 seconds behind master

Another interesting thing is last night around 17h it decided to unblock and what we saw was network traffic increase on it

UPDATE 3

Replica Status

UPDATE 4

Process Limits

UPDATE 5

Came in this AM and server was 12000 seconds behind master and the bandwidth usage was as usual almost nothing. Around 11AM it unblocked (no idea why) and replication started catching up

UPDATE 6

Working with some outside consultants on the issue and I think we've at least identified the problem. It's definitely an INNODB issue and pretty sure it involves TABLESPACE lookups. Take a look at this to see the problem in it's full glory. Notice that dropping and creating MyISAM tables is instant, doing it on INNO tables 3-10 seconds. Then the best part, disable bin log and do the create/drop INNO and INSTANT. The one difference between all my other read servers vs this one is that they are all purely read and don't log binary (just relay). I've disabled BIN LOG on this one and restarted it now, flying for now. Will monitor for 2-3 days as it's never gone that long without crapping out. At least I know where the issue is at even if I don't know why yet

UPDATE 7

So if anyone else has a similar issue, I'm pretty sure I figured it out. If you search drop table innodb bugs you'll see issues since 2008. After reading code and finding a super helpful article from Percona I think I figured out what is happening. INNO has an adaptive hash index which is supposed to help speed up queries making INNO more like an in memory DB. Issue is on a drop table INNO needs to ensure all transactions with that table are complete before executing the drop. When it does this it actually locks the entire DB (many bug docs say they resolved this but as of 8.0.22 it's exactly the issue I was seeing) and since it's locked you get replication latency. Interestingly enough this issue is on all of my servers but for some reason way more evident on my big ram server. Disabling innodb_adaptive_hash_index automatically caused the server to start catching up. I am now running replication + binlogging on the slave for over 2 days with 0 lag. I am waiting until mid next week to yell victory over this bug.

On my other servers the issue is weirder and harder to find. You can do 20 drop/creates of simple 1 column table and randomly 1 will take 3-4 seconds. It's why I never noticed it on any of my other servers. I think 64 buffer pool instances and over 200GB inno buffer makes the issue visible. Might be due to the fact I have thousands of tables also. Interestingly enough when I put my buffer pool to 128GB I still saw the issue and that was due to bin logging. Replication + Binlogging with adaptive hash on makes the issue super visible. I am left wondering if innodb_adaptive_flushing also slows things down? For now it's on and everything seems to work.

If by mid week I see no lag I will mark this issue resolved :)

Answer 1

So for anyone finding this issue and are in the same boat as me I can tell you that disabling innodb_adaptive_hash_index is the solution. After disabling it my server has not fallen behind once and the issue is absolutely with the Create/Drop of INNODB tables.

Hopefully this will help someone else in the long run, was a pain in the a** to find

Answer 2

Rate Per Second = RPS

Suggestions to consider for your my.cnf [mysqld] section

innodb_io_capacity=30000  # from 6000 for higher IOPS with your NVME devices

key_buffer_size=4G  # from ~ 64G since only 2% has been used
key_cache_age_threshold=7200   # from 300 seconds before age out
key_cache_block_size=16384  # from 1024 to minimize number of blocks to manage
key_cache_division_limit=50  # from 100 for Hot/Warm cache

these changes will reduce key_reads well below current 29 reads per second. For additional suggestions view my profile, Network profile for contact info and free downloadable Utility Scripts to assist with performance tuning. Tables are being scanned 7 times per second, indexes may provide relief. EXPLAIN SELECT (query) will help identify missing indexes.

Answer 3

Analysis of STATUS and VARIABLES:

Observations:

• Version: 8.0.22
• 1500 GB of RAM
• Uptime = 07:48:45; some GLOBAL STATUS values may not be meaningful yet.
• You are not running on Windows.
• Running 64-bit version
• It appears that you are running both MyISAM and InnoDB.

The More Important Issues:

Migrate tables from MyISAM to InnoDB. (Note: MySQL 8.0 removes MyISAM.)

Unless there are more distinct tables to open, the aggressive raising of table_open_cache was a waste. Open_tables is only 3089.

Increase binlog_stmt_cache_size to, say, 1M. Do you have a lot of "big" transactions?

innodb_page_cleaners = 64 (to match "instances")

innodb_buffer_pool_size is much larger than necessary. How much InnoDB data do you have? It sounds like less than 100MB, not 10000MB. (Shrinking the buffer_pool, plus associated settings, won't make any difference. This is more point out that 1.5TB is overkill.)

innodb_max_dirty_pages_pct = 1 is rather agressive. Did he help? Hurt?

See if some groups of statements can be artificially combined into transactions -- to avoid some of the I/O overhead.

With NVMe drives, I would expect innodb_flush_neighbors = 0 to be slightly better than 2.

Aborted_connects / Connections = 73% -- very high

thread_cache_size = 1800 is overkill considering that Max_used_connections = 6. And that says that no more than about 6 of your 144 cores were being used simultaneously.

DROPping 12 tables per second? Also, some other DDL statements are unusually frequently used.

transaction_isolation = READ-UNCOMMITTED is unusual; was it deliberately chosen?

Details and other observations:

Conversion from MyISAM to InnoDB ( (key_buffer_size - 1.2 * Key_blocks_used * 1024) ) = ((65536M - 1.2 * 941173 * 1024)) / 1536000M = 4.2% -- Percent of RAM wasted in key_buffer. -- Decrease key_buffer_size (now 68719476736).

( Key_reads + Key_writes + Innodb_pages_read + Innodb_pages_written + Innodb_dblwr_writes + Innodb_buffer_pool_pages_flushed ) = (825047 + 14132741 + 519455 + 3947009 + 594784 + 3885938) / 28125 = 849 /sec -- IOPs? -- If the hardware can handle it, set innodb_io_capacity (now 6000) to about this value.

( Opened_tables ) = 133,638 / 28125 = 4.8 /sec -- Frequency of opening Tables -- increase table_open_cache (now 100000)

( Opened_table_definitions ) = 260,203 / 28125 = 9.3 /sec -- Frequency of opening .frm files -- Increase table_definition_cache (now 8000) and/or table_open_cache (now 100000).

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

( Open_tables / table_open_cache ) = 3,089 / 100000 = 3.1% -- Cache usage (open tables + tmp tables) -- Optionally lower table_open_cache (now 100000)

( Binlog_stmt_cache_disk_use ) = 31,755 / 28125 = 1.1 /sec -- Freq of non-transactional binlog cache spilling to disk during transactions -- Increase binlog_stmt_cache_size (now 32768).

( 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_buffer_pool_pages_free * 16384 / innodb_buffer_pool_size ) = 68,530,659 * 16384 / 1179648M = 90.8% -- buffer pool free -- buffer_pool_size is bigger than working set; could decrease it

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

( Innodb_buffer_pool_pages_free / Innodb_buffer_pool_pages_total ) = 68,530,659 / 72M = 90.8% -- Pct of buffer_pool currently not in use -- innodb_buffer_pool_size (now 1236950581248) is bigger than necessary?

( innodb_io_capacity_max / innodb_io_capacity ) = 40,000 / 6000 = 6.67 -- 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_pages_flushed) ) = ((375278 + 3885938) ) / 28125 = 151 /sec -- InnoDB I/O ( Innodb_buffer_pool_pages_flushed ) = 3,885,938 / 28125 = 138 /sec -- Writes (flushes)

( innodb_change_buffer_max_size ) = 50 -- Percent of buffer_pool that is used for "change buffer" -- a write cache for index changes.

( Innodb_buffer_pool_bytes_data / innodb_buffer_pool_size ) = 113,997,725,696 / 1179648M = 9.2% -- Percent of buffer pool taken up by data -- A small percent may indicate that the buffer_pool is unnecessarily big.

( Innodb_pages_written/Innodb_data_writes ) = 3,947,009/204503857 = 1.9% -- Seems like these values should be equal?

( Innodb_os_log_written ) = 264,829,232,640 / 28125 = 9416150 /sec -- This is an indicator of how busy InnoDB is. -- Very busy InnoDB.

( innodb_log_buffer_size ) = 1024M -- Suggest 2MB-64MB, and at least as big as biggest blob set in transactions.

( Innodb_log_writes ) = 199,642,879 / 28125 = 7098 /sec -- Very high

( Innodb_dblwr_writes ) = 594,784 / 28125 = 21 /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 ) = 60 -- 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.

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

( join_buffer_size ) = 262,144 / 1536000M = 0.00% -- 0-N per thread. May speed up JOINs (better to fix queries/indexes) (all engines) Used for index scan, range index scan, full table scan, each full JOIN, etc. -- If large, decrease join_buffer_size (now 262144) to avoid memory pressure. Suggest less than 1% of RAM. If small, increase to 0.01% of RAM to improve some queries.

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

( net_buffer_length / max_allowed_packet ) = 16,384 / 1024M = 0.00%

( bulk_insert_buffer_size ) = 8 / 1536000M = 0.00% -- Buffer for multi-row INSERTs and LOAD DATA -- Too big could threaten RAM size. Too small could hinder such operations.

( Key_blocks_used * 1024 / key_buffer_size ) = 941,173 * 1024 / 65536M = 1.4% -- Percent of key_buffer used . High-water-mark. -- Lower key_buffer_size (now 68719476736) to avoid unnecessary memory usage.

( Key_writes / Key_write_requests ) = 14,132,741 / 28999183 = 48.7% -- key_buffer effectiveness for writes -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 68719476736).

( Key_reads ) = 825,047 / 28125 = 29 /sec -- MyISAM index read (from disk) rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 68719476736).

( Key_writes ) = 14,132,741 / 28125 = 502 /sec -- MyISAM index write (to disk) rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 68719476736).

( Key_reads + Key_writes ) = (825047 + 14132741) / 28125 = 531 /sec -- MyISAM index I/O rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 68719476736).

( (Queries-Questions)/Queries ) = (18774846-167787)/18774846 = 99.1% -- Fraction of queries that are inside Stored Routines. -- (Not bad if high; but it impacts the validity of some other conclusions.)

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

( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (2249849 + 3957040 + 228264 + 161) / 6345757 = 1.01 -- Statements per Commit (assuming all InnoDB) -- Low: Might help to group queries together in transactions; High: long transactions strain various things.

( Select_scan ) = 190,626 / 28125 = 6.8 /sec -- full table scans -- Add indexes / optimize queries (unless they are tiny tables)

( Select_scan / Com_select ) = 190,626 / 166472 = 114.5% -- % of selects doing full table scan. (May be fooled by Stored Routines.) -- Add indexes / optimize queries

( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (2249849 + 228264 + 36 + 161 + 3957040 + 94) / 28125 = 228 /sec -- writes/sec -- 50 writes/sec + log flushes will probably max out I/O write capacity of normal drives

( Com_alter_table ) = 1,892 / 28125 = 0.067 /sec -- Why so many ALTERs?

( Com__biggest ) = Com__biggest = Com_begin -- Which of the "Com_" metrics is biggest. -- Normally it is Com_select (now 166472). 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)

( expire_logs_days ) = 0 -- How soon to automatically purge binlog (after this many days). Being replaced by binlog_expire_logs_seconds. -- Too large (or zero) = consumes disk space; too small = need to respond quickly to network/machine crash. (Not relevant if log_bin (now ON) = OFF)

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

( log_slow_slave_statements ) = log_slow_slave_statements = OFF -- (5.6.11, 5.7.1) By default, replicated statements won't show up in the slowlog; this causes them to show. -- It can be helpful in the slowlog to see writes that could be interfering with Replica reads.

( Aborted_connects / Connections ) = 11,684 / 16001 = 73.0% -- Perhaps a hacker is trying to break in? (Attempts to connect)

( thread_cache_size / Max_used_connections ) = 1,800 / 6 = 30000.0% -- There is no advantage in having the thread cache bigger than your likely number of connections. Wasting space is the disadvantage.

Abnormally small:

Com_show_tables = 0
Handler_read_next / Handler_read_key = 0.296
Handler_read_rnd_next / Handler_read_rnd = 1.58
Innodb_buffer_pool_reads * innodb_page_size / innodb_buffer_pool_size = 0.50%
binlog_expire_logs_seconds = 86,400
innodb_lru_scan_depth / innodb_io_capacity = 0.0167
optimizer_search_depth = 0
range_optimizer_max_mem_size = 0

Abnormally large:

1.2 * Key_blocks_used * 1024 = 1,102.9MB
Binlog_cache_use = 119 /sec
Binlog_stmt_cache_use = 107 /sec
Com_alter_table + Com_flush = 0.067 /sec
Com_begin = 225 /sec
Com_commit = 225 /sec
Com_commit + Com_rollback = 225 /sec
Com_create_db = 0.13 /HR
Com_create_event = 0.38 /HR
Com_create_function = 0.38 /HR
Com_create_table = 5.1 /sec
Com_dealloc_sql = 4.6 /HR
Com_drop_event = 0.38 /HR
Com_drop_function = 0.38 /HR
Com_drop_index = 1.5 /HR
Com_drop_table = 12 /sec
Com_execute_sql = 4.6 /HR
Com_prepare_sql = 4.6 /HR
Com_rename_table = 0.22 /sec
Com_show_binlogs = 60 /HR
Com_show_slave_status = 0.23 /sec
Com_show_status = 1.1 /sec
Com_slave_start = 0.26 /HR
Com_slave_stop = 0.26 /HR
Com_truncate = 60 /HR
Com_update = 140 /sec
Handler_commit/Questions = 14421.6%
Handler_delete = 1943 /sec
Handler_prepare = 481 /sec
Handler_read_rnd = 7152 /sec
Handler_update = 5494 /sec
Handler_write = 30580 /sec
Innodb_buffer_pool_bytes_data = 4053252 /sec
Innodb_buffer_pool_pages_data = 6.96e+6
Innodb_buffer_pool_pages_dirty = 163,480
Innodb_buffer_pool_pages_free = 6.85e+7
Innodb_buffer_pool_pages_total = 7.55e+7
Innodb_buffer_pool_write_requests = 138416 /sec
Innodb_buffer_pool_write_requests / Innodb_buffer_pool_pages_flushed = 1,001
Innodb_data_pending_fsyncs = 1,828
Innodb_data_writes = 7271 /sec
Innodb_data_writes - Innodb_log_writes - Innodb_dblwr_writes = 151 /sec
Innodb_data_written = 13547354 /sec
Innodb_dblwr_pages_written = 138 /sec
Innodb_log_write_requests = 116170 /sec
Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group = 16,163.9MB
Innodb_pages_created = 231 /sec
Innodb_pages_written = 140 /sec
Innodb_rows_deleted = 1913 /sec
Innodb_rows_deleted + Innodb_rows_inserted = 30712 /sec
Innodb_rows_inserted = 28798 /sec
Innodb_rows_updated = 5267 /sec
Innodb_system_rows_deleted = 11 /sec
Innodb_system_rows_inserted = 11 /sec
Innodb_system_rows_read = 4.83e+6
Innodb_system_rows_updated = 128 /sec
Key_blocks_unused = 5.4e+7
Key_blocks_used = 941,173
Key_write_requests = 1031 /sec
Open_files = 2,392
Slave_open_temp_tables = 57
Ssl_accepts = 930
Ssl_finished_accepts = 930
Ssl_session_cache_overflows = 451
Ssl_used_session_cache_entries = 128
back_log / max_connections = 100.0%
binlog_group_commit_sync_delay = 10,000
eq_range_index_dive_limit = 5,000
host_cache_size = 903
innodb_buffer_pool_chunk_size = 1024MB
innodb_flush_log_at_timeout = 30
innodb_flushing_avg_loops = 60
innodb_io_capacity_max = 40,000
innodb_open_files = 100,000
innodb_read_io_threads = 64
innodb_write_io_threads = 64
max_error_count = 1,024
max_heap_table_size = 512MB
max_length_for_sort_data = 4,096
min(max_heap_table_size, tmp_table_size) = 512MB
net_read_timeout = 3,600
net_write_timeout = 3,600
optimizer_trace_offset = --1
performance_schema_error_size = 4,808
performance_schema_max_cond_classes = 100
performance_schema_max_mutex_classes = 300
performance_schema_max_rwlock_classes = 60
performance_schema_max_stage_classes = 175
performance_schema_max_statement_classes = 218
performance_schema_max_thread_classes = 100
schema_definition_cache = 100,000
slave_parallel_workers = 6
slave_pending_jobs_size_max = 4096MB
table_definition_cache = 8,000
tablespace_definition_cache = 15,000

Abnormal strings:

binlog_row_image = MINIMAL
event_scheduler = ON
have_query_cache = NO
init_file = /var/lib/mysql/initMysqlScripts.sql
innodb_fast_shutdown = 1
innodb_log_compressed_pages = OFF
innodb_tmpdir = /localbackup/mysql/tmp/inno/
log_bin_trust_function_creators = ON
optimizer_trace = enabled=off,one_line=off
optimizer_trace_features = greedy_search=on, range_optimizer=on, dynamic_range=on, repeated_subselect=on
slave_compressed_protocol = ON
slave_rows_search_algorithms = INDEX_SCAN,HASH_SCAN
slave_sql_verify_checksum = OFF
transaction_isolation = READ-UNCOMMITTED