Upgrading to SQL Connector/J 5.X triggers "Connection timed out" exceptions

[joachim peer]

Hi all!

since several days, i am trying to solve a puzzling mysql connection problem . I am posting it here in the hope that somebody has a hint about how to find the core of the problem:

we were using mysql-connector-j 3.X for many years, it works flawlessly. However, after after switching to mysql-connector-j 5 (5.0.X, 5.1.X), our programs suddenly experience spontaneous network timeouts. No other TCP/IP applications are affected, it can also happen when connecting to local server, and as a soon as we switch back to 3.X, all works fine again.

usually, our programs have a live span of only several hours, open connections to db's which are kept alive by periodic sending of "select o" pings. wait_timeout on server is set to a high value... -> this has worked for us very well in the past.

but now our queries (sometimes after 3 minutes, sometimes only after 2,3 hours) run into problems with timeouts.

Here a typical stacktrace:

- - - - - - - - - - - - - - - - - -
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
Last packet sent to the server was 13 ms ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1074)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3134)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1818)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2537)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2466)
at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1383)
at DatabaseTimeoutTest.main(DatabaseTimeoutTest.java:25)
Caused by: java.net.SocketException: Connection timed out
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3119)
... 6 more


On our machines, it can be reproduced by running this little program.

- - - - - - - - - - - - - - - - - -
import java.sql.*;
public
class DatabaseTimeoutTest {
public static void main(String[] anArgs) {
try {
int aDelay = Integer.parseInt(anArgs[0]);
String myConnection = anArgs[1];
String myUser = anArgs[2];
String myPwd = anArgs[3];

Class.forName(com.mysql.jdbc.Driver.class.getName());
Connection myCon = DriverManager.getConnection(myConnection, myUser, myPwd);

for (int i = 0;; i++) {
System.out.println("Ping nr " + i);
Statement myStatement = myCon.createStatement();
myStatement.executeQuery("SELECT 0");
Thread.sleep(aDelay * 1000);
}
}
catch (Exception e) {
e.printStackTrace();
}
}
}


By the way, it does not matter whether "SELECT 0" or "/* ping */ SELECT 0" is used. the timeouts happen in both cases.


~~~~~~~~

when i run mysqld with --log-warnings enabled, i see ouputs of following types:


081004 20:14:57 [Warning] Aborted connection 3 to db: 'my_database_name' user: 'myusername' host: 'myhostname' (Got an error reading communication packets)


~~~~~~~~

Now, it seems that this can not be a 'general' or obvious bug/issue of mysql-connector 5, because with the large user base the error could not go unnoticed for so long.

Nevertheless, so far this problem surfaces on all hardware/software combinations i tried out so far, so maybe we are not the only ones:

- Java Clients
-- running on fedora core 6-8, 32 bit and 64 bit,
-- various versions of Sun JVM 1.6.X
- MySQL servers (version 5.0.26)
-- running on 32 and 64 bit machines, also fedora core 6,8


Here the setup of one of the servers

