views:

1303

answers:

6

I recently discovered that a sql query that was running fine earlier is now timing out after 60 seconds and throwing an error. The query is slow but runs as part of a nightly job so that's not a problem in itself (so please don't suggest I optimize it).

I'm able to reproduce the error consistently by running "select SLEEP(120);" from PHP as shown below. However, running the same statement from a MySQL client is successful (returns 0). I've tried adjusting wait_timeout (set to 28800), but have had no luck. I've also rebooted both the db server and machine itself.

The fact that it always times out at exactly 60 seconds suggests to me that it is likely to be a setting and not a limited resources issue.

I'm running:
Windows Server 2003
MySql 5.1.36-community
PHP 5.3

Below are my test code, the output and the results from SHOW VARIABLES

Thanks!

CODE:

set_error_handler("sqlErrorHandler");
set_time_limit(12000);


$link = mysql_connect("$MYSQL_Host","$MYSQL_User","$MYSQL_Pass");
mysql_select_db($MYSQL_db, $link);

echo "mysql_ping = " . (mysql_ping($link) ? "LIVE" : "DEAD") . "<br /><br />"; 

$sql = "SELECT SLEEP(120);";

$start = microtime(true);
mysql_query($sql, $link);

echo "**query done**<br />";
allDone();

function allDone(){
 global $start, $sql;

 $end = microtime(true);
 echo "sql : $sql<br />";
 echo "elapsed : " . ($end - $start) . "<br />";
 echo "<br />";
}

function sqlErrorHandler($errno, $errstr, $errfile, $errline){
 global $link;
 echo "Error : $errno<br />$errstr<br />";
 echo "mysql_ping : " . (mysql_ping($link) ? "LIVE" : "DEAD") . "<br />"; 
 echo "<br />";

 allDone();
}

OUTPUT :

mysql_ping = LIVE

Error : 2
mysql_query() [function.mysql-query]: MySQL server has gone away
mysql_ping : DEAD

sql : SELECT SLEEP(120);
elapsed : 60.051116943359

Error : 2
mysql_query() [function.mysql-query]: Error reading result set's header
mysql_ping : DEAD

sql : SELECT SLEEP(120);
elapsed : 60.0511469841

**query done**
sql : SELECT SLEEP(120);
elapsed : 60.051155090332

SHOW VARIABLES:

