oracle.jdbc.ReadTimeout はソケット読込時のタイムアウト

Oracle JDBC Thin Diver の oracle.jdbc.ReadTimeout について調べたことをメモ。
Oracle ACE の id:yamadamn さんのスライドがわかりやすいです。

P.11

P.12

まとめ

  • Oracle JDBC Thin Diver の oracle.jdbc.ReadTimeout(ミリ秒) はソケット読込時のタイムアウト
    • スレッドがソケット読込み待ちになった時点からの経過時間でタイムアウトする。
  • ReadTimeout > SetQueryTimeout にする理由
    • SELECT で少しずつ結果セットを受信するようなケースでは問題ないが、実行時間の長い SELECT で最後まで結果セットが帰って来ないケースや UPDATE や DELETE などの DML で SetQueryTimeout を超えていなくても、ReadTimeoutを超えてタイムアウトしてしまうから

検証結果

$ export CLASSPATH=./ojdbc6.jar:.
$ javac TestReadTimeout.java 
$ strace -ff -Ttt -s 200 -o strace_java_log java TestReadTimeout
Error code: 17002
SQL state: 08006
java.sql.SQLRecoverableException: IO Error: Socket read timed out ★ ReadTimeout でタイムアウト発生
	at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1057)
	at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1336)
	at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1916)
	at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1878)
	at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:318)
	at TestReadTimeout.main(TestReadTimeout.java:23)
Caused by: oracle.net.ns.NetException: Socket read timed out
	at oracle.net.ns.Packet.receive(Packet.java:347)
	at oracle.net.ns.DataPacket.receive(DataPacket.java:106)
	at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:324)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:268)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:190)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:107)
	at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
	at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
	at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
	at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:350)
	at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:227)
	at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531)
	at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:195)
	at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:1036)
	... 5 more
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:5416)
	at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1585)
	at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1570)
	at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:94)
	at TestReadTimeout.main(TestReadTimeout.java:41)
  • pstack でコールスタックを見てみる
    • 上記とは別途実行して pstack を取得した結果
    • pstack よりスレッドダンプのほうがわかりやすいですね。
$ java TestReadTimeout &
[1] 23636
$ pstack 23636
Thread 14 (Thread 0x7fc066ebb700 (LWP 23641)):
#0  0x0000003c9b2df0d3 in poll () from /lib64/libc.so.6 ★ poll システムコールで待機している
#1  0x00007fc057aec39e in ?? () from /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.79.x86_64/jre/lib/amd64/libnet.so
#2  0x00007fc057ae7c3c in Java_java_net_SocketInputStream_socketRead0 () from /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.79.x86_64/jre/lib/amd64/libnet.so ★ Java_java_net_SocketInputStream_socketRead0 が呼ばれている
#3  0x00007fc05d012d98 in ?? ()
#4  0x000000000000137d in ?? ()
#5  0x00007fc05d0132ac in ?? ()
#6  0x00007fc066eb9d90 in ?? ()
#7  0x00007fc06770c940 in ?? () from /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.79.x86_64/jre/lib/amd64/server/libjvm.so
#8  0x00007fc05d0061d4 in ?? ()
#9  0x0000000000000000 in ?? ()
$ view strace_java_log.19377
12:50:53.661210 sendto(8, "\0V\0\0\6\0\0\0\0\0\3^\1\2\1!\0\1\1\30\1\1\r\0\0\0\0\2\177\370\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0call dbms_lock.sleep(10)\1\1\1\1\0\0\0\0\0\0\0\0\0\0\0", 86, 0, NULL, 0) = 86 <0.000027>
★↑dbms_lock.sleep(10) を実行して 10 秒スリープ
12:50:53.661321 poll([{fd=8, events=POLLIN|POLLERR}], 1, 4989) = 0 (Timeout) <4.994016>
★↑oracle.jdbc.ReadTimeout で設定した約5秒を超え、タイムアウトしている
12:50:58.655483 lseek(3, 30275151, SEEK_SET) = 30275151 <0.000012>
12:50:58.655567 read(3, "PK\3\4\n\0\0\10\0\0g\10\256F\347pK\356\f\2\0\0\f\2\0\0%\0\0\0", 30) = 30 <0.000011>
12:50:58.655642 lseek(3, 30275218, SEEK_SET) = 30275218 <0.000009>
12:50:58.655705 read(3, "\312\376\272\276\0\0\0003\0\32\n\0\4\0\26\n\0\4\0\27\7\0\30\7\0\31\1\0\20serialVersionUID\1\0\1J\1\0\rConstantValue\5\205:^J\376scT\1\0\6<init>\1\0\25(Ljava/lang/String;)V\1\0\4Code\1\0\17LineNumberTable\1\0\22LocalVariableTable\1\0\4this\1\0!Ljava/net/SocketTimeoutException;\1\0\3m"..., 524) = 524 <0.000010>

