ablog

不器用で落着きのない技術者のメモ

Oracle Database のサーバー・プロセスが通信する際にどのようなソケットオプションを使っているか調べる

環境

  • OS
[root@localhost ~]# cat /etc/issue
Enterprise Linux Enterprise Linux Server release 5.5 (Carthage)
Kernel \r on an \m

[root@localhost ~]# uname -a
Linux localhost.localdomain 2.6.18-194.17.1.0.1.el5 #1 SMP Wed Sep 29 15:40:03 EDT 2010 i686 i686 i386 GNU/Linux
SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
PL/SQL Release 11.2.0.2.0 - Production
CORE    11.2.0.2.0      Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production
[oracle@localhost OPatch]$ ./opatch lsinventory
...
Installed Top-level Products (1): 

Oracle Database 11g                                                  11.2.0.2.0
There are 1 products installed in this Oracle Home.


There are no Interim patches installed in this Oracle Home.

strace でシステムコールをトレースする

  • リスナープロセスの PID を調べる。
[root@localhost ~]# ps -ef|grep [t]ns
oracle    3249     1  0 19:35 ?        00:00:00 /home/oracle/app/oracle/product/11.2.0/dbhome_2/bin/tnslsnr LISTENER -inherit
  • strace でリスナープロセスと fork されるプロセスのシステムコールをトレースする。
[root@localhost ~]# strace -tf -p 3249 -o strace.log
  • テストケース実行後、setsockopt でどのようなソケットオプションを使用しているか調べる。
[root@localhost ~]# grep -i setsockopt strace.log
3250  20:12:35 setsockopt(14, SOL_SOCKET, SO_LINGER, {onoff=1, linger=900}, 8) = 0
3249  20:12:36 setsockopt(14, SOL_TCP, TCP_NODELAY, [1], 4) = 0
3601  20:12:36 setsockopt(14, SOL_TCP, TCP_NODELAY, [1], 4) = 0
3601  20:12:37 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
3601  20:12:37 setsockopt(14, SOL_SOCKET, SO_SNDTIMEO, "\0\0\0\0\0\0\0\0", 8) = 0
3601  20:12:37 setsockopt(14, SOL_SOCKET, SO_RCVTIMEO, "\0\0\0\0\0\0\0\0", 8) = 0
3601  20:12:37 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, [0], 4) = 0
3250  20:12:40 setsockopt(14, SOL_SOCKET, SO_LINGER, {onoff=1, linger=900}, 8) = 0
3249  20:12:40 setsockopt(14, SOL_TCP, TCP_NODELAY, [1], 4) = 0
3603  20:12:40 setsockopt(14, SOL_TCP, TCP_NODELAY, [1], 4) = 0
3603  20:12:40 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
3603  20:12:41 setsockopt(14, SOL_SOCKET, SO_SNDTIMEO, "\0\0\0\0\0\0\0\0", 8) = 0
3603  20:12:41 setsockopt(14, SOL_SOCKET, SO_RCVTIMEO, "\0\0\0\0\0\0\0\0", 8) = 0
3603  20:12:41 setsockopt(14, SOL_SOCKET, SO_KEEPALIVE, [0], 4) = 0

Oracle Net トレース・ファイルから確認する

  • Oracle Database の sqlnet.ora にトレース・レベルを設定する
[oracle@localhost ~]$ cat /home/oracle/app/oracle/product/11.2.0/dbhome_2/network/admin/sqlnet.ora 
TRACE_LEVEL_SERVER=16
  • テストケース実行後、トレース・ファイルを確認する。
