Oracle JDBC Thin Diver の oracle.jdbc.ReadTimeout について調べたことをメモ。
Oracle ACE の id:yamadamn さんのスライドがわかりやすいです。
P.11
P.12
まとめ
検証結果
$ 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 ?? ()
- strace で取得したシステムコールのトレースを見てみる
$ 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)); ★ }
- java.net.SocketInputStream#read
- java.net.SocketInputStream#read がソケットを read するメソッド
/** * 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(); }
- java.net.SocketInputStream#socketRead0
- read から呼ばれている socketRead0
/** * 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(); } } } }
