Take the 2-minute tour ×
Server Fault is a question and answer site for system and network administrators. It's 100% free, no registration required.

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
share|improve this question
    
It just happened again (only 2 hours after the previous time). –  mhost Feb 28 at 18:24

1 Answer 1

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.

share|improve this answer
    
The query cache has the exact same settings as the old server and this never happened on that server. Could this mean there is something faulty with the hardware? –  mhost Mar 2 at 17:46
    
'you can never step in twice in the same river', - old wisdom says. iostat shows your disks are OK. Besides, there is no disk activity, so it even doesn't matter. One CPU is loaded 100%, other CPUs - idle. That gives a hint that things are waiting on one thread that does some job. And my gut feeling says it's the query cache because it's single threaded (because of global mutex) –  akuzminsky Mar 2 at 21:11
    
Thanks for the help. I understand that the query cache is likely the cause of this, but what makes me think the deeper cause is hardware is the fact that nothing else has changed. The way our users use the site, our application, the software and the mysql configuration have not changed. The only thing that changed is the server hardware and now the query cache causes these locks. The query cache was working fine with all these same things on the old machine. –  mhost Mar 3 at 17:49
    
I've disabled the query cache and the problem is still happening. There was one query that was in "Sending data" for nearly 40 minutes and a bunch waiting for it. The system had pretty much the same stats (one cpu at 100% use and the rest at 0% and no IO wait) –  mhost Mar 3 at 22:40

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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