[oracle@localhost trace]$ grep testc *
orcl_ora_3564.trc:2013-04-20 20:09:41.321368 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3566.trc:2013-04-20 20:09:42.272207 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3579.trc:2013-04-20 20:10:59.363429 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3581.trc:2013-04-20 20:11:04.073404 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3590.trc:2013-04-20 20:11:35.457958 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3601.trc:2013-04-20 20:12:37.614055 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
orcl_ora_3603.trc:2013-04-20 20:12:41.459677 : nsbasic_brc:2F 2A 20 74 65 73 74 63  |/*.testc|
  • トレース・ファイルの中身を確認する。
[oracle@localhost trace]$ grep -i tcp orcl_ora_3601.trc
2013-04-20 20:12:36.959360 : nsinh_hoff:ADR="(ADDRESS=(PROTOCOL=tcp)(DEV=14)(HOST=192.168.56.101)(PORT=1521))"
2013-04-20 20:12:36.959715 : nsc2addr:(ADDRESS=(PROTOCOL=tcp)(DEV=14)(HOST=192.168.56.101)(PORT=1521))
2013-04-20 20:12:36.966778 : nttcon:NT layer TCP/IP connection has been established.
2013-04-20 20:12:36.966984 : nttcon:set TCP_NODELAY on 14
2013-04-20 20:12:37.002025 : nsprecv:3D 74 63 70 29 28 48 4F  |=tcp)(HO|
2013-04-20 20:12:37.100779 : nsgetclientaddress:Client address: "(ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.1)(PORT=1849))"
[oracle@localhost trace]$ grep -i tcp orcl_ora_3603.trc
2013-04-20 20:12:40.797698 : nsinh_hoff:ADR="(ADDRESS=(PROTOCOL=tcp)(DEV=14)(HOST=192.168.56.101)(PORT=1521))"
2013-04-20 20:12:40.798505 : nsc2addr:(ADDRESS=(PROTOCOL=tcp)(DEV=14)(HOST=192.168.56.101)(PORT=1521))
2013-04-20 20:12:40.806009 : nttcon:NT layer TCP/IP connection has been established.
2013-04-20 20:12:40.806195 : nttcon:set TCP_NODELAY on 14
2013-04-20 20:12:40.841755 : nsprecv:3D 74 63 70 29 28 48 4F  |=tcp)(HO|
2013-04-20 20:12:40.941021 : nsgetclientaddress:Client address: "(ADDRESS=(PROTOCOL=tcp)(HOST=192.168.56.1)(PORT=1851))"

テスト手順

  • Oracle Database の sqlnet.ora にトレース・レベル(16)を設定する。
  • strace でリスナープロセスと fork されるプロセスのシステムコールをトレースする。
  • テストプログラムを実行する。
exec_testcase1.bat
exec_testcase2.bat

テストに使ったファイル

  • set_env.bat
set JAVA_HOME=C:\Program Files\Java\jdk1.5.0_22
set PATH=%JAVA_HOME%\bin;%PATH%
  • build_testcase1.bat
call set_env.bat
%~d0
cd %~p0
set CLASSPATH=.;ojdbc5.jar
javac TestCase1.java
pause
  • build_testcase2.bat
call set_env.bat
%~d0
cd %~p0
set CLASSPATH=.;ojdbc5.jar
javac TestCase2.java
pause
  • exec_testcase1.bat
call set_env.bat
%~d0
cd %~p0
set CLASSPATH=.;ojdbc5.jar
java TestCase1
pause
  • exec_testcase2.bat
call set_env.bat
%~d0
cd %~p0
set CLASSPATH=.;ojdbc5.jar
java TestCase2
pause
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.Statement;
import java.sql.ResultSet;
import java.sql.SQLException;

public class TestCase1 {
	public static void main(String args[]) {
		Connection conn = null;
		Statement stmt = null;
		ResultSet resultSet = null;
		try {
			Class.forName ("oracle.jdbc.driver.OracleDriver");
			conn = DriverManager.getConnection("jdbc:oracle:thin:@192.168.56.101:1521:orcl","system","manager");
			stmt = conn.createStatement();
			resultSet = stmt.executeQuery("select /* testcase1 */ sys_context('USERENV','INSTANCE_NAME'), sys_context('USERENV','SERVER_HOST') from dual");
			for(;resultSet.next();) {
				System.out.println(resultSet.getString(1));
				System.out.println(resultSet.getString(2));
			}
			try {
				if (resultSet != null) {
					resultSet.close();
				}
			} catch (SQLException e){
				e.printStackTrace();
			}
			try {
				if (stmt != null) {
					stmt.close();
				}
			} catch (SQLException e){
				e.printStackTrace();
			}
		} 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();
			}
		}
	}
}
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 TestCase2 {
	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.setProperty("user", "system");
			info.setProperty("password", "manager");
			info.setProperty("TCP.NODELAY", "YES");
			conn = DriverManager.getConnection("jdbc:oracle:thin:@192.168.56.101:1521:ORCL",info);
			stmt = conn.createStatement();
			resultSet = stmt.executeQuery("select /* testcase2 */ sys_context('USERENV','INSTANCE_NAME'), sys_context('USERENV','SERVER_HOST') from dual");
			for(;resultSet.next();) {
				System.out.println(resultSet.getString(1));
				System.out.println(resultSet.getString(2));
			}
			try {
				if (resultSet != null) {
					resultSet.close();
				}
			} catch (SQLException e){
				e.printStackTrace();
			}
			try {
				if (stmt != null) {
					stmt.close();
				}
			} catch (SQLException e){
				e.printStackTrace();
			}
		} 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();
			}
		}
	}
}

おまけ(ltrace でライブラリコールのトレースを取得する)

  • ltrace でリスナープロセスと fork されるプロセスのライブラリコールをトレースする。
[root@localhost ~]# ltrace -tf -p 13079 -o ltrace.log
  • テストケース実行後、setsockopt でどのようなソケットオプションを使用しているか調べる。
