Sample Header Ad - 728x90

MariaDB freezes with no visible reason

3 votes
2 answers
3907 views
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: 1. There are many different queries (all of them are lightweight select using an index or plain inserts) that got frozen waiting for something. 2. After this *something* is over, queries are processed pretty fast. 3. 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 ... ---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 ... ---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 ... ---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.
Asked by user1065145 (141 rep)
May 21, 2021, 04:45 PM
Last activity: Nov 13, 2023, 09:47 PM