mysql> show variables;
+---------------------------------+------------------------------------------------------+
| Variable_name | Value |
+---------------------------------+------------------------------------------------------+
| auto_increment_increment | 1 |
| auto_increment_offset | 1 |
| automatic_sp_privileges | ON |
| back_log | 50 |
| basedir | /opt/linux/x86_64/mysql/5.0.26/ |
| 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 | /opt/linux/x86_64/mysql/5.0.26/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 | 5 |
| datadir | /home/mysql/5.0.26/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 | 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 | YES |
| have_bdb | NO |
| 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 | DISABLED |
| have_isam | NO |
| have_merge_engine | YES |
| 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 | 1048576 |
| innodb_autoextend_increment | 8 |
| innodb_buffer_pool_awe_mem_mb | 0 |
| innodb_buffer_pool_size | 8388608 |
| innodb_checksums | ON |
| innodb_commit_concurrency | 0 |
| innodb_concurrency_tickets | 500 |
| innodb_data_file_path | |
| innodb_data_home_dir | |
| 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_arch_dir | |
| innodb_log_archive | OFF |
| innodb_log_buffer_size | 1048576 |
| innodb_log_file_size | 5242880 |
| 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_support_xa | ON |
| innodb_sync_spin_loops | 20 |
| innodb_table_locks | ON |
| innodb_thread_concurrency | 8 |
| innodb_thread_sleep_delay | 10000 |
| interactive_timeout | 28800 |
| join_buffer_size | 131072 |
| key_buffer_size | 402653184 |
| key_cache_age_threshold | 300 |
| key_cache_block_size | 1024 |
| key_cache_division_limit | 100 |
| language | /opt/linux/x86_64/mysql/5.0.26/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 | 1047552 |
| max_binlog_cache_size | 18446744073709551615 |
| max_binlog_size | 1073741824 |
| max_connect_errors | 10 |
| max_connections | 1000 |
| 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 | 9223372036854775807 |
| myisam_recover_options | OFF |
| myisam_repair_threads | 1 |
| myisam_sort_buffer_size | 67108864 |
| 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 | OFF |
| open_files_limit | 5010 |
| optimizer_prune_level | 1 |
| optimizer_search_depth | 62 |
| pid_file | /home/mysql/5.0.26/data//myhostname.pid |
| port | 3306 |
| preload_buffer_size | 32768 |
| prepared_stmt_count | 0 |
| protocol_version | 10 |
| 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 |
| range_alloc_block_size | 2048 |
| read_buffer_size | 2093056 |
| read_only | OFF |
| read_rnd_buffer_size | 8384512 |
| relay_log_purge | ON |
| relay_log_space_limit | 0 |
| rpl_recovery_rank | 0 |
| secure_auth | OFF |
| server_id | 0 |
| skip_external_locking | ON |
| skip_networking | OFF |
| skip_show_database | OFF |
| slave_compressed_protocol | OFF |
| slave_load_tmpdir | /home/mysql/5.0.26/tmp/ |
| slave_net_timeout | 3600 |
| slave_skip_errors | OFF |
| slave_transaction_retries | 10 |
| slow_launch_time | 2 |
| socket | /tmp/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 | CEST |
| table_cache | 512 |
| table_lock_wait_timeout | 50 |
| table_type | MyISAM |
| thread_cache_size | 8 |
| thread_stack | 262144 |
| time_format | %H:%i:%s |
| time_zone | SYSTEM |
| timed_mutexes | OFF |
| tmp_table_size | 8388608 |
| tmpdir | /home/mysql/5.0.26/tmp/ |
| transaction_alloc_block_size | 8192 |
| transaction_prealloc_size | 4096 |
| tx_isolation | REPEATABLE-READ |
| updatable_views_with_limit | YES |
| version | 5.0.26-standard |
| version_comment | MySQL Community Edition - Standard (GPL) |
| version_compile_machine | x86_64 |
| version_compile_os | unknown-linux-gnu |
| wait_timeout | 28800 |
+---------------------------------+------------------------------------------------------+
220 rows in set (0.00 sec)


Linux networks settings in general are pretty standards, with following timeout settings:

/proc/sys/net/ipv4/tcp_keepalive_time: 10
/proc/sys/net/ipv4/tcp_keepalive_probes: 2
/proc/sys/net/ipv4/tcp_keepalive_intvl: 4
/proc/sys/net/ipv4/tcp_window_scaling: 0

And, interestingly the error can also be reproduced when connecting to the server from the same host!
=> this is why i believe it's a software (network stack) issue, not network issue per se.


i also tried various setting on the JDBC connections themselves, such as socketTimeout=... but the basic problem of "spontaneous" connection timeouts stayed.

however this does NOT happen with older versions of the driver! i am not 100% sure which driver version it exactly, is, i think around 3.1.10, that jar has 409191 bytes.

~~~~~~~~~~~~

So, these are the facts as i gathered them up till now. The only thing which i know for sure is that switching JDBC versions solves/creates the problem

my questions:

- did anybody else experience this or something similar?

- are there any other diagnostic tools you would recommend?

- is there any kind of feature in sql connector j 5.x which could be related to that? Is the new driver more sensitive to potentially flakey network/tpc-ip-stack settings?

- any other hints? :-)


thanks in advance for any input!
kind regards
Joachim