0

I have a problem where queries freezes sporadically during the day. I made a script monitoring the processlist and have detected a pattern where a slow query is running (different slow queries) and then (fast) queries are stuck in different states, ie. opening tables, query end, update, etc, like this:

time (seconds)  state           query
7               Opening tables  SELECT id FROM... 
8               Opening tables  SELECT type FROM...
8               query end       UPDATE cache...
8               Opening tables  SELECT language FROM...
9               query end       INSERT INTO cache...
9               query end       INSERT INTO cache...
29              Sending data    SELECT product_id FROM...

Usually it's write operations getting stuck, but also simple selects in state "Opening tables". Then something happens and the queries disappears from the list. Not sure what this "something" is though. It feels like something is locking the queries but I'm not able to pinpoint what it is.

Any ideas what can be causing this problem or how I can debug it further?

MariaDB version: 10.1.41-MariaDB-0+deb9u1

SHOW GLOBAL STATUS: https://pastebin.com/gyZNhEsP

SHOW VARIABLES: https://pastebin.com/YAXFcz2G

UPDATE, action plan based on Ricks analyze:

  • No good reason for MyISAM => all tables will be converted to InnoDB.
  • Settings update (server has 32 GB RAM and SSD drives):
table_open_cache = 2K
innodb_log_file_size = 200M
innodb_flush_method = O_DIRECT
query_cache_type = OFF
query_cache_size = 0
table_definition_cache = 1K
innodb_buffer_pool_instances = 8
innodb_lru_scan_depth = 256
innodb_io_capacity = 1000
innodb_flush_neighbors = 0
  • Added logging of SHOW ENGINE INNODB STATUS in monitoring script if we detect a freeze.
  • In the long run: Replace all REPLACE-queries.

Looks like the problem occurs more frequently when a lot of writing is happening. Maybe the freezes occurs when data is flushed to disk or something similar. Hopefully the changes of I/O-settings will solve it.

UPDATE 2: We still have the same problem after the settings update. Managed to log SHOW ENGINE INNODB STATUS when a freeze occured: https://pastebin.com/EPg9RXgS

The queries are stuck in "flushing log". Can it be a problem with the SSD? Or writing to binlog? Anything else?

6
  • check the error log and see if there is a hint
    – nbk
    Jun 1 '21 at 8:50
  • @nbk my bad, we rotate it each day and then delete it after some days. Nothing but some unrelated skip-name-resolve mode warnings a few days ago.
    – Daniel H
    Jun 1 '21 at 11:39
  • you version is very old, there is at least 10.1.48 the last, you should upgrade at least the minor versions and see if it helps.
    – nbk
    Jun 1 '21 at 12:33
  • thanks, we will upgrade to 10.1.48 tomorrow and hope it helps.
    – Daniel H
    Jun 1 '21 at 13:45
  • 1
    you should also test if a newer Version 10.3 or 10.4 is iok, because 10.1 has reached it end of life endoflife.date/mariadb
    – nbk
    Jun 1 '21 at 13:50
1
Analysis of GLOBAL STATUS and VARIABLES:
 

Observations:

  • Version: 10.1.41-MariaDB-0+deb9u1
  • 32 GB of RAM??
  • Uptime = 12d 00:12:10
  • You are not running on Windows.
  • Running 64-bit version
  • It appears that you are running both MyISAM and InnoDB.

The More Important Issues:

It is generally better to us InnoDB instead of MyISAM. If you have specific reasons for using MyISAM, please explain. (MyISAM may even be part of the problem you are having; seeing the specific query and schema may allow me to explain why.)

table_open_cache = 2K
key_buffer_size = 200M         # If you continue to use MyISAM
innodb_log_file_size = 200M    # This could be difficult to change

If the disk is SSD:

innodb_io_capacity = 1000
innodb_flush_neighbors = 0

Check your deadlocks; there may be issues that have gone unnoticed: SHOW ENGINE INNODB STATUS;

IODKU is generally preferred to REPLACE.

Details and other observations:

Conversion from MyISAM to InnoDB ( Opened_tables ) = 77,237,969 / 1037530 = 74 /sec -- Frequency of opening Tables -- increase table_open_cache (now 1024)

( Opened_table_definitions ) = 71,478,506 / 1037530 = 69 /sec -- Frequency of opening .frm files -- Increase table_definition_cache (now 400) and/or table_open_cache (now 1024).

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

( innodb_lru_scan_depth ) = 1,024 -- "InnoDB: page_cleaner: 1000ms intended loop took ..." may be fixed by lowering lru_scan_depth

( innodb_io_capacity ) = 200 -- When flushing, use this many IOPs. -- Reads could be slugghish or spiky.

( innodb_io_capacity_max / innodb_io_capacity ) = 2,000 / 200 = 10 -- 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_pages_written/Innodb_data_writes ) = 15,482,984/130821328 = 11.8% -- Seems like these values should be equal?

( Innodb_log_writes ) = 114,197,086 / 1037530 = 110 /sec

( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 129,168,817,152 / (1037530 / 3600) / 2 / 48M = 4.45 -- Ratio -- (see minutes)

( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 1,037,530 / 60 * 48M / 129168817152 = 6.74 -- Minutes between InnoDB log rotations Beginning with 5.6.8, this can be changed dynamically; be sure to also change my.cnf. -- (The recommendation of 60 minutes between rotations is somewhat arbitrary.) Adjust innodb_log_file_size (now 50331648). (Cannot change in AWS.)

( innodb_flush_method ) = innodb_flush_method = -- 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_waits ) = 136,917 / 1037530 = 0.13 /sec -- How often there is a delay in getting a row lock. -- May be caused by complex queries that could be optimized.

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

( innodb_io_capacity ) = 200 -- I/O ops per second capable on disk . 100 for slow drives; 200 for spinning drives; 1000-2000 for SSDs; multiply by RAID factor.

( innodb_strict_mode ) = innodb_strict_mode = OFF -- Catches some subtle errors earlier. -- OFF leaves some warnings as warnings; ON makes them errors.

( 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_adaptive_hash_index ) = innodb_adaptive_hash_index = ON -- Usually should be ON. -- There are cases where OFF is better. See also innodb_adaptive_hash_index_parts (after 5.7.9) and innodb_adaptive_hash_index_partitions (now 1) (MariaDB and Percona). ON has been implicated in rare crashes (bug 73890). 10.5.0 decided to default OFF.

( 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.

( Innodb_deadlocks ) = 13 / 1037530 = 0.045 /HR -- Deadlocks -- SHOW ENGINE INNODB STATUS; to see the latest pair of queries that deadlocked.

( 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.

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

( Key_writes / Key_write_requests ) = 5,495,507 / 8518626 = 64.5% -- key_buffer effectiveness for writes -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 16777216).

( Key_reads ) = 77,011,899 / 1037530 = 74 /sec -- MyISAM index read (from disk) rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 16777216).

( Key_reads + Key_writes ) = (77011899 + 5495507) / 1037530 = 80 /sec -- MyISAM index I/O rate -- If you have enough RAM, it would be worthwhile to increase key_buffer_size (now 16777216).

( Created_tmp_tables ) = 181,680,361 / 1037530 = 175 /sec -- Frequency of creating "temp" tables as part of complex SELECTs.

( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (7515459 + 6183556 + 136341 + 48492329 + 53500428 + 0) / 1037530 = 111 /sec -- writes/sec -- 50 writes/sec + log flushes will probably max out I/O write capacity of HDD drives

( Com_replace ) = 48,492,329 / 1037530 = 47 /sec -- Consider changing to INSERT ... ON DUPLICATE KEY UPDATE.

( 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

( 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.

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

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.

Abnormally small:

aria_checkpoint_log_activity = 1.05e+6
aria_pagecache_buffer_size = 128MB
innodb_max_bitmap_file_size = 100MB
innodb_online_alter_log_max_size = 128MB
innodb_sort_buffer_size = 1.05e+6

Abnormally large:

Aria_pagecache_reads = 14 /sec
Aria_pagecache_write_requests = 501 /sec
Binlog_stmt_cache_use = 16 /sec
Com_create_procedure = 0.0035 /HR
Com_delete_multi = 0.13 /sec
Com_drop_index = 0.0069 /HR
Com_drop_procedure = 0.0035 /HR
Com_replace_select = 0.34 /HR
Com_rollback_to_savepoint = 78 /HR
Com_show_binlogs = 55 /HR
Com_show_create_func = 1.3 /HR
Com_show_create_proc = 1.2 /HR
Com_show_create_trigger = 1 /HR
Com_show_engine_status = 55 /HR
Com_show_master_status = 10 /HR
Com_show_open_tables = 0.17 /sec
Com_show_processlist = 0.17 /sec
Com_show_slave_status = 0.033 /sec
Com_truncate = 18 /HR
Delete_scan = 204,917
Executed_triggers = 7.4 /sec
Feature_subquery = 73 /sec
Feature_trigger = 1.8 /sec
Handler_discover = 0.66 /sec
Handler_icp_attempts = 328023 /sec
Handler_icp_match = 61573 /sec
Handler_read_key = 70342 /sec
Handler_read_last = 4.2 /sec
Handler_read_rnd_deleted = 4.7 /sec
Handler_savepoint = 0.33 /HR
Handler_savepoint_rollback = 0.043 /sec
Innodb_buffer_pool_pages_misc * 16384 / innodb_buffer_pool_size = 8.9%
Innodb_ibuf_discarded_delete_marks = 357,414
Innodb_ibuf_discarded_deletes = 4,032
Innodb_mutex_spin_waits = 1057 /sec
Innodb_num_index_pages_written = 12 /sec
Innodb_num_non_index_pages_written = 113 /sec
Innodb_rows_deleted = 58 /sec
Innodb_s_lock_os_waits = 41 /sec
Innodb_s_lock_spin_rounds = 1716 /sec
Opened_views = 3.8 /sec
Performance_schema_digest_lost = 2.33e+8
Performance_schema_file_instances_lost = 1.5e+8
Select_full_range_join = 1.3 /sec
Select_full_range_join / Com_select = 0.10%
Select_range = 101 /sec
Select_range_check = 36 /HR
Sort_priority_queue_sorts = 74 /sec
Sort_range = 43 /sec
Sort_scan = 98 /sec
Subquery_cache_hit = 1265 /sec
Subquery_cache_miss = 6132 /sec
Table_locks_immediate = 1904 /sec
Update_scan = 661,649
aria_sort_buffer_size = 256.0MB
innodb_thread_concurrency = 50
performance_schema_max_socket_instances = 3,020
performance_schema_max_thread_instances = 3,100
thread_concurrency = 50

Abnormal strings:

Compression = ON
ft_min_word_len = 3
innodb_default_row_format = compact
innodb_fast_shutdown = 1
myisam_stats_method = NULLS_UNEQUAL
1
  • Thanks Rick. That was a more thoroughly answer than I could hope for. I will update my post with our action plan. You will obviously have some banana lattes coming your way.
    – Daniel H
    Jun 2 '21 at 13:24

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.