Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

MySQL query randomly takes "forever"

We have an XMPP application that uses MySQL to store information. We are not experiencing any specific load problem so far, but I am trying to be prepared for the worst (or the best, in terms of users;)).

The host on which this MySQL server is installed is a Slicehost slice with 2GB of RAM.

Yesterday, I activated slow query logging to be sure we actually had nothing slow. Unfortunately, it seems that a lot of slow queries were actually found:

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 109  Time=25.57s (2787s)  Lock=0.00s (0s)  Rows=1.0 (109), xxxxx[xxxxx]@[172.21.xxx.xxx]
  SELECT * FROM `feeds` WHERE (`id` = 'S') LIMIT N

This is really strange for me, since id is actually a primary key... The Table is InnoDB

I did an EXPLAIN:

mysql> EXPLAIN SELECT * FROM `feeds` WHERE (`id` = '2650') LIMIT 1;

 +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
 | id | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra |
 +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
 |  1 | SIMPLE      | feeds | const | PRIMARY       | PRIMARY | 4       | const |    1 |       |
 +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
 1 row in set (0.00 sec)

There must be another reason why this happens. And there are actaully a lot of similar slow queries (query that use primary keys) in our log.

I think it would make sense to post the MySQL settings here :

mysql> SHOW VARIABLES;
+---------------------------------+-----------------------------+
| Variable_name                   | Value                       |
+---------------------------------+-----------------------------+
| auto_increment_increment        | 1                           | 
| auto_increment_offset           | 1                           | 
| automatic_sp_privileges         | ON                          | 
| back_log                        | 50                          | 
| basedir                         | /usr/                       | 
| binlog_cache_size               | 32768                       | 
| bulk_insert_buffer_size         | 8388608                     | 
| character_set_client            | latin1                      | 
| character_set_connection        | latin1                      | 
| character_set_database          | latin1                      | 
| character_set_filesystem        | binary                      | 
| character_set_results           | latin1                      | 
| character_set_server            | latin1                      | 
| character_set_system            | utf8                        | 
| character_sets_dir              | /usr/share/mysql/charsets/  | 
| collation_connection            | latin1_swedish_ci           | 
| collation_database              | latin1_swedish_ci           | 
| collation_server                | latin1_swedish_ci           | 
| completion_type                 | 0                           | 
| concurrent_insert               | 1                           | 
| connect_timeout                 | 10                          | 
| datadir                         | /var/lib/mysql/             | 
| date_format                     | %Y-%m-%d                    | 
| datetime_format                 | %Y-%m-%d %H:%i:%s           | 
| default_week_format             | 0                           | 
| delay_key_write                 | ON                          | 
| delayed_insert_limit            | 100                         | 
| delayed_insert_timeout          | 300                         | 
| delayed_queue_size              | 1000                        | 
| div_precision_increment         | 4                           | 
| keep_files_on_create            | OFF                         | 
| engine_condition_pushdown       | OFF                         | 
| expire_logs_days                | 10                          | 
| flush                           | OFF                         | 
| flush_time                      | 0                           | 
| ft_boolean_syntax               | + -><()~*:""&|              | 
| ft_max_word_len                 | 84                          | 
| ft_min_word_len                 | 4                           | 
| ft_query_expansion_limit        | 20                          | 
| ft_stopword_file                | (built-in)                  | 
| group_concat_max_len            | 1024                        | 
| have_archive                    | YES                         | 
| have_bdb                        | NO                          | 
| have_blackhole_engine           | YES                         | 
| have_compress                   | YES                         | 
| have_crypt                      | YES                         | 
| have_csv                        | YES                         | 
| have_dynamic_loading            | YES                         | 
| have_example_engine             | NO                          | 
| have_federated_engine           | DISABLED                    | 
| have_geometry                   | YES                         | 
| have_innodb                     | YES                         | 
| have_isam                       | NO                          | 
| have_merge_engine               | YES                         | 
| have_ndbcluster                 | DISABLED                    | 
| have_openssl                    | DISABLED                    | 
| have_ssl                        | DISABLED                    | 
| have_query_cache                | YES                         | 
| have_raid                       | NO                          | 
| have_rtree_keys                 | YES                         | 
| have_symlink                    | YES                         | 
| hostname                        | SuperfeedrDatabase          | 
| init_connect                    |                             | 
| init_file                       |                             | 
| init_slave                      |                             | 
| innodb_additional_mem_pool_size | 1048576                     | 
| innodb_autoextend_increment     | 8                           | 
| innodb_buffer_pool_awe_mem_mb   | 0                           | 
| innodb_buffer_pool_size         | 1073741824                  | 
| innodb_checksums                | ON                          | 
| innodb_commit_concurrency       | 0                           | 
| innodb_concurrency_tickets      | 500                         | 
| innodb_data_file_path           | ibdata1:10M:autoextend      | 
| innodb_data_home_dir            |                             | 
| innodb_adaptive_hash_index      | ON                          | 
| innodb_doublewrite              | ON                          | 
| innodb_fast_shutdown            | 1                           | 
| innodb_file_io_threads          | 4                           | 
| innodb_file_per_table           | ON                          | 
| innodb_flush_log_at_trx_commit  | 2                           | 
| innodb_flush_method             | O_DIRECT                    | 
| innodb_force_recovery           | 0                           | 
| innodb_lock_wait_timeout        | 50                          | 
| innodb_locks_unsafe_for_binlog  | OFF                         | 
| innodb_log_arch_dir             |                             | 
| innodb_log_archive              | OFF                         | 
| innodb_log_buffer_size          | 4194304                     | 
| innodb_log_file_size            | 5242880                     | 
| innodb_log_files_in_group       | 2                           | 
| innodb_log_group_home_dir       | ./                          | 
| innodb_max_dirty_pages_pct      | 90                          | 
| innodb_max_purge_lag            | 0                           | 
| innodb_mirrored_log_groups      | 1                           | 
| innodb_open_files               | 300                         | 
| innodb_rollback_on_timeout      | OFF                         | 
| innodb_support_xa               | ON                          | 
| innodb_sync_spin_loops          | 20                          | 
| innodb_table_locks              | ON                          | 
| innodb_thread_concurrency       | 8                           | 
| innodb_thread_sleep_delay       | 10000                       | 
| interactive_timeout             | 28800                       | 
| join_buffer_size                | 131072                      | 
| key_buffer_size                 | 16777216                    | 
| key_cache_age_threshold         | 300                         | 
| key_cache_block_size            | 1024                        | 
| key_cache_division_limit        | 100                         | 
| language                        | /usr/share/mysql/english/   | 
| large_files_support             | ON                          | 
| large_page_size                 | 0                           | 
| large_pages                     | OFF                         | 
| lc_time_names                   | en_US                       | 
| license                         | GPL                         | 
| local_infile                    | ON                          | 
| locked_in_memory                | OFF                         | 
| log                             | OFF                         | 
| log_bin                         | OFF                         | 
| log_bin_trust_function_creators | OFF                         | 
| log_error                       |                             | 
| log_queries_not_using_indexes   | ON                          | 
| log_slave_updates               | OFF                         | 
| log_slow_queries                | ON                          | 
| log_warnings                    | 1                           | 
| long_query_time                 | 3                           | 
| low_priority_updates            | OFF                         | 
| lower_case_file_system          | OFF                         | 
| lower_case_table_names          | 0                           | 
| max_allowed_packet              | 16777216                    | 
| max_binlog_cache_size           | 18446744073709547520        | 
| max_binlog_size                 | 104857600                   | 
| max_connect_errors              | 10                          | 
| max_connections                 | 2000                        | 
| max_delayed_threads             | 20                          | 
| max_error_count                 | 64                          | 
| max_heap_table_size             | 16777216                    | 
| max_insert_delayed_threads      | 20                          | 
| max_join_size                   | 18446744073709551615        | 
| max_length_for_sort_data        | 1024                        | 
| max_prepared_stmt_count         | 16382                       | 
| max_relay_log_size              | 0                           | 
| max_seeks_for_key               | 18446744073709551615        | 
| max_sort_length                 | 1024                        | 
| max_sp_recursion_depth          | 0                           | 
| max_tmp_tables                  | 32                          | 
| max_user_connections            | 0                           | 
| max_write_lock_count            | 18446744073709551615        | 
| multi_range_count               | 256                         | 
| myisam_data_pointer_size        | 6                           | 
| myisam_max_sort_file_size       | 9223372036853727232         | 
| myisam_recover_options          | BACKUP                      | 
| myisam_repair_threads           | 1                           | 
| myisam_sort_buffer_size         | 8388608                     | 
| myisam_stats_method             | nulls_unequal               | 
| ndb_autoincrement_prefetch_sz   | 1                           | 
| ndb_force_send                  | ON                          | 
| ndb_use_exact_count             | ON                          | 
| ndb_use_transactions            | ON                          | 
| ndb_cache_check_time            | 0                           | 
| ndb_connectstring               |                             | 
| net_buffer_length               | 16384                       | 
| net_read_timeout                | 30                          | 
| net_retry_count                 | 10                          | 
| net_write_timeout               | 60                          | 
| new                             | OFF                         | 
| old_passwords                   | OFF                         | 
| open_files_limit                | 10000                       | 
| optimizer_prune_level           | 1                           | 
| optimizer_search_depth          | 62                          | 
| pid_file                        | /var/run/mysqld/mysqld.pid  | 
| plugin_dir                      |                             | 
| port                            | 3306                        | 
| preload_buffer_size             | 32768                       | 
| profiling                       | OFF                         | 
| profiling_history_size          | 15                          | 
| protocol_version                | 10                          | 
| query_alloc_block_size          | 8192                        | 
| query_cache_limit               | 1048576                     | 
| query_cache_min_res_unit        | 4096                        | 
| query_cache_size                | 16777216                    | 
| query_cache_type                | ON                          | 
| query_cache_wlock_invalidate    | OFF                         | 
| query_prealloc_size             | 8192                        | 
| range_alloc_block_size          | 4096                        | 
| read_buffer_size                | 131072                      | 
| read_only                       | OFF                         | 
| read_rnd_buffer_size            | 262144                      | 
| relay_log                       |                             | 
| relay_log_index                 |                             | 
| relay_log_info_file             | relay-log.info              | 
| relay_log_purge                 | ON                          | 
| relay_log_space_limit           | 0                           | 
| rpl_recovery_rank               | 0                           | 
| secure_auth                     | OFF                         | 
| secure_file_priv                |                             | 
| server_id                       | 0                           | 
| skip_external_locking           | ON                          | 
| skip_networking                 | OFF                         | 
| skip_show_database              | OFF                         | 
| slave_compressed_protocol       | OFF                         | 
| slave_load_tmpdir               | /tmp/                       | 
| slave_net_timeout               | 3600                        | 
| slave_skip_errors               | OFF                         | 
| slave_transaction_retries       | 10                          | 
| slow_launch_time                | 2                           | 
| socket                          | /var/run/mysqld/mysqld.sock | 
| sort_buffer_size                | 2097144                     | 
| sql_big_selects                 | ON                          | 
| sql_mode                        |                             | 
| sql_notes                       | ON                          | 
| sql_warnings                    | OFF                         | 
| ssl_ca                          |                             | 
| ssl_capath                      |                             | 
| ssl_cert                        |                             | 
| ssl_cipher                      |                             | 
| ssl_key                         |                             | 
| storage_engine                  | MyISAM                      | 
| sync_binlog                     | 0                           | 
| sync_frm                        | ON                          | 
| system_time_zone                | UTC                         | 
| table_cache                     | 64                          | 
| table_lock_wait_timeout         | 50                          | 
| table_type                      | MyISAM                      | 
| thread_cache_size               | 8                           | 
| thread_stack                    | 131072                      | 
| time_format                     | %H:%i:%s                    | 
| time_zone                       | SYSTEM                      | 
| timed_mutexes                   | OFF                         | 
| tmp_table_size                  | 33554432                    | 
| tmpdir                          | /tmp                        | 
| transaction_alloc_block_size    | 8192                        | 
| transaction_prealloc_size       | 4096                        | 
| tx_isolation                    | READ-COMMITTED              | 
| updatable_views_with_limit      | YES                         | 
| version                         | 5.0.67-0ubuntu6-log         | 
| version_comment                 | (Ubuntu)                    | 
| version_compile_machine         | x86_64                      | 
| version_compile_os              | debian-linux-gnu            | 
| wait_timeout                    | 28800                       | 
+---------------------------------+-----------------------------+
237 rows in set (0.00 sec)

Most of our requests are "basic", however, we need a tremendous speed!

Any thoughts on what could actually make MySQL so slow?

[SUMMARY] To sum up the various answers :

  • Remove "LIMIT", change WHERE id = "X" into WHERE id = X
  • Make sure I don't have any script(backup or else) that runs from time to time that would consume a lot of resources
  • Make sure the "host" is not actually the culprit.
like image 842
Julien Genestoux Avatar asked Jun 10 '09 16:06

Julien Genestoux


1 Answers

Looking at the mean & variance of slows, you have a problem with the VM host machine (which is not under your control unfortunately).

For those of you pointing out the memory/disk I/O, those numbers are just too big for that. Disk should return in 100ms, not several seconds.

like image 199
Joshua Avatar answered Oct 22 '22 07:10

Joshua