2

I am encountering some strange behaviour. I have a Java programm that permanently writes data to a MySQL table using prepared statements and batch inserts. If some other process issues a LOCK TABLES t WRITE on the same table, and releases it shortly thereafter (after a few minutes), the Java program continues as expected. However, when the locking sustains for a longer period (more than 30 minutes), the Java program looses connection and does not continue. After 2 hours, it fails with a Communications link failure. The insert statement that is pending during table lock is executed after the lock is released, but the connection is gone afterwards.

Here are the details:

  • it happens on both MySQL 5.0.51a and 5.1.66
  • I'm using the most recent JDBC driver mysql-connector-5.1.25-bin.jar
  • the wait_timeout is set to 28800 (8 hours)
  • the stack trace of the Communications link failure and the Java program are given below

Does anyone know what's going on here? Are there any timeouts I need to set/increase?

The exception thrown after two hours:

Exception in thread "main" java.sql.BatchUpdateException: Communications link failure

The last packet successfully received from the server was 7.260.436 milliseconds ago.  The last packet sent successfully to the server was 7.210.431 milliseconds ago.
    at com.mysql.jdbc.PreparedStatement.executeBatchedInserts(PreparedStatement.java:1836)
    at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1456)
    at com.mysql.jdbc.CallableStatement.executeBatch(CallableStatement.java:2499)
    at main.LockTest.main(LockTest.java:26)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 7.260.436 milliseconds ago.  The last packet sent successfully to the server was 7.210.431 milliseconds 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:411)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1121)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3670)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4110)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375)
    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359)
    at com.mysql.jdbc.PreparedStatement.executeBatchedInserts(PreparedStatement.java:1792)
    ... 3 more
Caused by: java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
    at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
    at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3570)
    ... 13 more

The full Java program:

package main;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.SQLException;
import java.util.Date;

public class LockTest {

    private static final String CONNECTION_PATTERN = "jdbc:mysql://%s/?user=%s&password=%s"
            + "&autoReconnect=true&rewriteBatchedStatements=true&characterEncoding=utf8";
    private static final String QUERY = "INSERT INTO test.lock_test (random_text) VALUES (?)";

    public static void main(String[] args) throws SQLException, InterruptedException {
        Connection con = DriverManager.getConnection(String.format(CONNECTION_PATTERN, "host", "user", "pw"));
        PreparedStatement ps = con.prepareCall(QUERY);
        int i = 0;
        while (true) {
            i++;
            ps.setString(1, Long.toString(System.currentTimeMillis()));
            ps.addBatch();
            if (i % 10 == 0) {
                ps.executeBatch();
                System.out.println(new Date() + ": inserting 10 rows");
            }
            Thread.sleep(5000);
        }
    }
}
twonkeys
  • 552
  • 6
  • 11

2 Answers2

4

Finally, I found out about the real reason. MySQL's wait_timeout has nothing to do with problem--as long as a statement is running (no matter for how long), the database session is not in the state SLEEP and hence the session will never be closed by MySQL.

The reason seems to be the Linux operating system (Debian 6 or 7), which closes the tcp connection after being idle for 2 hours (the concrete mechanism is unknown to me, maybe someone can elaborate on this?).

To avoid the described timeouts, one needs to send more frequent tcp keep alive packets. To do so, one has to decrease /proc/sys/net/ipv4/tcp_keepalive_time (I decreased it from 7,200 to 60). cat 60 > /proc/sys/net/ipv4/tcp_keepalive_time does this temporarily; to retain it after a system reboot, one has to set net.ipv4.tcp_keepalive_time=60 in /etc/sysctl.conf.

twonkeys
  • 552
  • 6
  • 11
  • I cannot change the content of my keep alive file `tcp_keepalive_time" E667: Fsynch has failed` using `vi`. I had to do it like this: `root@sd-53310:/home/ocatelin# echo 60 | sudo dd of=/proc/sys/net/ipv4/tcp_keepalive_time 0+1 enregistrements lus 0+1 enregistrements écrits 3 octets (3 B) copiés, 2,4948e-05 s, 120 kB/s root@sd-53310:/home/ocatelin# cat /proc/sys/net/ipv4/tcp_keepalive_time 60` – Stephane Mar 25 '17 at 09:35
1

I just search the same question. I think my answer can help you .

  1. view your exception

The last packet successfully received from the server was 7.260.436 milliseconds ago.

That's apparently means that 7.260.436 milliseconds < wait_timeout is set to 28800

2.If your application throws exception because the wait_timeout is too small. The exception show like this:

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 46,208,149 milliseconds ago.  The last packet sent successfully to the server was 46,208,150 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
; SQL []; The last packet successfully received from the server was 46,208,149 milliseconds ago.  
The last packet sent successfully to the server was 46,208,150 milliseconds ago.
 is longer than the server configured value of 'wait_timeout'. 
 You should consider either expiring and/or testing connection validity before use in your application, 
 increasing the server configured values for client timeouts,
 or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.;

that means 46,208,150 milliseconds ago > wait_timeout

  1. Answer !!!

Be attention to the following key word "Communications link failure" ,this is mostly about MySQl variables: net_write_timeout or net_read_timeout。

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

the default value of net_write_timeout and net_read_timeout is small ,you can execute 

 mysql> show variables like '%timeout%';
to find the result.
wish lv
  • 21
  • 3