Variable_name=Value
auto_increment_increment=1
auto_increment_offset=1
autocommit=ON
automatic_sp_privileges=ON
back_log=50
basedir=C:\\Program Files\\MySQL\\MySQL Server 5.1\\
big_tables=OFF
binlog_cache_size=32768
binlog_format=STATEMENT
bulk_insert_buffer_size=8388608
character_set_client=utf8
character_set_connection=utf8
character_set_database=latin1
character_set_filesystem=binary
character_set_results=utf8
character_set_server=latin1
character_set_system=utf8
character_sets_dir=C:\\Program Files\\MySQL\\MySQL Server 5.1\\share\\charsets\\
collation_connection=utf8_general_ci
collation_database=latin1_swedish_ci
collation_server=latin1_swedish_ci
completion_type=0
concurrent_insert=1
connect_timeout=10
datadir=C:\\Documents and Settings\\All Users\\Application Data\\MySQL\\MySQL Server 5.1\\Data\\
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
engine_condition_pushdown=ON
error_count=0
event_scheduler=OFF
expire_logs_days=0
flush=OFF
flush_time=1800
foreign_key_checks=ON
ft_boolean_syntax=+ -><()~*:""&|
ft_max_word_len=84
ft_min_word_len=4
ft_query_expansion_limit=20
ft_stopword_file=(built-in)
general_log=OFF
general_log_file=C:\\Documents and Settings\\All Users\\Application Data\\MySQL\\MySQL Server 5.1\\Data\\p1.log
group_concat_max_len=1024
have_community_features=YES
have_compress=YES
have_crypt=NO
have_csv=YES
have_dynamic_loading=YES
have_geometry=YES
have_innodb=YES
have_ndbcluster=NO
have_openssl=DISABLED
have_partitioning=YES
have_query_cache=YES
have_rtree_keys=YES
have_ssl=DISABLED
have_symlink=YES
identity=0
ignore_builtin_innodb=OFF
init_connect=
init_file=
init_slave=
innodb_adaptive_hash_index=ON
innodb_additional_mem_pool_size=2097152
innodb_autoextend_increment=8
innodb_autoinc_lock_mode=1
innodb_buffer_pool_size=96468992
innodb_checksums=ON
innodb_commit_concurrency=0
innodb_concurrency_tickets=500
innodb_data_file_path=ibdata1:10M:autoextend
innodb_data_home_dir=D:\\MySQL Datafiles\\
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=
innodb_force_recovery=0
innodb_lock_wait_timeout=50
innodb_locks_unsafe_for_binlog=OFF
innodb_log_buffer_size=1048576
innodb_log_file_size=19922944
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_stats_on_metadata=ON
innodb_support_xa=ON
innodb_sync_spin_loops=20
innodb_table_locks=ON
innodb_thread_concurrency=8
innodb_thread_sleep_delay=10000
innodb_use_legacy_cardinality_algorithm=ON
insert_id=0
interactive_timeout=28800
join_buffer_size=131072
keep_files_on_create=OFF
key_buffer_size=50331648
key_cache_age_threshold=300
key_cache_block_size=1024
key_cache_division_limit=100
language=C:\\Program Files\\MySQL\\MySQL Server 5.1\\share\\english\\
large_files_support=ON
large_page_size=0
large_pages=OFF
last_insert_id=0
lc_time_names=en_US
license=GPL
local_infile=ON
log=OFF
log_bin=OFF
log_bin_trust_function_creators=OFF
log_bin_trust_routine_creators=OFF
log_error=C:\\Documents and Settings\\All Users\\Application Data\\MySQL\\MySQL Server 5.1\\Data\\p1.err
log_output=FILE
log_queries_not_using_indexes=OFF
log_slave_updates=OFF
log_slow_queries=OFF
log_warnings=1
long_query_time=10.000000
low_priority_updates=OFF
lower_case_file_system=ON
lower_case_table_names=1
max_allowed_packet=1048576
max_binlog_cache_size=4294963200
max_binlog_size=1073741824
max_connect_errors=10
max_connections=800
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=4294967295
max_sort_length=1024
max_sp_recursion_depth=0
max_tmp_tables=32
max_user_connections=0
max_write_lock_count=4294967295
min_examined_row_limit=0
multi_range_count=256
myisam_data_pointer_size=6
myisam_max_sort_file_size=107374182400
myisam_recover_options=OFF
myisam_repair_threads=1
myisam_sort_buffer_size=12582912
myisam_stats_method=nulls_unequal
myisam_use_mmap=OFF
named_pipe=OFF
net_buffer_length=16384
net_read_timeout=30
net_retry_count=10
net_write_timeout=80
new=OFF
old=OFF
old_alter_table=OFF
old_passwords=OFF
open_files_limit=2048
optimizer_prune_level=1
optimizer_search_depth=62
optimizer_switch=index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on
pid_file=C:\\Documents and Settings\\All Users\\Application Data\\MySQL\\MySQL Server 5.1\\Data\\p1.pid
plugin_dir=C:\\Program Files\\MySQL\\MySQL Server 5.1\\lib/plugin
port=3306
preload_buffer_size=32768
profiling=OFF
profiling_history_size=15
protocol_version=10
pseudo_thread_id=3230
query_alloc_block_size=8192
query_cache_limit=1048576
query_cache_min_res_unit=4096
query_cache_size=33554432
query_cache_type=ON
query_cache_wlock_invalidate=OFF
query_prealloc_size=8192
rand_seed1=
rand_seed2=
range_alloc_block_size=4096
read_buffer_size=65536
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
report_host=
report_password=
report_port=3306
report_user=
rpl_recovery_rank=0
secure_auth=OFF
secure_file_priv=
server_id=0
shared_memory=OFF
shared_memory_base_name=MYSQL
skip_external_locking=ON
skip_networking=OFF
skip_show_database=OFF
slave_compressed_protocol=OFF
slave_exec_mode=STRICT
slave_load_tmpdir=C:\\WINDOWS\\TEMP
slave_net_timeout=3600
slave_skip_errors=OFF
slave_transaction_retries=10
slow_launch_time=2
slow_query_log=OFF
slow_query_log_file=C:\\Documents and Settings\\All Users\\Application Data\\MySQL\\MySQL Server 5.1\\Data\\p1-slow.log
sort_buffer_size=262144
sql_auto_is_null=ON
sql_big_selects=ON
sql_big_tables=OFF
sql_buffer_result=OFF
sql_log_bin=ON
sql_log_off=OFF
sql_log_update=ON
sql_low_priority_updates=OFF
sql_max_join_size=18446744073709551615
sql_mode=
sql_notes=ON
sql_quote_show_create=ON
sql_safe_updates=OFF
sql_select_limit=18446744073709551615
sql_slave_skip_counter=
sql_warnings=OFF
ssl_ca=
ssl_capath=
ssl_cert=
ssl_cipher=
ssl_key=
storage_engine=InnoDB
sync_binlog=0
sync_frm=ON
system_time_zone=Eastern Daylight Time
table_definition_cache=256
table_lock_wait_timeout=50
table_open_cache=619
table_type=InnoDB
thread_cache_size=38
thread_handling=one-thread-per-connection
thread_stack=196608
time_format=%H:%i:%s
time_zone=SYSTEM
timed_mutexes=OFF
timestamp=1256827484
tmp_table_size=16777216
tmpdir=C:\\WINDOWS\\TEMP
transaction_alloc_block_size=8192
transaction_prealloc_size=4096
tx_isolation=REPEATABLE-READ
unique_checks=ON
updatable_views_with_limit=YES
version=5.1.36-community
version_comment=MySQL Community Server (GPL)
version_compile_machine=ia32
version_compile_os=Win32
wait_timeout=28800
warning_count=0
+3  A: 