JDKソースコード

世の中のサーバサイド Java ではまだ Java 6 を使っているケースのほうが多いのかなと思い、Java 6 のソースコードを調べました。 Java 7 でも似たような感じです(たしか)。

    /**
     *  Enable/disable SO_TIMEOUT with the specified timeout, in ★
     *  milliseconds.  With this option set to a non-zero timeout, ★
     *  a read() call on the InputStream associated with this Socket ★
     *  will block for only this amount of time.  If the timeout expires, ★
     *  a <B>java.net.SocketTimeoutException</B> is raised, though the ★
     *  Socket is still valid. The option <B>must</B> be enabled
     *  prior to entering the blocking operation to have effect. The
     *  timeout must be > 0.
     *  A timeout of zero is interpreted as an infinite timeout.
     * @param timeout the specified timeout, in milliseconds. 
     * @exception SocketException if there is an error
     * in the underlying protocol, such as a TCP error.
     * @since   JDK 1.1
     * @see #getSoTimeout()
     */
    public synchronized void setSoTimeout(int timeout) throws SocketException {
        if (isClosed())
            throw new SocketException("Socket is closed");
        if (timeout < 0)
          throw new IllegalArgumentException("timeout can't be negative");

        getImpl().setOption(SocketOptions.SO_TIMEOUT, new Integer(timeout)); ★
    }
    /**
     * Reads into a byte array <i>b</i> at offset <i>off</i>,
     * <i>length</i> bytes of data.
     * @param b the buffer into which the data is read
     * @param off the start offset of the data
     * @param len the maximum number of bytes read
     * @return the actual number of bytes read, -1 is
     *          returned when the end of the stream is reached.
     * @exception IOException If an I/O error has occurred.
     */
    public int read(byte b[], int off, int length) throws IOException {
        int n;

        // EOF already encountered
        if (eof) {
            return -1;
        }

        // connection reset
        if (impl.isConnectionReset()) {
            throw new SocketException("Connection reset");
        }

        // bounds check
        if (length <= 0 || off < 0 || off + length > b.length) {
            if (length == 0) {
                return 0;
            }
            throw new ArrayIndexOutOfBoundsException();
        }

        boolean gotReset = false;

        // acquire file descriptor and do the read
        FileDescriptor fd = impl.acquireFD();
        try {
            n = socketRead0(fd, b, off, length, impl.getTimeout()); ★socketRead0 を呼んでいる
            if (n > 0) {
                return n;
            }
        } catch (ConnectionResetException rstExc) {
            gotReset = true;
        } finally {
            impl.releaseFD();
        }

        /*
         * We receive a "connection reset" but there may be bytes still
         * buffered on the socket
         */
        if (gotReset) {
            impl.setConnectionResetPending();
            impl.acquireFD();
            try {
                n = socketRead0(fd, b, off, length, impl.getTimeout()); ★socketRead0 を呼んでいる
                if (n > 0) {
                    return n;
                }
            } catch (ConnectionResetException rstExc) {
            } finally {
                impl.releaseFD();
            }
    /**
     * Reads into an array of bytes at the specified offset using
     * the received socket primitive.
     * @param fd the FileDescriptor
     * @param b the buffer into which the data is read
     * @param off the start offset of the data
     * @param len the maximum number of bytes read
     * @param timeout the read timeout in ms ★
     * @return the actual number of bytes read, -1 is
     *          returned when the end of the stream is reached.
     * @exception IOException If an I/O error has occurred.
     */
    private native int socketRead0(FileDescriptor fd, ★ JNI(Java Native Interface) を呼んでいる
                                   byte b[], int off, int len,
                                   int timeout)
        throws IOException;
/*
 * Class:     java_net_SocketInputStream
 * Method:    socketRead0
 * Signature: (Ljava/io/FileDescriptor;[BIII)I
 */
JNIEXPORT jint JNICALL
Java_java_net_SocketInputStream_socketRead0(JNIEnv *env, jobject this,
                                            jobject fdObj, jbyteArray data,
                                            jint off, jint len, jint timeout)
{
    char BUF[MAX_BUFFER_LEN];
    char *bufP;
    jint fd, nread;

    if (IS_NULL(fdObj)) {
        /* should't this be a NullPointerException? -br */
        JNU_ThrowByName(env, JNU_JAVANETPKG "SocketException",
                        "Socket closed");
        return -1;
    } else {
        fd = (*env)->GetIntField(env, fdObj, IO_fd_fdID);
        /* Bug 4086704 - If the Socket associated with this file descriptor
         * was closed (sysCloseFD), the the file descriptor is set to -1.
         */
        if (fd == -1) {
            JNU_ThrowByName(env, "java/net/SocketException", "Socket closed");
            return -1;
        }
    }

    /*
     * If the read is greater than our stack allocated buffer then
     * we allocate from the heap (up to a limit)
     */
    if (len > MAX_BUFFER_LEN) {
        if (len > MAX_HEAP_BUFFER_LEN) {
            len = MAX_HEAP_BUFFER_LEN;
        }
        bufP = (char *)malloc((size_t)len);
        if (bufP == NULL) {
            bufP = BUF;
            len = MAX_BUFFER_LEN;
        }
    } else {
        bufP = BUF;
    }

    if (timeout) { ★
        nread = NET_Timeout(fd, timeout);
        if (nread <= 0) {
            if (nread == 0) {
                JNU_ThrowByName(env, JNU_JAVANETPKG "SocketTimeoutException", ★
                            "Read timed out");
            } else if (nread == JVM_IO_ERR) {
                if (errno == EBADF) {
                     JNU_ThrowByName(env, JNU_JAVANETPKG "SocketException", "Socket closed");
                 } else {
                     NET_ThrowByNameWithLastError(env, JNU_JAVANETPKG "SocketException",
                                                  "select/poll failed");
                 }
            } else if (nread == JVM_IO_INTR) {
                JNU_ThrowByName(env, JNU_JAVAIOPKG "InterruptedIOException",
                            "Operation interrupted");
            }
            if (bufP != BUF) {
                free(bufP);
            }
            return -1;
        }
    }

    nread = NET_Read(fd, bufP, len);

    if (nread <= 0) {
        if (nread < 0) {

            switch (errno) {
                case ECONNRESET:
                case EPIPE:
                    JNU_ThrowByName(env, "sun/net/ConnectionResetException",
                        "Connection reset");
                    break;

                case EBADF:
                    JNU_ThrowByName(env, JNU_JAVANETPKG "SocketException",
                        "Socket closed");
                    break;

                case EINTR:
                     JNU_ThrowByName(env, JNU_JAVAIOPKG "InterruptedIOException",
                           "Operation interrupted");
                     break;

                default:
                    NET_ThrowByNameWithLastError(env,
                        JNU_JAVANETPKG "SocketException", "Read failed");
            }
        }
    } else {
        (*env)->SetByteArrayRegion(view src/solaris/native/java/net/SocketInputStream.c @ 1181:814bf0775b52env, data, off, nread, (jbyte *)bufP);
    }

    if (bufP != BUF) {
        free(bufP);
    }
    return nread;
}
#   Compiler emits things like:  path/file.o: file.h
#   We want something like: relative_path/file.o relative_path/file.d: file.h
CC_DEPEND	 = -MM
CC_DEPEND_FILTER = $(SED) -e 's!$*\.$(OBJECT_SUFFIX)!$(dir $@)& $(dir $@)$*.$(DEPEND_SUFFIX)!g'

ifndef PLATFORM_SRC
  PLATFORM_SRC = $(BUILDDIR)/../src/solaris
endif # PLATFORM_SRC

# Platform specific closed sources
ifndef OPENJDK
  ifndef CLOSED_PLATFORM_SRC
    CLOSED_PLATFORM_SRC = $(BUILDDIR)/../src/closed/solaris
  endif
endif
検証プログラムのソースコード
  • TestReadTimeout.java
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.Statement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.util.Properties;

public class TestReadTimeout {
        public static void main(String args[]) {
                Connection conn = null;
                Statement stmt = null;
                ResultSet resultSet = null;
                try {
                        Class.forName ("oracle.jdbc.driver.OracleDriver");
			java.util.Properties info = new java.util.Properties();
			info.put ("user", "scott");
			info.put ("password","tiger");
			info.put ("oracle.jdbc.ReadTimeout","4989");
                        conn = DriverManager.getConnection
                                ("jdbc:oracle:thin:@dbserver:1521:orcl",info);
                        for(;;) {
                            stmt = conn.createStatement();
                            stmt.execute("call dbms_lock.sleep(10)");
                        }
                } catch (SQLException e) {
                        System.out.println("Error code: " + e.getErrorCode());
                        System.out.println("SQL state: " + e.getSQLState());
                        e.printStackTrace();
                } catch (ClassNotFoundException e) {
                        e.printStackTrace();
                } finally {
                        try {
                                if (resultSet != null) {
                                        resultSet.close();
                                }
                        } catch (SQLException e){
                                e.printStackTrace();
                        }
                        try {
                                if (stmt != null) {
                                        stmt.close();
                                }
                        } catch (SQLException e){
                                e.printStackTrace();
                        }
                        try {
                                if (conn != null) {
                                        conn.close();
                                }
                        } catch (SQLException e){
                                e.printStackTrace();
                        }
                }
        }
}