[root@localhost ~]# grep -C 2 -i setsockopt ltrace.log 
13090 21:04:07 __ctype_b_loc()                                                        = 0x147ed0
13090 21:04:07 free(0x11b6d080)                                                       = <void>
13090 21:04:07 setsockopt(14, 6, 1, 0xbfaec328, 4)                                    = 0
13090 21:04:07 malloc(4096)                                                           = 0x11b6d080
13090 21:04:07 vsnprintf("set TCP_NODELAY on 14\n", 4096, "set TCP_NODELAY on %d\n", 0xbfaec264) = 22
--
13090 21:04:08 write(8, "m}nttctl*0TgSY"1;\n", 18)                                    = 18
13090 21:04:08 free(0x11b750d0)                                                       = <void>
13090 21:04:08 setsockopt(14, 1, 9, 0xbfaebcbc, 4)                                    = 0
13090 21:04:08 malloc(4096)                                                           = 0x11b750d0
13090 21:04:08 vsnprintf("normal exit\n", 4096, "normal exit\n", 0xbfaebf80)          = 12
--
13090 21:04:13 write(8, "W}0TgmT"1;\n", 11)                                           = 11
13090 21:04:13 free(0x11b76110)                                                       = <void>
13090 21:04:13 setsockopt(14, 1, 21, 0xbfaf522c, 8)                                   = 0
13090 21:04:13 malloc(4096)                                                           = 0x11b76110
13090 21:04:13 vsnprintf("entry\n", 4096, "entry\n", 0xbfaf52a0)                      = 6
--
13090 21:04:13 write(8, "}0TgdP"1;\n", 10)                                            = 10
13090 21:04:13 free(0x11b76110)                                                       = <void>
13090 21:04:13 setsockopt(14, 1, 20, 0xbfaf522c, 8)                                   = 0
13090 21:04:13 malloc(4096)                                                           = 0x11b76110
13090 21:04:13 vsnprintf("entry\n", 4096, "entry\n", 0xbfaf5224)                      = 6
--
13090 21:04:13 write(8, "!nttdisc*0ThdS"1;\n", 18)                                    = 18
13090 21:04:13 free(0x11b76110)                                                       = <void>
13090 21:04:13 setsockopt(14, 1, 9, 0xbfaf520c, 4)                                    = 0
13090 21:04:13 close(14)                                                              = 0
13090 21:04:13 malloc(4096)                                                           = 0x11b76110
--
13097 21:04:19 __ctype_b_loc()                                                        = 0x633690
13097 21:04:19 free(0x1241a080)                                                       = <void>
13097 21:04:19 setsockopt(14, 6, 1, 0xbf990628, 4)                                    = 0
13097 21:04:19 malloc(4096)                                                           = 0x1241a080
13097 21:04:19 vsnprintf("set TCP_NODELAY on 14\n", 4096, "set TCP_NODELAY on %d\n", 0xbf990564) = 22
--
13097 21:04:20 write(8, "m}nttctl*0TgEW"1;\n", 18)                                    = 18
13097 21:04:20 free(0x124220d0)                                                       = <void>
13097 21:04:20 setsockopt(14, 1, 9, 0xbf98ffbc, 4)                                    = 0
13097 21:04:20 malloc(4096)                                                           = 0x124220d0
13097 21:04:20 vsnprintf("normal exit\n", 4096, "normal exit\n", 0xbf990280)          = 12
--
13097 21:04:25 write(8, "W}0Tg4U"8;\n", 11)                                           = 11
13097 21:04:25 free(0x12423110)                                                       = <void>
13097 21:04:25 setsockopt(14, 1, 21, 0xbf99952c, 8)                                   = 0
13097 21:04:25 malloc(4096)                                                           = 0x12423110
13097 21:04:25 vsnprintf("entry\n", 4096, "entry\n", 0xbf9995a0)                      = 6
--
13097 21:04:25 write(8, "}0TgUT"8;\n", 10)                                            = 10
13097 21:04:25 free(0x12423110)                                                       = <void>
13097 21:04:25 setsockopt(14, 1, 20, 0xbf99952c, 8)                                   = 0
13097 21:04:25 malloc(4096)                                                           = 0x12423110
13097 21:04:25 vsnprintf("entry\n", 4096, "entry\n", 0xbf999524)                      = 6
--
13097 21:04:25 write(8, "!nttdisc*0ThAR"1;\n", 18)                                    = 18
13097 21:04:25 free(0x12423110)                                                       = <void>
13097 21:04:25 setsockopt(14, 1, 9, 0xbf99950c, 4)                                    = 0
13097 21:04:25 close(14)                                                              = 0
13097 21:04:25 malloc(4096)                                                           = 0