MariaDB server experiences some sort of freezes happening sporadically with no visible reason or connection to outside factors (load, etc). After a thorough investigation the common picture for those freezes is the following:
- There are many different queries (all of them are lightweight select using an index or plain inserts) that got frozen waiting for something.
- After this something is over, queries are processed pretty fast.
- Freeze lasts for about 5-10 seconds.
---TRANSACTION 35712946030, not started
...
--TRANSACTION 35712946031, not started flushing log
...
---TRANSACTION 35712945941, not started
...
---TRANSACTION 35712945772, not started flushing log
mysql tables in use 1, locked 1
MySQL thread id 1904927, OS thread handle 0x7f437b04b700, query id 88121305 localhost dbu_user query end
INSERT INTO t_log <just plain values>
...
---TRANSACTION 35712945932, not started flushing log
mysql tables in use 1, locked 1
MySQL thread id 1904895, OS thread handle 0x7f4371568700, query id 88121792 localhost dbu_user query end
INSERT INTO t_log <just plain values>
...
---TRANSACTION 35712945902, not started flushing log
mysql tables in use 1, locked 1
MySQL thread id 1904887, OS thread handle 0x7f3dace37700, query id 88121710 localhost dbu_user query end
INSERT INTO t_log <just plain values>
...
---TRANSACTION 35712946032, not started
MySQL thread id 1904891, OS thread handle 0x7f3de3d9d700, query id 88122203 localhost dbu_user
---TRANSACTION 35712946047, not started
MySQL thread id 1904899, OS thread handle 0x7f437da37700, query id 88122191 localhost dbu_user
---TRANSACTION 35712945339, not started
MySQL thread id 1904898, OS thread handle 0x7f3de3f14700, query id 88122121 localhost dbu_user
...
So every INSERT transaction says:
not started flushing log
Other says:
not started
More of SHOW ENGINE INNODB STATUS:
MySQL thread id 1, OS thread handle 0x7f437dacd700, query id 0 Waiting for requests
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 1; buffer pool: 1
6994083 OS file reads, 2285417 OS file writes, 234347 OS fsyncs
11.60 reads/s, 16384 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
0 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
0 out of 1000 descriptors used
Main thread process no. 1493, id 139904004646656, state: sleeping
Number of rows inserted 5295384, updated 429036, deleted 692576, read 1748285626
12.60 inserts/s, 1.55 updates/s, 0.00 deletes/s, 27032.25 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
Most of the times there is the following row for main process:
Main thread process no. 1493, id 139904004646656, state: flushing log
Header says:
=====================================
2021-05-21 17:39:59 7f3df0fff700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 17 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 50917 srv_active, 0 srv_shutdown, 253 srv_idle
srv_master_thread log flush and writes: 51168
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 96271
OS WAIT ARRAY INFO: signal count 282014
Mutex spin waits 1951655, rounds 3496412, OS waits 64297
RW-shared spins 238185, rounds 1674512, OS waits 21055
RW-excl spins 81399, rounds 1006087, OS waits 10118
Spin rounds per wait: 1.79 mutex, 7.03 RW-shared, 12.36 RW-excl
SELECT VERSION():
VERSION()
10.1.48-MariaDB-0+deb9u2
SHOW GLOBAL STATUS:
Variable_name Value
***
Aria_pagecache_blocks_not_flushed 0
Aria_pagecache_blocks_unused 15706
Aria_pagecache_blocks_used 15706
Aria_pagecache_read_requests 338868768
Aria_pagecache_reads 30678281
Aria_pagecache_write_requests 69095480
Aria_pagecache_writes 370410
Aria_transaction_log_syncs 13
Binlog_commits 0
Binlog_group_commits 0
Binlog_group_commit_trigger_count 0
Binlog_group_commit_trigger_lock_wait 0
Binlog_group_commit_trigger_timeout 0
Binlog_snapshot_file
Binlog_snapshot_position 0
Binlog_bytes_written 0
Binlog_cache_disk_use 0
Binlog_cache_use 0
Binlog_stmt_cache_disk_use 0
Binlog_stmt_cache_use 0
Busy_time 0.000000
Bytes_received 18590540106
Bytes_sent 181560472399
Com_admin_commands 3
Com_alter_db 0
Com_alter_db_upgrade 0
Com_alter_event 0
Com_alter_function 0
Com_alter_procedure 0
Com_alter_server 0
Com_alter_table 59
Com_alter_tablespace 0
Com_analyze 0
Com_assign_to_keycache 0
Com_begin 15
Com_binlog 0
Com_call_procedure 0
Com_change_db 6264
Com_change_master 0
Com_check 0
Com_checksum 0
Com_commit 14
Com_compound_sql 0
Com_create_db 0
Com_create_event 0
Com_create_function 0
Com_create_index 0
Com_create_procedure 0
Com_create_role 0
Com_create_server 0
Com_create_table 1
Com_create_temporary_table 0
Com_create_trigger 0
Com_create_udf 0
Com_create_user 0
Com_create_view 0
Com_dealloc_sql 0
Com_delete 3
Com_delete_multi 4
Com_do 0
Com_drop_db 0
Com_drop_event 0
Com_drop_function 0
Com_drop_index 0
Com_drop_procedure 0
Com_drop_role 0
Com_drop_server 0
Com_drop_table 1
Com_drop_temporary_table 0
Com_drop_trigger 0
Com_drop_user 0
Com_drop_view 0
Com_empty_query 2
Com_execute_sql 0
Com_flush 0
Com_get_diagnostics 0
Com_grant 0
Com_grant_role 0
Com_ha_close 0
Com_ha_open 0
Com_ha_read 0
Com_help 0
Com_insert 1967555
Com_insert_select 847
Com_install_plugin 0
Com_kill 3
Com_load 0
Com_lock_tables 0
Com_optimize 0
Com_preload_keys 0
Com_prepare_sql 0
Com_purge 0
Com_purge_before_date 0
Com_release_savepoint 1
Com_rename_table 0
Com_rename_user 0
Com_repair 0
Com_replace 1
Com_replace_select 0
Com_reset 0
Com_resignal 0
Com_revoke 0
Com_revoke_all 0
Com_revoke_role 0
Com_rollback 0
Com_rollback_to_savepoint 2
Com_savepoint 1
Com_select 29384364
Com_set_option 4278953
Com_show_authors 0
Com_show_binlog_events 0
Com_show_binlogs 0
Com_show_charsets 0
Com_show_collations 50
Com_show_contributors 0
Com_show_create_db 131
Com_show_create_event 0
Com_show_create_func 0
Com_show_create_proc 0
Com_show_create_table 30281755
Com_show_create_trigger 0
Com_show_databases 6
Com_show_engine_logs 0
Com_show_engine_mutex 0
Com_show_engine_status 20
Com_show_errors 0
Com_show_events 30
Com_show_explain 0
Com_show_fields 30282518
Com_show_function_status 1
Com_show_generic 0
Com_show_grants 0
Com_show_keys 119
Com_show_master_status 0
Com_show_open_tables 0
Com_show_plugins 0
Com_show_privileges 0
Com_show_procedure_status 1
Com_show_processlist 116
Com_show_profile 0
Com_show_profiles 0
Com_show_relaylog_events 0
Com_show_slave_hosts 3
Com_show_slave_status 3
Com_show_status 16
Com_show_storage_engines 6
Com_show_table_status 104
Com_show_tables 0
Com_show_triggers 22
Com_show_variables 26
Com_show_warnings 141
Com_shutdown 0
Com_signal 0
Com_start_all_slaves 0
Com_start_slave 0
Com_stmt_close 0
Com_stmt_execute 0
Com_stmt_fetch 0
Com_stmt_prepare 0
Com_stmt_reprepare 0
Com_stmt_reset 0
Com_stmt_send_long_data 0
Com_stop_all_slaves 0
Com_stop_slave 0
Com_truncate 6
Com_uninstall_plugin 0
Com_unlock_tables 1
Com_update 319512
Com_update_multi 788
Com_xa_commit 0
Com_xa_end 0
Com_xa_prepare 0
Com_xa_recover 0
Com_xa_rollback 0
Com_xa_start 0
Compression OFF
Connection_errors_accept 0
Connection_errors_internal 0
Connection_errors_max_connections 0
Connection_errors_peer_address 0
Connection_errors_select 0
Connection_errors_tcpwrap 0
Connections 2141938
Cpu_time 0.000000
Created_tmp_disk_tables 30318872
Created_tmp_files 38088
Created_tmp_tables 36812016
Delayed_errors 0
Delayed_insert_threads 0
Delayed_writes 0
Delete_scan 1
Empty_queries 6291088
Executed_events 0
Executed_triggers 0
Feature_delay_key_write 0
Feature_dynamic_columns 0
Feature_fulltext 0
Feature_gis 0
Feature_locale 0
Feature_subquery 2011
Feature_timezone 3
Feature_trigger 1
Feature_xml 0
Flush_commands 1
Handler_commit 31637906
Handler_delete 692578
Handler_discover 52
Handler_external_lock 0
Handler_icp_attempts 19307656516
Handler_icp_match 62206365
Handler_mrr_init 0
Handler_mrr_key_refills 0
Handler_mrr_rowid_refills 0
Handler_prepare 0
Handler_read_first 3284385
Handler_read_key 258101790
Handler_read_last 4146611
Handler_read_next 1298969205
Handler_read_prev 38190
Handler_read_retry 0
Handler_read_rnd 482143308
Handler_read_rnd_deleted 16887
Handler_read_rnd_next 446790716
Handler_rollback 4
Handler_savepoint 1
Handler_savepoint_rollback 2
Handler_tmp_update 29778550
Handler_tmp_write 359275356
Handler_update 440384
Handler_write 23298394
Innodb_available_undo_logs 128
Innodb_background_log_sync 57342
Innodb_buffer_pool_bytes_data 21139406848
Innodb_buffer_pool_bytes_dirty 204390400
Innodb_buffer_pool_dump_status Dumping buffer pool(s) not yet started
Innodb_buffer_pool_load_status Loading buffer pool(s) not yet started
Innodb_buffer_pool_pages_data 1290247
Innodb_buffer_pool_pages_dirty 12475
Innodb_buffer_pool_pages_flushed 275633
Innodb_buffer_pool_pages_free 20453
Innodb_buffer_pool_pages_lru_flushed 0
Innodb_buffer_pool_pages_made_not_young 133262961
Innodb_buffer_pool_pages_made_young 6416964
Innodb_buffer_pool_pages_misc 0
Innodb_buffer_pool_pages_old 475882
Innodb_buffer_pool_pages_total 1310700
Innodb_buffer_pool_read_ahead 635595
Innodb_buffer_pool_read_ahead_evicted 0
Innodb_buffer_pool_read_ahead_rnd 0
Innodb_buffer_pool_read_requests 3823266111
Innodb_buffer_pool_reads 6800967
Innodb_buffer_pool_wait_free 99906
Innodb_buffer_pool_write_requests 41795423
Innodb_checkpoint_age 198686598
Innodb_checkpoint_max_age 3478212404
Innodb_data_fsyncs 253776
Innodb_data_pending_fsyncs 0
Innodb_data_pending_reads 0
Innodb_data_pending_writes 0
Innodb_data_read 122639356416
Innodb_data_reads 7485133
Innodb_data_writes 2394663
Innodb_data_written 12082536448
Innodb_dblwr_pages_written 277234
Innodb_dblwr_writes 77724
Innodb_deadlocks 0
Innodb_have_atomic_builtins ON
Innodb_history_list_length 29
Innodb_ibuf_discarded_delete_marks 0
Innodb_ibuf_discarded_deletes 0
Innodb_ibuf_discarded_inserts 0
Innodb_ibuf_free_list 232719
Innodb_ibuf_merged_delete_marks 1242585
Innodb_ibuf_merged_deletes 126524
Innodb_ibuf_merged_inserts 63001
Innodb_ibuf_merges 52159
Innodb_ibuf_segment_size 232721
Innodb_ibuf_size 1
Innodb_log_waits 1
Innodb_log_write_requests 4463179
Innodb_log_writes 2031869
Innodb_lsn_current 2668534004820
Innodb_lsn_flushed 2668534003645
Innodb_lsn_last_checkpoint 2668335318222
Innodb_master_thread_active_loops 57090
Innodb_master_thread_idle_loops 253
Innodb_max_trx_id 35716233897
Innodb_mem_adaptive_hash 339996064
Innodb_mem_dictionary 85658368
Innodb_mem_total 22481469440
Innodb_mutex_os_waits 71063
Innodb_mutex_spin_rounds 3743636
Innodb_mutex_spin_waits 2067078
Innodb_oldest_view_low_limit_trx_id 0
Innodb_os_log_fsyncs 64283
Innodb_os_log_pending_fsyncs 0
Innodb_os_log_pending_writes 0
Innodb_os_log_written 2992949248
Innodb_page_size 16384
Innodb_pages_created 62985
Innodb_pages_read 7484347
Innodb_pages0_read 425
Innodb_pages_written 277234
Innodb_purge_trx_id 35716233820
Innodb_purge_undo_no 0
Innodb_read_views_memory 984
Innodb_row_lock_current_waits 0
Innodb_row_lock_time 526
Innodb_row_lock_time_avg 37
Innodb_row_lock_time_max 282
Innodb_row_lock_waits 14
Innodb_rows_deleted 692576
Innodb_rows_inserted 5357728
Innodb_rows_read 1901348483
Innodb_rows_updated 440384
Innodb_system_rows_deleted 0
Innodb_system_rows_inserted 0
Innodb_system_rows_read 0
Innodb_system_rows_updated 0
Innodb_s_lock_os_waits 21170
Innodb_s_lock_spin_rounds 1678379
Innodb_s_lock_spin_waits 238517
Innodb_truncated_status_writes 0
Innodb_x_lock_os_waits 10269
Innodb_x_lock_spin_rounds 1011254
Innodb_x_lock_spin_waits 81605
Innodb_page_compression_saved 0
Innodb_page_compression_trim_sect512 0
Innodb_page_compression_trim_sect1024 0
Innodb_page_compression_trim_sect2048 0
Innodb_page_compression_trim_sect4096 0
Innodb_page_compression_trim_sect8192 0
Innodb_page_compression_trim_sect16384 0
Innodb_page_compression_trim_sect32768 0
Innodb_num_index_pages_written 323915
Innodb_num_non_index_pages_written 2069541
Innodb_num_pages_page_compressed 0
Innodb_num_page_compressed_trim_op 0
Innodb_num_page_compressed_trim_op_saved 0
Innodb_num_pages_page_decompressed 0
Innodb_num_pages_page_compression_error 0
Innodb_num_pages_encrypted 0
Innodb_num_pages_decrypted 0
Innodb_have_lz4 OFF
Innodb_have_lzo OFF
Innodb_have_lzma OFF
Innodb_have_bzip2 OFF
Innodb_have_snappy OFF
Innodb_defragment_compression_failures 0
Innodb_defragment_failures 0
Innodb_defragment_count 0
Innodb_onlineddl_rowlog_rows 0
Innodb_onlineddl_rowlog_pct_used 0
Innodb_onlineddl_pct_progress 0
Innodb_secondary_index_triggered_cluster_reads 232038557
Innodb_secondary_index_triggered_cluster_reads_avoided 0
Innodb_buffered_aio_submitted 635595
Innodb_encryption_rotation_pages_read_from_cache 0
Innodb_encryption_rotation_pages_read_from_disk 0
Innodb_encryption_rotation_pages_modified 0
Innodb_encryption_rotation_pages_flushed 0
Innodb_encryption_rotation_estimated_iops 0
Innodb_encryption_key_rotation_list_length 0
Innodb_encryption_n_merge_blocks_encrypted 0
Innodb_encryption_n_merge_blocks_decrypted 0
Innodb_encryption_n_rowlog_blocks_encrypted 0
Innodb_encryption_n_rowlog_blocks_decrypted 0
Innodb_scrub_background_page_reorganizations 0
Innodb_scrub_background_page_splits 0
Innodb_scrub_background_page_split_failures_underflow 0
Innodb_scrub_background_page_split_failures_out_of_filespace 0
Innodb_scrub_background_page_split_failures_missing_index 0
Innodb_scrub_background_page_split_failures_unknown 0
Innodb_encryption_num_key_requests 0
Key_blocks_not_flushed 0
Key_blocks_unused 53569
Key_blocks_used 9
Key_blocks_warm 0
Key_read_requests 85795
Key_reads 9
Key_write_requests 0
Key_writes 0
Last_query_cost 0.000000
Master_gtid_wait_count 0
Master_gtid_wait_time 0
Master_gtid_wait_timeouts 0
Max_statement_time_exceeded 0
Max_used_connections 149
Memory_used 244375568
Not_flushed_delayed_rows 0
Open_files 132
Open_streams 0
Open_table_definitions 413
Open_tables 867
Opened_files 121314326
Opened_plugin_libraries 0
Opened_table_definitions 452
Opened_tables 1031
Opened_views 1695
***
Prepared_stmt_count 0
Qcache_free_blocks 1
Qcache_free_memory 1031336
Qcache_hits 0
Qcache_inserts 0
Qcache_lowmem_prunes 0
Qcache_not_cached 0
Qcache_queries_in_cache 0
Qcache_total_blocks 1
Queries 98665350
Questions 98665350
Rows_read 1901287392
Rows_sent 732824967
Rows_tmp_read 499084097
Rpl_status AUTH_MASTER
Select_full_join 0
Select_full_range_join 17548
Select_range 9003432
Select_range_check 0
Select_scan 30293630
***
Slow_launch_threads 0
Slow_queries 11828
Sort_merge_passes 19804
Sort_priority_queue_sorts 869093
Sort_range 5142865
Sort_rows 485949805
Sort_scan 6526377
***
Subquery_cache_hit 8
Subquery_cache_miss 5517
Syncs 36
Table_locks_immediate 55939785
Table_locks_waited 0
Tc_log_max_pages_used 0
Tc_log_page_size 4096
Tc_log_page_waits 0
Threadpool_idle_threads 21
Threadpool_threads 24
Threads_cached 0
Threads_connected 11
Threads_created 2664
Threads_running 3
Update_scan 48
Uptime 61512
Uptime_since_flush_status 61512
***
my.cnf is pretty standard, InnoDB settings:
innodb_file_per_table
innodb_buffer_pool_size = 20G
innodb_flush_method = O_DIRECT
innodb_flush_log_at_trx_commit = 2
innodb_buffer_pool_instances = 20
innodb_log_file_size = 2G
innodb_log_buffer_size = 8M
Some output from mysqltuner.pl:
-------- Performance Metrics -----------------------------------------------------------------------
[--] Up for: 17h 14m 39s (99M q [1K qps], 2M conn, TX: 170G, RX: 17G)
[--] Reads / Writes: 92% / 8%
[--] Binary logging is disabled
[--] Physical Memory : 62.8G
[--] Max MySQL memory : 29.3G
[--] Other process memory: 0B
[--] Total buffers: 20.5G global + 34.9M per thread (256 max threads)
[--] P_S Max memory usage: 105M
[--] Galera GCache Max memory usage: 0B
[OK] Maximum reached memory usage: 25.6G (40.82% of installed RAM)
[OK] Maximum possible memory usage: 29.3G (46.63% of installed RAM)
[OK] Overall possible memory usage with other process is compatible with memory available
[OK] Slow queries: 0% (11K/99M)
[OK] Highest usage of available connections: 58% (149/256)
[OK] Aborted connections: 0.00% (16/2163778)
[!!] name resolution is active : a reverse name resolution is made for each new connection and can reduce performance
[OK] Query cache is disabled by default due to mutex contention on multiprocessor machines.
[OK] Sorts requiring temporary tables: 0% (19K temp sorts / 11M sorts)
[OK] No joins without indexes
[!!] Temporary tables created on disk: 82% (30M on disk / 37M total)
[--] Thread cache not used with thread_handling=pool-of-threads
[OK] Table cache hit rate: 84% (868 open / 1K opened)
[OK] table_definition_cache(800) is upper than number of tables(491)
[OK] Open file limit used: 5% (132/2K)
[OK] Table locks acquired immediately: 100% (56M immediate / 56M locks)
InnoDB Metrics:
-------- InnoDB Metrics ----------------------------------------------------------------------------
[--] InnoDB is enabled.
[--] InnoDB Thread Concurrency: 0
[OK] InnoDB File per table is activated
[!!] InnoDB buffer pool / data size: 20.0G/193.6G
[OK] Ratio InnoDB log file size / InnoDB Buffer pool size: 2.0G * 2/20.0G should be equal to 25%
[OK] InnoDB buffer pool instances: 20
[--] InnoDB Buffer Pool Chunk Size not used or defined in your version
[OK] InnoDB Read buffer efficiency: 99.82% (3853979630 hits/ 3860826332 total)
[!!] InnoDB Write Log efficiency: 54.38% (2430712 hits/ 4470120 total)
[!!] InnoDB log waits: 0.00% (1 waits / 2039408 writes)
Everything seems fine, so I must be missing something out. Asking for advice.
UPDATE. Some extra weird data and mutex stats:
=====================================
2021-05-22 21:17:29 7fb9de7ff700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 46933 srv_active, 0 srv_shutdown, 26232 srv_idle
srv_master_thread log flush and writes: 73161
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 83146
--Thread 140435913168640 has waited at trx0sys.ic line 103 for 4.0000 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7fbf117fe968 '&block->lock'
a writer (thread id 140435913168640) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1126
Last time write locked in file trx0sys.ic line 103
Holder thread 0 file not yet reserved line 0
--Thread 140435783866112 has waited at trx0trx.cc line 1057 for 4.0000 seconds the semaphore:
Mutex at 0x7fbf66bbc068 '&trx_sys->mutex', lock var 1
Last time reserved by thread 140435913168640 in file not yet reserved line 0, waiters flag 1
--Thread 140459985676032 has waited at trx0trx.cc line 1057 for 4.0000 seconds the semaphore:
Mutex at 0x7fbf66bbc068 '&trx_sys->mutex', lock var 1
Last time reserved by thread 140435913168640 in file not yet reserved line 0, waiters flag 1
--Thread 140435788166912 has waited at trx0trx.cc line 1057 for 4.0000 seconds the semaphore:
Mutex at 0x7fbf66bbc068 '&trx_sys->mutex', lock var 1
Last time reserved by thread 140435913168640 in file not yet reserved line 0, waiters flag 1
--Thread 140435799533312 has waited at trx0trx.cc line 1057 for 4.0000 seconds the semaphore:
... (post length limits)
OS WAIT ARRAY INFO: signal count 171303
Mutex spin waits 566839, rounds 1843729, OS waits 48137
RW-shared spins 954015, rounds 4867601, OS waits 18698
RW-excl spins 247858, rounds 2764788, OS waits 14386
Spin rounds per wait: 3.25 mutex, 5.10 RW-shared, 11.15 RW-excl
Mutex stats:
show engine innodb mutex
Type Name Status
...
InnoDB &ibuf_mutex os_waits=8
InnoDB &dict_sys->mutex os_waits=152
InnoDB &trx_sys->mutex os_waits=3802
InnoDB &lock_sys->mutex os_waits=95
InnoDB &log_sys->mutex os_waits=11308
InnoDB &buf_pool->flush_state_mutex os_waits=1613
InnoDB &buf_pool->LRU_list_mutex os_waits=7
InnoDB &buf_pool->flush_state_mutex os_waits=2599
InnoDB &buf_pool->LRU_list_mutex os_waits=22
InnoDB &buf_pool->flush_state_mutex os_waits=1406
InnoDB &buf_pool->LRU_list_mutex os_waits=7
InnoDB &buf_pool->flush_state_mutex os_waits=8609
InnoDB &buf_pool->LRU_list_mutex os_waits=63
InnoDB &buf_pool->flush_state_mutex os_waits=428
InnoDB &buf_pool->LRU_list_mutex os_waits=3
InnoDB &buf_pool->flush_state_mutex os_waits=1317
InnoDB &buf_pool->flush_state_mutex os_waits=445
InnoDB &buf_pool->LRU_list_mutex os_waits=1
InnoDB &buf_pool->flush_state_mutex os_waits=3218
InnoDB &buf_pool->LRU_list_mutex os_waits=3
InnoDB &buf_pool->flush_state_mutex os_waits=519
InnoDB &buf_pool->LRU_list_mutex os_waits=3
InnoDB &buf_pool->flush_state_mutex os_waits=628
InnoDB &buf_pool->LRU_list_mutex os_waits=15
InnoDB &buf_pool->flush_state_mutex os_waits=1738
InnoDB &buf_pool->LRU_list_mutex os_waits=4
InnoDB &buf_pool->flush_state_mutex os_waits=4458
InnoDB &buf_pool->LRU_list_mutex os_waits=18
InnoDB &buf_pool->flush_state_mutex os_waits=362
InnoDB &buf_pool->LRU_list_mutex os_waits=4
InnoDB &buf_pool->flush_state_mutex os_waits=214
InnoDB &buf_pool->LRU_list_mutex os_waits=2
InnoDB &buf_pool->flush_state_mutex os_waits=175
InnoDB &buf_pool->LRU_list_mutex os_waits=1
InnoDB &buf_pool->flush_state_mutex os_waits=1310
InnoDB &buf_pool->LRU_list_mutex os_waits=5
InnoDB &buf_pool->flush_state_mutex os_waits=1268
InnoDB &buf_pool->LRU_list_mutex os_waits=15
InnoDB &buf_pool->flush_state_mutex os_waits=110
InnoDB &buf_pool->LRU_list_mutex os_waits=1
InnoDB &buf_pool->flush_state_mutex os_waits=80
InnoDB &buf_pool->flush_state_mutex os_waits=497
InnoDB &buf_pool->LRU_list_mutex os_waits=4
InnoDB &fil_system->mutex os_waits=157
InnoDB &srv_sys.mutex os_waits=59
InnoDB combined &block->mutex os_waits=129
InnoDB &new_index->lock os_waits=2
InnoDB &new_index->lock os_waits=274
InnoDB &new_index->lock os_waits=332
InnoDB &new_index->lock os_waits=480
InnoDB &new_index->lock os_waits=4
InnoDB &new_index->lock os_waits=2
InnoDB &new_index->lock os_waits=11
InnoDB &new_index->lock os_waits=3
InnoDB &new_index->lock os_waits=3
InnoDB &new_index->lock os_waits=484
InnoDB &new_index->lock os_waits=1
InnoDB &new_index->lock os_waits=1
InnoDB &space->latch os_waits=17
InnoDB &space->latch os_waits=2
InnoDB &space->latch os_waits=1
InnoDB &new_index->lock os_waits=28
InnoDB &dict_operation_lock os_waits=78
InnoDB &log_sys->checkpoint_lock os_waits=5379
InnoDB &btr_search_latch_arr[i] os_waits=16938
InnoDB table->sync_obj.rw_locks + i os_waits=13
InnoDB table->sync_obj.rw_locks + i os_waits=6
InnoDB table->sync_obj.rw_locks + i os_waits=1
InnoDB table->sync_obj.rw_locks + i os_waits=8
InnoDB table->sync_obj.rw_locks + i os_waits=5
InnoDB table->sync_obj.rw_locks + i os_waits=1
InnoDB table->sync_obj.rw_locks + i os_waits=23
InnoDB table->sync_obj.rw_locks + i os_waits=5
InnoDB table->sync_obj.rw_locks + i os_waits=10
InnoDB table->sync_obj.rw_locks + i os_waits=6
InnoDB combined &block->lock os_waits=2609
UPDATE (following Rick James answer). Thanks for the directions on tackling the problem, has already switched long_query_time to 1sec.
The weirdest thing about the case is that there is no visible link to any activity or parameter external to the database. It happens under different amounts of load, both low and medium. The following queries take more than a second to complete (according to slow log):
SHOW FULL COLUMNS FROM `tbl_xyz`;
SELECT * FROM `tbl_index` `t` WHERE `t`.`term`='weird'; // term is a PK
I know my system inside out, each and every query was thoroughly designed, tested, stress-tested, and watched closely after being deployed to production. The system handles pretty heavy tasks during nightly jobs just fine.
These freezes/stalls are happening unpredictably and they don't seem to be connected with queries being executed on the database. Sounds crazy? That's exactly how it is.
I was thinking of a bug, but I don't have any idea of how to prove it. The database is updated to the latest available for Debian Stretch: 10.1.48-MariaDB-0+deb9u2.
Hardware fault was an option too, but monitoring shows no signs of it.
My backup plan is to upgrade to 10.3.27-0+deb10u1, which requires some heavy maintenance activity. Keeping it as a last resort.
P.S. There was a hardware issue (SSD) about a month ago. Has done mysqlanalyze/mysqlcheck, recovered one of the tables (by redeploying it from scratch), everything is in OK status since then. Not sure if it has any effect of happening now, but putting it there just in case.
