| Bug #11958 | Periodic 'XXX command denied' on server at high loads | ||
|---|---|---|---|
| Submitted: | 15 Jul 2005 8:35 | Modified: | 15 Nov 2005 4:57 |
| Reporter: | Dan Makovec | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server | Severity: | S1 (Critical) |
| Version: | 4.1.11-4.1.15 | OS: | Linux (Linux 2.4.22) |
| Assigned to: | CPU Architecture: | Any | |
[15 Jul 2005 8:35]
Dan Makovec
[17 Jul 2005 23:41]
Dan Makovec
FYI, here's further information about our config in case it helps debugging. Here's our my.cnf file: ------------------------------------ [mysqld] #basedir= datadir=/Data/mysql/ tmpdir=/Data/mysqltmp/ port=3306 log-bin server-id=1 innodb_buffer_pool_size=1G innodb_additional_mem_pool_size=20M innodb_log_file_size=250M innodb_log_buffer_size=8M max_binlog_size=104857600 master_user=xxxxx master_password=xxxxx log-slave-updates thread-stack=126K max_connections=200 old-passwords log-slow-queries long-query-time=30 ------------------------------------ SHOW STATUS reveals: ------------------------------------ +----------------------------+------------+ | Variable_name | Value | +----------------------------+------------+ | Aborted_clients | 824 | | Aborted_connects | 323 | | Binlog_cache_disk_use | 13 | | Binlog_cache_use | 51130 | | Bytes_received | 2262997065 | | Bytes_sent | 719944134 | | Com_admin_commands | 5804248 | | Com_alter_db | 0 | | Com_alter_table | 1080 | | Com_analyze | 0 | | Com_backup_table | 0 | | Com_begin | 1452191 | | Com_change_db | 2119225 | | Com_change_master | 0 | | Com_check | 0 | | Com_checksum | 0 | | Com_commit | 1736727 | | Com_create_db | 0 | | Com_create_function | 0 | | Com_create_index | 0 | | Com_create_table | 12129 | | Com_dealloc_sql | 0 | | Com_delete | 1627446 | | Com_delete_multi | 14 | | Com_do | 0 | | Com_drop_db | 0 | | Com_drop_function | 0 | | Com_drop_index | 0 | | Com_drop_table | 14349 | | Com_drop_user | 0 | | Com_execute_sql | 0 | | Com_flush | 104 | | Com_grant | 0 | | Com_ha_close | 0 | | Com_ha_open | 0 | | Com_ha_read | 0 | | Com_help | 0 | | Com_insert | 263212 | | Com_insert_select | 221957 | | Com_kill | 0 | | Com_load | 0 | | Com_load_master_data | 0 | | Com_load_master_table | 0 | | Com_lock_tables | 37 | | Com_optimize | 0 | | Com_preload_keys | 0 | | Com_prepare_sql | 0 | | Com_purge | 2 | | Com_purge_before_date | 0 | | Com_rename_table | 0 | | Com_repair | 0 | | Com_replace | 21 | | Com_replace_select | 1078 | | Com_reset | 0 | | Com_restore_table | 0 | | Com_revoke | 0 | | Com_revoke_all | 0 | | Com_rollback | 2489 | | Com_savepoint | 0 | | Com_select | 17454030 | | Com_set_option | 8600245 | | Com_show_binlog_events | 0 | | Com_show_binlogs | 128 | | Com_show_charsets | 670 | | Com_show_collations | 17593 | | Com_show_column_types | 0 | | Com_show_create_db | 31 | | Com_show_create_table | 1007 | | Com_show_databases | 747 | | Com_show_errors | 0 | | Com_show_fields | 1682 | | Com_show_grants | 28 | | Com_show_innodb_status | 0 | | Com_show_keys | 307 | | Com_show_logs | 0 | | Com_show_master_status | 4 | | Com_show_new_master | 0 | | Com_show_open_tables | 0 | | Com_show_privileges | 0 | | Com_show_processlist | 5357 | | Com_show_slave_hosts | 11 | | Com_show_slave_status | 0 | | Com_show_status | 5342 | | Com_show_storage_engines | 0 | | Com_show_tables | 3284 | | Com_show_variables | 2140381 | | Com_show_warnings | 0 | | Com_slave_start | 0 | | Com_slave_stop | 0 | | Com_truncate | 0 | | Com_unlock_tables | 41 | | Com_update | 2786347 | | Com_update_multi | 6249 | | Connections | 2145717 | | Created_tmp_disk_tables | 429 | | Created_tmp_files | 7658 | | Created_tmp_tables | 478923 | | Delayed_errors | 0 | | Delayed_insert_threads | 0 | | Delayed_writes | 0 | | Flush_commands | 5 | | Handler_commit | 1757785 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_read_first | 1386408 | | Handler_read_key | 553756816 | | Handler_read_next | 830459404 | | Handler_read_prev | 68904 | | Handler_read_rnd | 4989897 | | Handler_read_rnd_next | 121131383 | | Handler_rollback | 2134746 | | Handler_update | 3876646 | | Handler_write | 7488215 | | Key_blocks_not_flushed | 0 | | Key_blocks_unused | 7247 | | Key_blocks_used | 677 | | Key_read_requests | 4441224 | | Key_reads | 8828 | | Key_write_requests | 586802 | | Key_writes | 12378 | | Max_used_connections | 61 | | Not_flushed_delayed_rows | 0 | | Open_files | 11 | | Open_streams | 0 | | Open_tables | 64 | | Opened_tables | 112247 | | Qcache_free_blocks | 0 | | Qcache_free_memory | 0 | | Qcache_hits | 0 | | Qcache_inserts | 0 | | Qcache_lowmem_prunes | 0 | | Qcache_not_cached | 0 | | Qcache_queries_in_cache | 0 | | Qcache_total_blocks | 0 | | Questions | 40827241 | | Rpl_status | NULL | | Select_full_join | 95374 | | Select_full_range_join | 0 | | Select_range | 255444 | | Select_range_check | 0 | | Select_scan | 932852 | | Slave_open_temp_tables | 0 | | Slave_running | OFF | | Slave_retried_transactions | 0 | | Slow_launch_threads | 1 | | Slow_queries | 38 | | Sort_merge_passes | 482 | | Sort_range | 4080838 | | Sort_rows | 41674577 | | Sort_scan | 477452 | | Table_locks_immediate | 26692502 | | Table_locks_waited | 0 | | Threads_cached | 0 | | Threads_connected | 13 | | Threads_created | 2145716 | | Threads_running | 3 | | Uptime | 360950 | +----------------------------+------------+ Finally, SHOW VARIABLES: ------------------------------------ +---------------------------------+------------------------------------------+ | Variable_name | Value | +---------------------------------+------------------------------------------+ | back_log | 50 | | basedir | / | | binlog_cache_size | 32768 | | bulk_insert_buffer_size | 8388608 | | character_set_client | latin1 | | character_set_connection | latin1 | | character_set_database | latin1 | | 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 | | concurrent_insert | ON | | connect_timeout | 5 | | datadir | /Data/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 | | 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 | NO | | have_blackhole_engine | NO | | have_compress | YES | | have_crypt | YES | | have_csv | NO | | have_example_engine | NO | | have_geometry | YES | | have_innodb | YES | | have_isam | NO | | have_ndbcluster | NO | | have_openssl | NO | | 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 | 1073741824 | | innodb_data_file_path | ibdata1:10M:autoextend | | innodb_data_home_dir | | | innodb_fast_shutdown | ON | | innodb_file_io_threads | 4 | | innodb_file_per_table | OFF | | innodb_flush_log_at_trx_commit | 1 | | innodb_flush_method | | | 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 | 8388608 | | innodb_log_file_size | 262144000 | | 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_table_locks | ON | | innodb_thread_concurrency | 8 | | interactive_timeout | 28800 | | join_buffer_size | 131072 | | key_buffer_size | 8388600 | | key_cache_age_threshold | 300 | | key_cache_block_size | 1024 | | key_cache_division_limit | 100 | | language | /usr/share/mysql/english/ | | large_files_support | ON | | license | GPL | | local_infile | ON | | locked_in_memory | OFF | | log | OFF | | log_bin | ON | | log_error | | | log_slave_updates | ON | | log_slow_queries | ON | | log_update | OFF | | log_warnings | 1 | | long_query_time | 30 | | low_priority_updates | OFF | | lower_case_file_system | OFF | | lower_case_table_names | 0 | | max_allowed_packet | 1048576 | | max_binlog_cache_size | 4294967295 | | max_binlog_size | 104857600 | | max_connect_errors | 10 | | max_connections | 200 | | max_delayed_threads | 20 | | max_error_count | 64 | | max_heap_table_size | 16777216 | | max_insert_delayed_threads | 20 | | max_join_size | 4294967295 | | max_length_for_sort_data | 1024 | | max_relay_log_size | 0 | | max_seeks_for_key | 4294967295 | | max_sort_length | 1024 | | max_tmp_tables | 32 | | max_user_connections | 0 | | max_write_lock_count | 4294967295 | | myisam_data_pointer_size | 4 | | myisam_max_extra_sort_file_size | 2147483648 | | myisam_max_sort_file_size | 2147483647 | | myisam_recover_options | OFF | | myisam_repair_threads | 1 | | myisam_sort_buffer_size | 8388608 | | 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 | | pid_file | /Data/mysql//coba01.pid | | port | 3306 | | preload_buffer_size | 32768 | | 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 | 2048 | | read_buffer_size | 131072 | | read_only | OFF | | read_rnd_buffer_size | 262144 | | relay_log_purge | ON | | relay_log_space_limit | 0 | | rpl_recovery_rank | 0 | | secure_auth | OFF | | server_id | 1 | | skip_external_locking | ON | | skip_networking | OFF | | skip_show_database | OFF | | slave_net_timeout | 3600 | | slave_transaction_retries | 0 | | slow_launch_time | 2 | | socket | /var/lib/mysql/mysql.sock | | sort_buffer_size | 2097144 | | sql_mode | | | storage_engine | MyISAM | | sql_notes | OFF | | sql_warnings | OFF | | sync_binlog | 0 | | sync_replication | 0 | | sync_replication_slave_id | 0 | | sync_replication_timeout | 0 | | sync_frm | ON | | system_time_zone | EST | | table_cache | 64 | | table_type | MyISAM | | thread_cache_size | 0 | | thread_stack | 131072 | | time_format | %H:%i:%s | | time_zone | SYSTEM | | tmp_table_size | 33554432 | | tmpdir | /Data/mysqltmp/ | | transaction_alloc_block_size | 8192 | | transaction_prealloc_size | 4096 | | tx_isolation | REPEATABLE-READ | | version | 4.1.11-standard-log | | version_comment | MySQL Community Edition - Standard (GPL) | | version_compile_machine | i686 | | version_compile_os | pc-linux-gnu | | wait_timeout | 28800 | +---------------------------------+------------------------------------------+
[3 Aug 2005 4:42]
Dan Makovec
Hi Hartmut, Have you managed to find the problem? Or do you need more information to assist you?
[5 Sep 2005 23:53]
Dan Makovec
Guys, The issue was reported nearly 2 months ago now and as yet there's no confirmation that the issue is even being looked at. I marked the issue as S1 because applications seriously break when the problem occurs. As I said before, if you need any further information to help fix this I'm only an email away.
[6 Sep 2005 13:42]
Valeriy Kravchuk
Let me try to repeat this problem (I am using Fedora Core 1 too). I'll try on latest 4.1.14 version. A couple of questions to you: 1. Is there something notable in the error log (you may upload part of the .err file for the appropriate period using the File tab). 2. Have you tried newer versions of MySQL? If yes, have you got similar problems? 3. What hardware do you use (RAM, CPU type/etc)?
[7 Sep 2005 0:39]
Dan Makovec
Hi Valeriy, 1. Unfortunately, no - which is the really perplexing part. In terms of purely staying alive, the server is very robust. Here's the log in its entirety (note the date): 050714 05:21:26 mysqld started 050714 5:21:26 InnoDB: Started; log sequence number 3 3907872235 /usr/sbin/mysqld: ready for connections. Version: '4.1.11-standard-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Edition - Standard (GPL) 2. We've experienced the same problem with 4.1.12. After trying one upgrade, we're reluctant to keep performing upgrades on the off-chance the change has been fixed and not documented in the change logs because the nature of the databases means each second of DB downtime is critical. We're hoping to try 4.1.14 on a test system this week. 3. The servers are HP/Compaq ML 530s, quad Xeon 3GHz. Drives are running on an Adaptec AIC7889 SCSI RAID controller. Not sure of the exact specs, but 10,000RPM at 147GB.
[7 Sep 2005 0:40]
Dan Makovec
I forgot to add - 3GB RAM
[16 Sep 2005 12:23]
Valeriy Kravchuk
I will not be able to try verifying it any more really until September 29th, so I'd better leave it unassigned till that time...
[25 Sep 2005 12:24]
Valeriy Kravchuk
Dan, In your last message on September 7th you wrote: "We're hoping to try 4.1.14 on a test system this week." Have you tried to repeat the described behaviour on 4.1.14? Is there anything new to add to this bug report?
[26 Sep 2005 9:01]
Andrejs Dubovskis
I had created similar report #13477 But I am not sure that our problem has identical nature. Please check.
[30 Sep 2005 4:37]
Dan Makovec
We're a little short-handed at the moment, so I won't get around to trying 4.1.14 until 2 weeks. If the problem isn't solved by that upgrade, we'll try some of the solutions in #13477 - this sounds eerily similar to an old problem we used to have on FreeBSD. Will try IP-based authentication followed by "%" host authentication
[30 Sep 2005 13:14]
Valeriy Kravchuk
Please, inform me about the results of 4.1.14 usage. For the time being, I'll be working on http://bugs.mysql.com/bug.php?id=13477 and will inform you about any news on it.
[13 Oct 2005 0:16]
Dan Makovec
We upgraded this morning to 4.1.13 (it was supposed to be 4.1.14 but some testing issues prevented us going with it) and Fedora Core 4 and a much faster server (faster drives in a RAID0+1 config). Still seeing the same problems. We'll be upgrading to 4.1.14 next week but nothing in the changelogs suggests the problem will have disappeared.
[17 Oct 2005 16:47]
Hartmut Holzgraefe
Looks similar to #7209 ( http://bugs.mysql.com/7209 ) to me?
[1 Nov 2005 13:32]
Valeriy Kravchuk
Some time passed... I wonder if you tried to use 4.1.15? Please, try with OUR RPMs, not those provided by Red Hat. But, please, add your further comments to http://bugs.mysql.com/bug.php?id=7209. This bug is decided to be a duplicate of that one. We still need to create a repeatable test case for 7209...
[3 Nov 2005 21:44]
Jacob Martin
I really don't have a simpler test case, but we are having this same problem on: ========================================================= | version | 4.1.15-standard-debug-log | | version_comment | MySQL Community Edition - Standard (GPL) | | version_compile_machine | i686 | | version_compile_os | pc-linux-gnu ========================================================= We have a problem that random SELECT queries will be rejected, when they should be accepted. Then, during the same connection, the query may then start to be accepted again. So, the problem is random, and happens about 1% of the time. A perhaps unrelated problem is that it seems that the DNS cache will sometimes get the wrong FQDN somehow for a user. I think this points to some problem with the host cache's hash function access or something. http://bugs.mysql.com/bug.php?id=10931 For example, we have one person who will log in from x.x.x.x and then get the access denied error saying she is not allowed from y.y.y.y, even thought that is NOT HER IP! When we flush the hosts, then it will think she really has logged in from x.x.x.x. I have found some stuff in the error logs after turning tracing on. Don't know if this is relevant....? ?func: info: New connection received on TCP/IP (144) ?func: info: Host: clc-pc37.chem.uga.edu ip: 128.192.181.100 ?func: info: vio_read returned -1, errno: 11 Note that this is her IP, but that is not the right DNS name! Maybe the host cache's hashtable's keys are wrong? I don't know what errno 11 is...
[15 Nov 2005 4:57]
Dan Makovec
Confirming, the bug is still present in 4.1.15 on our FC4 servers. Damn.