The mysql.connect_timeout option is the reason for this. It's not only used for connect timeout, but as well as waiting for the first answer from the server. You can increase it like this:

ini_set('mysql.connect_timeout', 300);
ini_set('default_socket_timeout', 300);
reko_t
I thought that was going to work, but it didn't change anything.
Bill
Did you set it before connecting or after?
reko_t
before. First line of the script
Bill
and I did an ini_get to verify the new value
Bill
Try this with it if you're connecting via a socket (eg. localhost):ini_set('default_socket_timeout', 60);
reko_t
YES! Adding ini_set('default_socket_timeout', 300) did it. Thanks!!
Bill
+1  A: 

There's a whole bunch of things that can cause this. I'd read through these and try each of them

http://dev.mysql.com/doc/refman/5.1/en/gone-away.html

I've worked for several web hosting companies over the years and generally when I see this, it is the wait_timeout on the server end though this doesn't appear to be the case here.

If you find the solution, I hope you post it. I'd like to know.

Seth
I went over that page a few times before posting here. Nothing seems to work. Thanks though
Bill
A: 

I am migrating a wamp2 install with PHP5.2.6, Apache 2.2.8, MySQL 5.0.51b to wamp2 PHP5.3, Apache 2.2.11 and MySQL 5.1.36. I have the same configuration as yours: Windows 2003 Server. While everything worked fine in hold version, in the new one, connections drop exactly after 60 secs. I can see the query is still running on the server but I get disconnected after this time with the error message: "MySQL Server has gone away". I tried to upgrade MySQL version to 5.1.40 but without any improvement. I scanned drives to find any parameters set to "60" without finding one I could change to help. It is definitely not the max_packet_size (set to 16M!) as I am not transmitting any database data but just the time necessary for the query run. A bit desperate on this one.

Damien Goor
A: 

Ok, I was able to apply the solution here above: ini_set('mysql.connect_timeout', 300); ini_set('default_socket_timeout', 300);

In my php.ini file, I had "default_socket_timeout" set to "60", I change it to "-1" (no limit which is OK for my usage of MySQL) and it is OK. What is not clear to me is that in my old configuration (PHP 5.2) this parameter was also set to "60" and has never given any timeout problem.

Damien Goor
A: 

I noticed something perhaps relevant.

I had two scripts running, both doing rather slow queries. One of them locked a table and the other had to wait. The one that was waiting had default_socket_timeout = 300. Eventually it quit with "MySQL server has gone away". However, the mysql process list continued to show both query, the slow one still running and the other locked and waiting.

So I don't think mysqld is the culprit. Something has changed in the php mysql client. Quite possibly the default_socket_timeout which I will now set to -1 to see if that changes anything.

fsb
A: 

My case was a database corruption after a minor upgrade in mysql basically 5.0.x to 5.1.x with the DB in myisam. The same lines on query: MySQL server has gone away Error reading result set's header

After repairing & optimizing it with mysqlcheck, it returned to normal, without the need to change the socket timeout.

levis3