MariaDB 10.1 shutdown stuck at "Event Scheduler: Purging the queue"

Question

I have read many different questions about slow MariaDB/MySQL shutdown, but I have not found an answer which solves my problem yet.

On one of our servers with the highest load, when I issue a stop command for MariaDB, in the logfile I see:

2020-05-26 13:26:02 140304972457728 [Note] /opt/lampp/sbin/mysqld: Normal shutdown
2020-05-26 13:26:02 140304972457728 [Note] Event Scheduler: Purging the queue. 0 events

From there, it won't move, at least not in the 15-20 minutes I waited, and I usually have to kill the mysqld daemon.

By following other questions and answers found online, the shutdown command is given through the mysqladmin command via TCP (instead of socket), and also I check that the dirty pages are at or close to zero.

mysqladmin --user=shutdown --password=xxx --port=3306 --host=127.0.0.1 --protocol=tcp shutdown

The log does not show any specific error or warning message which might explain such a slow shutdown, and when monitoring CPU/RAM usage during the command, the server seems just idle.

I also checked the OS logs, but found nothing unusual.

Finally, the server uses MariaDB 10.1.36 and hosts 10 databases, each a clone of the other, which are made of ~2000 tables each, all InnoDB; it's a dual core server with 8 GB RAM and CentOS 7.8 as its OS.

innodb_fast_shutdown is set to 1.

What can I do to lower the database shutdown time to a more acceptable 1-2 minutes?

Here is the database configuration from my.cnf:

innodb_data_home_dir = /opt/agews64/data/mysql/
innodb_data_file_path = ibdata1:10M:autoextend
innodb_log_group_home_dir = /opt/agews64/data/mysql/
innodb_lock_wait_timeout = 60
innodb_file_format = Barracuda
innodb_file_format_max = Barracuda
innodb_large_prefix = 1
innodb_fast_shutdown = 1

default_storage_engine = InnoDB
innodb_flush_log_at_trx_commit = 1
sync_binlog = 0
innodb_flush_method = O_DIRECT
#innodb_thread_concurrency = 8
innodb_io_capacity = 1000
innodb_io_capacity_max = 2000
innodb_stats_on_metadata = 0
innodb_buffer_pool_dump_at_shutdown = 0
innodb_buffer_pool_load_at_startup = 0
innodb_buffer_pool_dump_pct = 100
innodb_adaptive_hash_index_partitions = 8
innodb_checksum_algorithm = crc32
innodb_log_checksum_algorithm = crc32
#table_open_cache_instances = 16
innodb_read_io_threads = 8
innodb_write_io_threads = 4
innodb_max_dirty_pages_pct = 90
innodb_max_dirty_pages_pct_lwm = 10

max_connections = 20
sort_buffer_size = 16M
read_buffer_size = 1M
read_rnd_buffer_size = 4M
join_buffer_size = 4M
thread_stack = 512K
binlog_cache_size = 32K
myisam_sort_buffer_size = 1M
net_buffer_length = 16K
wait_timeout = 3600
interactive_timeout = 3600
# BUFFER GLOBALI
key_buffer_size = 64M
query_cache_type = 0
query_cache_size = 0
tmp_table_size = 64M
max_heap_table_size = 64M
aria_pagecache_buffer_size = 128M
innodb_buffer_pool_size = 3072M
innodb_buffer_pool_instances = 3
innodb_log_file_size = 256M
innodb_log_files_in_group = 3
innodb_log_buffer_size = 64M
table_open_cache = 30000
table_definition_cache = 15400
open_files_limit = 90000
innodb_open_files = 90000
thread_cache_size = 8
thread_handling = one-thread-per-connection
max_sp_recursion_depth = 16

log_output = NONE
general_log = 0
slow_query_log = 0
#slow_query_log_file = /opt/agews64/logs/slow_queries.log
long_query_time = 3
min_examined_row_limit = 0
log_queries_not_using_indexes = 0
log_slow_admin_statements = 0

plugin_load_add = query_response_time
query_response_time_stats = 0
userstat = 0
#innodb_monitor_enable = all
performance_schema = 1
performance_schema_instrument = "%=off"
performance_schema_consumer_global_instrumentation = 0
performance_schema_consumer_thread_instrumentation = 0
performance_schema_consumer_events_stages_current = 0
performance_schema_consumer_events_stages_history = 0
performance_schema_consumer_events_stages_history_long = 0
performance_schema_consumer_events_statements_current = 0
performance_schema_consumer_events_statements_history = 0
performance_schema_consumer_events_statements_history_long = 0
performance_schema_consumer_events_waits_current = 0
performance_schema_consumer_events_waits_history = 0
performance_schema_consumer_events_waits_history_long = 0
performance_schema_consumer_statements_digest = 0
performance_schema_events_stages_history_size = 100
performance_schema_events_stages_history_long_size = 10000
performance_schema_events_statements_history_size = 100
performance_schema_events_statements_history_long_size = 10000
performance_schema_events_waits_history_size = 100
performance_schema_events_waits_history_long_size = 10000
performance_schema_digests_size = -1

plugin_load_add = "federated=ha_federatedx.so"
# gestione della criptazione dei dati
plugin_load_add = file_key_management
file_key_management_filename = /opt/agews64/data/mysql/.keys
file_key_management_filekey = FILE:/opt/agews64/etc/mysql/.key
file_key_management_encryption_algorithm = aes_ctr
innodb_encrypt_tables = OFF
innodb_encrypt_log = 0
encrypt_tmp_disk_tables = 0
encrypt_tmp_files = 0
encrypt_binlog = 0

Answer 1

MySQL also have the same problem. I encountered the same problem in MySQl5.7.19. When shutdown a mysql server, it stuck at "Event Scheduler: Purging the queue. 0 events". In MySQL5.7.25 offical version， the release note say，they fix a bug for a slave cann't shutdown:

Replication: If autocommit was set to 0 for a replication slave or Group Replication group member where GTIDs were in use and super_read_only=ON was set, server shutdown was prevented by a transaction that did not complete. The transaction was attempting to save GTIDs to the mysql.gtid_executed table, but the update failed because super_read_only=ON was set. (With autocommit set to 1, the transaction would complete in this situation, and the mysql.gtid_executed table would instead be updated at server startup.) Now, the check for the super_read_only setting is skipped for this task, so the transaction is able to save the GTIDs to the mysql.gtid_executed table and complete regardless of the combination of super_read_only and autocommit settings. (Bug #28183718)

https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-25.html

Maybe you can check about is your problem is same as the offical say.

But, in my environment, it is not same as the above env. My MySQL server is a replication slave, but it set autocommit = 1.

I read the mysql code, the sever may be stuck at wait_till_no_thd(), but I cann't do more analysis. I guess there may be have other bugs in it.

|----close_connections
|----Events::deinit()/*print log: Event Scheduler: Purging the queue*****/
|----thd_manager->wait_till_no_thd()
    |----while (get_thd_count() > 0){mysql_cond_wait(&COND_thd_list, &LOCK_thd_list);}/*wait untiy all thd exit, thd count == 0*/

Answer 2

I stumbled on the same issue on MySQL 5.7.

The log was stuck on the "Purging queue..." line, while I had issued a restart command to the service & right after a DB to DB copy operation was cut off by Nginx/phpMyAdmin after taking too long run (PMA timed out), but essentially the underlying operation in MySQL was still running.

After 5 mins of no inactivity on the restart command, I simply did a "Ctrl+C" on the "service mysql restart" command to stop the sequence. After that, and since I was tailing the MySQL log, I saw the service get unstuck, it stopped and then resumed properly.