Random 5s mysql query response time
Posted by: C P
Date: November 09, 2012 11:40AM
Date: November 09, 2012 11:40AM
I'm running a mysql 5.0.77 server (all InnoDB tables) on a 12-core 32GB memory machine running Centos 5.8, which should be far overspec'd for it's current use. Also running an Apache/PHP/Yii Framework server on a separate, also overspec'd, machine. Running a load test against the web server of ~10 requests/sec (each causes reads and usually a write or two) results in an average request time of ~150ms and all is happy.
However, randomly (once every several hours) there's a spike that causes, as far as I can debug, the MySQL queries to take upwards of 5 seconds for a handful of requests. Then it recovers immediately and drops back to the normal 10-20ms MySQL request time expected.
The long responses aren't for a specific request and have been logged (dumping timestamps from PHP) for requests that typically complete in ~5ms.
Is there anything server-side that might be causing the MySQL server to hang/lock for a few seconds at this frequency, or at least anything that could be checked?
General server CPU load is ~5-10% and looking at the MySQL process list, there's only a couple actions at a time. I haven't captured the process list during the period of slow response, as the period is only a few seconds every many hours.
Thanks in advance.
Below is some of the server config:
However, randomly (once every several hours) there's a spike that causes, as far as I can debug, the MySQL queries to take upwards of 5 seconds for a handful of requests. Then it recovers immediately and drops back to the normal 10-20ms MySQL request time expected.
The long responses aren't for a specific request and have been logged (dumping timestamps from PHP) for requests that typically complete in ~5ms.
Is there anything server-side that might be causing the MySQL server to hang/lock for a few seconds at this frequency, or at least anything that could be checked?
General server CPU load is ~5-10% and looking at the MySQL process list, there's only a couple actions at a time. I haven't captured the process list during the period of slow response, as the period is only a few seconds every many hours.
Thanks in advance.
Below is some of the server config:
+---------------------------------+------------------------------------------------------------+ | Variable_name | Value | +---------------------------------+------------------------------------------------------------+ | auto_increment_increment | 1 | | auto_increment_offset | 1 | | automatic_sp_privileges | ON | | back_log | 50 | | basedir | /usr/ | | bdb_cache_size | 8384512 | | bdb_home | /var/lib/mysql/ | | bdb_log_buffer_size | 262144 | | bdb_logdir | | | bdb_max_lock | 10000 | | bdb_shared_data | OFF | | bdb_tmpdir | /tmp/ | | 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 | 0 | | 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 | NO | | have_bdb | YES | | have_blackhole_engine | NO | | have_compress | YES | | have_crypt | YES | | have_csv | NO | | have_dynamic_loading | YES | | have_example_engine | NO | | have_federated_engine | NO | | have_geometry | YES | | have_innodb | YES | | have_isam | NO | | have_merge_engine | YES | | have_ndbcluster | NO | | have_openssl | DISABLED | | have_ssl | DISABLED | | have_query_cache | YES | | have_raid | NO | | have_rtree_keys | YES | | have_symlink | YES | | init_connect | | | init_file | | | init_slave | | | innodb_additional_mem_pool_size | 20971520 | | innodb_autoextend_increment | 8 | | innodb_buffer_pool_awe_mem_mb | 0 | | innodb_buffer_pool_size | 12884901888 | | 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 | OFF | | innodb_flush_log_at_trx_commit | 1 | | 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 | 16777216 | | innodb_log_file_size | 209715200 | | 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 | 24 | | innodb_thread_sleep_delay | 10000 | | interactive_timeout | 28800 | | join_buffer_size | 131072 | | key_buffer_size | 8384512 | | 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 | OFF | | log_slave_updates | OFF | | log_slow_queries | OFF | | log_warnings | 1 | | long_query_time | 10 | | low_priority_updates | OFF | | lower_case_file_system | OFF | | lower_case_table_names | 0 | | max_allowed_packet | 1048576 | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 1073741824 | | max_connect_errors | 10 | | max_connections | 100 | | 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 | OFF | | myisam_repair_threads | 1 | | myisam_sort_buffer_size | 8388608 | | myisam_stats_method | nulls_unequal | | net_buffer_length | 16384 | | net_read_timeout | 30 | | net_retry_count | 10 | | net_write_timeout | 60 | | new | OFF | | old_passwords | ON | | open_files_limit | 1024 | | 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 | 0 | | 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/lib/mysql/mysql.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 | 0 | | thread_stack | 262144 | | 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 | REPEATABLE-READ | | updatable_views_with_limit | YES | | version | 5.0.77 | | version_bdb | Sleepycat Software: Berkeley DB 4.1.24: (January 29, 2009) | | version_comment | Source distribution | | version_compile_machine | x86_64 | | version_compile_os | redhat-linux-gnu | | wait_timeout | 28800 | +---------------------------------+------------------------------------------------------------+ ===================================== 121109 17:35:16 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 20 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 2401686, signal count 2366759 Mutex spin waits 0, rounds 1376750607, OS waits 973392 RW-shared spins 1398015, OS waits 50889; RW-excl spins 2732857, OS waits 23997 ------------ TRANSACTIONS ------------ Trx id counter 0 41087749 Purge done for trx's n:o < 0 41087520 undo n:o < 0 0 History list length 29 Total number of lock structs in row lock hash table 75 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 7569, OS thread id 1183516992 MySQL thread id 1468197, query id 30431404 localhost root show engine innodb status ---TRANSACTION 0 41087748, ACTIVE 0 sec, process no 7569, OS thread id 1176860992 fetching rows, thread declared inside InnoDB 135 mysql tables in use 1, locked 1 76 lock struct(s), heap size 14320 *** DELETED QUERY AS IT CONTAINS PRIVATE INFO ***** -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request (insert buffer thread) I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 9764 OS file reads, 4179941 OS file writes, 3917311 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 36.10 writes/s, 35.85 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 5, seg size 7, 325 inserts, 325 merged recs, 324 merges Hash table size 25499819, used cells 3709368, node heap has 5914 buffer(s) 297571.52 hash searches/s, 4936.00 non-hash searches/s --- LOG --- Log sequence number 1 2856203535 Log flushed up to 1 2856203535 Last checkpoint at 1 2844821035 0 pending log writes, 0 pending chkp writes 3863738 log i/o's done, 35.85 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 14292088808; in additional pool allocated 12681984 Buffer pool size 786432 Free buffers 702320 Database pages 78198 Modified db pages 4571 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 17428, created 60770, written 1702242 0.00 reads/s, 0.05 creates/s, 6.15 writes/s Buffer pool hit rate 1000 / 1000 -------------- ROW OPERATIONS -------------- 2 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread process no. 7569, id 1165678912, state: sleeping Number of rows inserted 4936086, updated 4896570, deleted 631745, read 18710343583 14.30 inserts/s, 13.10 updates/s, 12.70 deletes/s, 305724.06 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================
Subject
Views
Written By
Posted
Sorry, you can't reply to this topic. It has been closed.
Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.