This morning our database became extremely slow for no apparent reason. There were 2 active queries, one took a little over 30 minutes in "Sending data" and another took almost 10 minutes in "storing result in query cache". There were also many queries "Waiting for table level lock". Once those 2 queries completed, all queries finished up very quickly.
I don't think the queries need optimizing because after this happened, I re-ran those queries manually, and the 30 minute one completed in 14 seconds and the 10 minute one completed in 8 seconds. So it seems like it is just a temporary server issue however, it happened last week as well and once about a month ago.
This server runs nothing except mysql. Any help would be greatly appreciated.
This is a brand new server that we bought because we expect a lot more traffic soon. The old server which had much lower specs never had this problem.
Here are some commands that I ran while it was in this state:
pidstat -dru 1 3:
Linux 3.8.0-29-generic (db1) 02/28/2014 _x86_64_ (32 CPU)
10:16:06 AM PID %usr %system %guest %CPU CPU Command
10:16:07 AM 2907 103.88 1.94 0.00 105.83 17 mysqld
10:16:07 AM 29727 0.97 1.94 0.00 2.91 17 pidstat
10:16:06 AM PID minflt/s majflt/s VSZ RSS %MEM Command
10:16:07 AM 2907 230.10 0.00 17380572 756892 1.15 mysqld
10:16:07 AM 29727 868.93 0.00 7636 1268 0.00 pidstat
10:16:06 AM PID kB_rd/s kB_wr/s kB_ccwr/s Command
10:16:07 AM PID %usr %system %guest %CPU CPU Command
10:16:08 AM 10 0.00 1.00 0.00 1.00 5 rcu_sched
10:16:08 AM 462 0.00 1.00 0.00 1.00 31 kworker/31:1
10:16:08 AM 2907 105.00 1.00 0.00 106.00 17 mysqld
10:16:08 AM 29727 1.00 2.00 0.00 3.00 17 pidstat
10:16:07 AM PID minflt/s majflt/s VSZ RSS %MEM Command
10:16:08 AM 2907 177.00 0.00 17380572 756892 1.15 mysqld
10:16:08 AM 29619 28.00 0.00 23304 4616 0.01 bash
10:16:08 AM 29727 895.00 0.00 7636 1300 0.00 pidstat
10:16:07 AM PID kB_rd/s kB_wr/s kB_ccwr/s Command
10:16:08 AM PID %usr %system %guest %CPU CPU Command
10:16:09 AM 2907 103.00 2.00 0.00 105.00 17 mysqld
10:16:09 AM 29727 2.00 2.00 0.00 4.00 17 pidstat
10:16:08 AM PID minflt/s majflt/s VSZ RSS %MEM Command
10:16:09 AM 2907 162.00 0.00 17380572 756892 1.15 mysqld
10:16:09 AM 29619 2.00 0.00 23304 4616 0.01 bash
10:16:09 AM 29727 887.00 0.00 7636 1300 0.00 pidstat
10:16:08 AM PID kB_rd/s kB_wr/s kB_ccwr/s Command
10:16:09 AM 2907 0.00 2000.00 0.00 mysqld
Average: PID %usr %system %guest %CPU CPU Command
Average: 10 0.00 0.33 0.00 0.33 - rcu_sched
Average: 462 0.00 0.33 0.00 0.33 - kworker/31:1
Average: 2907 103.96 1.65 0.00 105.61 - mysqld
Average: 29727 1.32 1.98 0.00 3.30 - pidstat
Average: PID minflt/s majflt/s VSZ RSS %MEM Command
Average: 2907 190.10 0.00 17380572 756892 1.15 mysqld
Average: 29619 9.90 0.00 23304 4616 0.01 bash
Average: 29727 883.50 0.00 7636 1289 0.00 pidstat
Average: PID kB_rd/s kB_wr/s kB_ccwr/s Command
Average: 2907 0.00 660.07 0.00 mysqld
vmstat 1 2:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
2 0 416 322964 191692 63370180 0 0 5 5 0 0 0 0 100 0
1 0 416 322908 191692 63370188 0 0 0 0 567 2422 3 0 97 0
mpstat -P ALL 1 2:
Linux 3.8.0-29-generic (db1) 02/28/2014 _x86_64_ (32 CPU)
10:16:02 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle
10:16:03 AM all 3.16 0.00 0.03 0.00 0.00 0.00 0.00 0.00 96.81
10:16:03 AM 0 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
10:16:03 AM 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 4 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 5 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 7 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 8 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 9 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 10 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 11 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 12 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 13 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 14 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 15 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 16 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 17 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 18 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 20 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 21 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 22 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 23 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 24 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 25 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 26 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 27 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 28 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 29 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 30 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM 31 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:03 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle
10:16:04 AM all 3.22 0.00 0.06 0.00 0.00 0.00 0.00 0.00 96.72
10:16:04 AM 0 98.02 0.00 0.99 0.00 0.00 0.00 0.00 0.00 0.99
10:16:04 AM 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 4 1.98 0.00 0.99 0.00 0.00 0.00 0.00 0.00 97.03
10:16:04 AM 5 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 7 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 8 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 9 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 10 2.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 98.00
10:16:04 AM 11 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 12 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 13 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 14 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 15 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 16 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 17 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 18 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 19 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 20 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 21 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 22 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 23 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 24 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 25 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 26 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 27 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 28 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 29 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 30 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
10:16:04 AM 31 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
iostat -x 1 2:
Linux 3.8.0-29-generic (db1) 02/28/2014 _x86_64_ (32 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
0.17 0.00 0.04 0.00 0.00 99.79
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 1.29 1.41 3.11 151.57 151.91 134.28 0.08 16.85 0.54 24.28 0.31 0.14
dm-0 0.00 0.00 1.41 4.40 151.57 151.91 104.44 0.08 14.06 0.54 18.41 0.24 0.14
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 8.00 0.00 2.27 0.54 5.68 1.22 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
3.25 0.00 0.03 0.00 0.00 96.72
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
free -m:
total used free shared buffers cached
Mem: 64385 64070 315 0 187 61884
-/+ buffers/cache: 1998 62387
Swap: 65491 0 65491
SHOW GLOBAL STATUS:
Variable_name Value
Aborted_clients 32
Aborted_connects 2088
Binlog_cache_disk_use 0
Binlog_cache_use 0
Binlog_stmt_cache_disk_use 2
Binlog_stmt_cache_use 2798217
Bytes_received 1724697475
Bytes_sent 10912829491
Com_admin_commands 103619
Com_assign_to_keycache 0
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 113
Com_alter_tablespace 0
Com_analyze 0
Com_begin 1095437
Com_binlog 0
Com_call_procedure 0
Com_change_db 393259
Com_change_master 0
Com_check 15189
Com_checksum 0
Com_commit 1095434
Com_create_db 1
Com_create_event 0
Com_create_function 0
Com_create_index 0
Com_create_procedure 1
Com_create_server 0
Com_create_table 42
Com_create_trigger 0
Com_create_udf 0
Com_create_user 0
Com_create_view 0
Com_dealloc_sql 24
Com_delete 9989
Com_delete_multi 2
Com_do 0
Com_drop_db 1
Com_drop_event 0
Com_drop_function 0
Com_drop_index 0
Com_drop_procedure 2
Com_drop_server 0
Com_drop_table 1
Com_drop_trigger 0
Com_drop_user 0
Com_drop_view 0
Com_empty_query 0
Com_execute_sql 24
Com_flush 4
Com_grant 0
Com_ha_close 0
Com_ha_open 0
Com_ha_read 0
Com_help 0
Com_insert 711847
Com_insert_select 6
Com_install_plugin 0
Com_kill 0
Com_load 0
Com_lock_tables 0
Com_optimize 55
Com_preload_keys 0
Com_prepare_sql 24
Com_purge 0
Com_purge_before_date 0
Com_release_savepoint 0
Com_rename_table 1
Com_rename_user 0
Com_repair 0
Com_replace 491733
Com_replace_select 31
Com_reset 0
Com_resignal 0
Com_revoke 0
Com_revoke_all 0
Com_rollback 0
Com_rollback_to_savepoint 0
Com_savepoint 0
Com_select 2842695
Com_set_option 388138
Com_signal 0
Com_show_authors 0
Com_show_binlog_events 0
Com_show_binlogs 0
Com_show_charsets 0
Com_show_collations 0
Com_show_contributors 0
Com_show_create_db 0
Com_show_create_event 0
Com_show_create_func 0
Com_show_create_proc 0
Com_show_create_table 0
Com_show_create_trigger 0
Com_show_databases 3
Com_show_engine_logs 0
Com_show_engine_mutex 0
Com_show_engine_status 0
Com_show_events 0
Com_show_errors 0
Com_show_fields 231871
Com_show_function_status 0
Com_show_grants 0
Com_show_keys 0
Com_show_master_status 0
Com_show_open_tables 0
Com_show_plugins 0
Com_show_privileges 0
Com_show_procedure_status 0
Com_show_processlist 4103
Com_show_profile 0
Com_show_profiles 0
Com_show_relaylog_events 0
Com_show_slave_hosts 0
Com_show_slave_status 0
Com_show_status 4099
Com_show_storage_engines 0
Com_show_table_status 0
Com_show_tables 1516319
Com_show_triggers 0
Com_show_variables 6
Com_show_warnings 0
Com_slave_start 0
Com_slave_stop 0
Com_stmt_close 24
Com_stmt_execute 24
Com_stmt_fetch 0
Com_stmt_prepare 24
Com_stmt_reprepare 0
Com_stmt_reset 0
Com_stmt_send_long_data 0
Com_truncate 3
Com_uninstall_plugin 0
Com_unlock_tables 0
Com_update 1584610
Com_update_multi 22
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
Connections 445201
Created_tmp_disk_tables 1736238
Created_tmp_files 90
Created_tmp_tables 1795650
Delayed_errors 0
Delayed_insert_threads 0
Delayed_writes 0
Flush_commands 1
Handler_commit 3893481
Handler_delete 9342
Handler_discover 0
Handler_prepare 0
Handler_read_first 329186
Handler_read_key 4104519415
Handler_read_last 12543
Handler_read_next 5423345858
Handler_read_prev 27590297
Handler_read_rnd 5211189
Handler_read_rnd_next 42554732813
Handler_rollback 0
Handler_savepoint 0
Handler_savepoint_rollback 0
Handler_update 39411585
Handler_write 274236845
Key_blocks_not_flushed 1
Key_blocks_unused 0
Key_blocks_used 319666
Key_read_requests 17637822343
Key_reads 13404466
Key_write_requests 192935745
Key_writes 1202353
Last_query_cost 0.000000
Max_used_connections 412
Not_flushed_delayed_rows 0
Open_files 9779
Open_streams 0
Open_table_definitions 4767
Open_tables 5000
Opened_files 7094126
Opened_table_definitions 49482
Opened_tables 55504
Performance_schema_cond_classes_lost 0
Performance_schema_cond_instances_lost 0
Performance_schema_file_classes_lost 0
Performance_schema_file_handles_lost 0
Performance_schema_file_instances_lost 0
Performance_schema_locker_lost 0
Performance_schema_mutex_classes_lost 0
Performance_schema_mutex_instances_lost 0
Performance_schema_rwlock_classes_lost 0
Performance_schema_rwlock_instances_lost 0
Performance_schema_table_handles_lost 0
Performance_schema_table_instances_lost 0
Performance_schema_thread_classes_lost 0
Performance_schema_thread_instances_lost 0
Prepared_stmt_count 0
Qcache_free_blocks 15231
Qcache_free_memory 49970792
Qcache_hits 2495975
Qcache_inserts 2762600
Qcache_lowmem_prunes 182256
Qcache_not_cached 80858
Qcache_queries_in_cache 11811
Qcache_total_blocks 39192
Queries 13324094
Questions 13324094
Rpl_status AUTH_MASTER
Select_full_join 10253
Select_full_range_join 278
Select_range 5736
Select_range_check 18
Select_scan 1905346
Slave_heartbeat_period 0.000
Slave_open_temp_tables 0
Slave_received_heartbeats 0
Slave_retried_transactions 0
Slave_running OFF
Slow_launch_threads 0
Slow_queries 445
Sort_merge_passes 44
Sort_range 66431
Sort_rows 5055362
Sort_scan 67580
Ssl_accept_renegotiates 0
Ssl_accepts 0
Ssl_callback_cache_hits 0
Ssl_cipher
Ssl_cipher_list
Ssl_client_connects 0
Ssl_connect_renegotiates 0
Ssl_ctx_verify_depth 0
Ssl_ctx_verify_mode 0
Ssl_default_timeout 0
Ssl_finished_accepts 0
Ssl_finished_connects 0
Ssl_session_cache_hits 0
Ssl_session_cache_misses 0
Ssl_session_cache_mode NONE
Ssl_session_cache_overflows 0
Ssl_session_cache_size 0
Ssl_session_cache_timeouts 0
Ssl_sessions_reused 0
Ssl_used_session_cache_entries 0
Ssl_verify_depth 0
Ssl_verify_mode 0
Ssl_version
Table_locks_immediate 5984350
Table_locks_waited 21734
Tc_log_max_pages_used 0
Tc_log_page_size 0
Tc_log_page_waits 0
Threads_cached 0
Threads_connected 412
Threads_created 30180
Threads_running 38
Uptime 250436
Uptime_since_flush_status 250436
Best Answer
Disable the Query Cache. It's protected by one global mutex, so if it's locked everything else stalls. And it can be locked if the QC big and MySQL needs to clean it up.