MySQL query randomly takes "forever"

Question

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.

Answer 1

This could be caused by a delayed name resolution, depending on your setup. You could test the speed of DNS lookups from the server with:

nslookup www.domain.com

If you are getting a slow response, try setting the following in your /etc/my.cnf file:

skip-name-resolve
# and/or:
skip-networking

Also it's a good idea to bind the IP address and port number to remove doubt about the connection path:

bind-address=127.0.0.1
port=3306

Otherwise I would look at the table locking and troubleshoot from there.

Answer 2

I've gotten to get a lot of experience in this kind of thing over the last year, unfortunately.

I agree with others it could be a CPU/disk latency issue (due to the virtual hosting). Is there some way you can get disk latency numbers from the host? Maybe there are spikes.

I also agree that the query is a little weird, in specifying the limit clause and the quoting the index. The SELECT * bit I can totally understand.

I'd guess InnoDB doesn't have enough memory, but with so few rows and giving InnoDB 1 gig, that's not it.

I'd guess the query is wrong. I've seen MySQL do this kind of thing before. Some query takes too long or causes others to start to stack up. But the queries that you see taking too long are simple smaller things that should never take very long.

I have a few suggestions for you:

• Is there some sort of automated backup running that could be locking the table?
• Does this happen on any kind of regular or predictable interval?
• Have you ever been logged in and seen the full process list when this occurs?
• Does it coincide with anything specific (any time people run a certain report, etc)?
• Do you have any very large tables that could be tying up all your memory while they're working on queries, preventing this table from coming in (unlikely)?
• Has this always been the case? Did it start recently? Has the MySQL version changed? Are you able to try another build of MySQL (newer point release, Percona Performance build, etc)?

Some times looking at the full process list while this is going on can be the most helpful.

When we were running into this kind of thing last year, it was watching the process list that finally caught the real issue.

Answer 3

I have seen this problem before.

Your index is on an integer field, and your where clause key is a string. Your index is being defeated by the fact that you are causing a type conversion. Unquote your key in the where clause.

I was very surprised that mysql behaves this way, it's quite disappointing that it can't detect when this is happening.

Answer 4

If id is a primary key, why are you adding the LIMIT clause?

Have you tried specifying the column names you want instead of using a *?

Also, is your Id column int? By specifying '1' instead of 1, you may not be using the index.

Try

SELECT * FROM Feeds WHERE id = 1

rather than

SELECT * FROM Feeds WHERE id = '1'

Edit for comment

It's better to specify the column names explicitly, in my opinion, because you may need to add columns to that table in the future that are not needed by your app. At that point, you start pulling more data than is needed.

Answer 5

Your query is very simple, and given that id is a primary key there's no way it should take that long even on a huge table, under normal circumstances. Just a guess here, but maybe the server is the problem? As I understand it (from 30 seconds of looking at their homepage), Slicehost is offering you a virtual machine "slice" of a more powerful server. Could it be that the other slices on the same server are doing heavy disk reads every now and then, temporarily stealing all your resources? Or maybe it happens when the administrators create/remove slices from the machine for other users.

Does this happen very frequently?

Answer 6

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.

Answer 7

If the table is larger than what can be kept in memory caches, then it could be that some of these queries needed to touch the disc at some unfortunate moments where something else were putting a lot of load on them?

MySQL tuning is sometimes a bit of a black art. High key-buffer cache contention can also give noticeable slow downs.

You could also try searching the mysql performance blog for clues and plausible theories.

Answer 8

If you're using MyISAM, you might be hitting concurrency problems.