上一篇博文讲了很多系统调用函数，这些知识再加上经验积累，可用于在实际工作中分析和解决问题。


问题：香港机房的一台linux服务器，上面安装的sqlplus无法连接到深圳公司机房的oracle server，执行sqlplus xxxx/xxxx@rwdb的时候直接没反应，经过2分钟左右，报：

SQL*Plus: Release 11.2.0.1.0 Production on Tue Apr 21 15:44:04 2015

Copyright (c) 1982, 2009, Oracle.  All rights reserved.

ERROR:
ORA-12547: TNS:lost contact


环境：

客户端机器地址为：172.17.5.13(redhat5.8+oracle11g client)
服务端机器地址为：192.168.1.48(solaris9+oracle10g server)


经过测试：

1、tnsping rwdb正常，这说明客户端tnsnames配置没有问题

2、在其它环境下测试redhat5.8+oracle 11g client连接solaris9+oracle 10g server，成功，无兼容性问题。


那么，如何继续排查问题呢？这个时候strace就派上用场了。

在客户端机器上执行：

#strace -o strace.log sqlplus xxxx/xxxx@rwdb

卡住的时候，strace.log显示：

brk(0x9196000)                          = 0x9196000
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 9
fcntl(9, F_SETFL, O_RDONLY|O_NONBLOCK)  = 0
connect(9, {sa_family=AF_INET, sin_port=htons(1521), sin_addr=inet_addr("192.168.1.48")}, 16) = -1 EINPROGRESS (Operation now in progress)
times({tms_utime=1, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 2186561939
mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ae433057000
poll([{fd=9, events=POLLOUT}], 1, 60000) = 1 ([{fd=9, revents=POLLOUT}])
getsockopt(9, SOL_SOCKET, SO_ERROR, [-132438043876392960], [4]) = 0
fcntl(9, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(9, F_SETFL, O_RDWR)               = 0
getsockname(9, {sa_family=AF_INET, sin_port=htons(53136), sin_addr=inet_addr("172.17.5.13")}, [549755813904]) = 0
getsockopt(9, SOL_SOCKET, SO_SNDBUF, [366915001648168960], [4]) = 0
getsockopt(9, SOL_SOCKET, SO_RCVBUF, [366915001648239956], [4]) = 0
setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
rt_sigaction(SIGPIPE, {0x1, ~[ILL ABRT BUS FPE SEGV USR2 XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x35a240ebe0}, {SIG_DFL, [], 0}, 8) = 0
write(9, "\0\324\0\0\1\0\0\0\1:\1,\fA \0\177\377\177\10\0\0\1\0\0\232\0:\0\0\10\0"..., 212) = 212
read(9,


分析：

这里的fd9是一个客户端连接服务端（192.168.1.48）1521端口的socket，这个socket的建立是正常的，但是当write发出第一个消息出去后就卡顿了。这里我们有理由开始怀疑网络问题，是否网络不稳定导致了sqlplus的异常。


果然，通过测试，发现香港到深圳的这个***网络环境不稳定，存在丢包：

#ping -s 172.17.5.13 1024 >ping.log

14%的丢包率：
530 packets transmitted, 455 packets received, 14% packet loss
round-trip (ms)  min/avg/max = 11/11/17


联系网络管理员，将路由从***切换至另外一个专线通道后问题解决，sqlplus连接成功。这个case也说明，sqlplus对网络环境是要求很高的，之前一直以为即使有丢包也应该能连上，但事实并非如此。


小结：

1、通过对strace的分析，可能未必能一次性解决问题，还得考虑其它因素。这个case，即使不分析strace，通过测试网络，最终也能发现问题，但strace可以很好地提供一个证据和参考，这里socket通信有问题就是证据，否则凭什么说是网络引起的问题呢？


2、用得较多的一个参数还有-Ttt，含义如下：

-t          Prefix each line of the trace with the time of day.
-tt         If given twice, the time printed will include the microseconds.
-T          Show  the time spent in system calls. This records the time difference between the beginning and the end of each system call.


这样子可以在strace里显示每一行的时间点（微秒为单位）和每个系统调用消耗的时间（秒为单位），这是分析程序性能问题所必须的信息。


可以将前面的strace用法改为：

#strace -o sqlplus.strace -Ttt sqlplus xxxx/xxxx@rwdb


跟踪结果片段如下：

14:12:00.697642 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 4 <0.000034>
14:12:00.697771 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000021>
14:12:00.697870 connect(4, {sa_family=AF_INET, sin_port=htons(1521), sin_addr=inet_addr("192.168.128.40")}, 16) = -1 EINPROGRESS (Op
eration now in progress) <0.000054>
14:12:00.698021 times({tms_utime=1, tms_stime=2, tms_cutime=0, tms_cstime=0}) = 1942175931 <0.000018>
14:12:00.698121 brk(0xfc2000)           = 0xfc2000 <0.000019>
14:12:00.698225 poll([{fd=4, events=POLLOUT}], 1, 60000) = 1 ([{fd=4, revents=POLLOUT}]) <0.001505>
14:12:00.699833 getsockopt(4, SOL_SOCKET, SO_ERROR, [-9002124836780113920], [4]) = 0 <0.000017>
14:12:00.699944 fcntl(4, F_GETFL)       = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000022>
14:12:00.700045 fcntl(4, F_SETFL, O_RDWR) = 0 <0.000021>
14:12:00.700146 getsockname(4, {sa_family=AF_INET, sin_port=htons(53522), sin_addr=inet_addr("192.168.128.72")}, [16]) = 0 <0.000022>
14:12:00.700277 getsockopt(4, SOL_SOCKET, SO_SNDBUF, [-9002118548947927040], [4]) = 0 <0.000019>
14:12:00.700376 getsockopt(4, SOL_SOCKET, SO_RCVBUF, [-9002118548947905196], [4]) = 0 <0.000018>
14:12:00.700477 setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000020>
14:12:00.700579 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000018>
14:12:00.701216 rt_sigaction(SIGPIPE, {SIG_IGN, ~[ILL ABRT BUS FPE SEGV USR2 XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SI
GINFO, 0x37a6a0f710}, {SIG_DFL, [], 0}, 8) = 0 <0.000027>
14:12:00.701544 write(4, "\0\326\0\0\1\0\0\0\1:\1,\fA \0\377\377\177\10\0\0\1\0\0\234\0:\0\0\10\0"..., 214) = 214 <0.000034>
14:12:00.701758 read(4, "\0\10\0\0\v\0\0\0", 8208) = 8 <0.089866>
14:12:00.791752 write(4, "\0\326\0\0\1\0\0\0\1:\1,\fA \0\377\377\177\10\0\0\1\0\0\234\0:\0\0\10\0"..., 214) = 214 <0.000031>
14:12:00.791900 read(4, "\0 \0\0\2\0\0\0\0019\f\1\10\0\177\377\0\1\0\0\0 I\10\0\0\0\0\0\0\0\0", 8208) = 32 <0.000326>
14:12:00.796226 getuid()                = 0 <0.000022>
14:12:00.796325 getppid()               = 12428 <0.000016>
14:12:00.796539 rt_sigaction(SIGTSTP, {SIG_IGN, ~[ILL ABRT BUS FPE SEGV USR2 XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SI
GINFO, 0x37a6a0f710}, {SIG_DFL, [], 0}, 8) = 0 <0.000020>
14:12:00.796694 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0 <0.000023>
14:12:00.796815 readlink("/proc/self/fd/0", "/dev/pts/1", 254) = 10 <0.000050>
14:12:00.796955 uname({sys="Linux", node="gd-ip-probe", ...}) = 0 <0.000019>
14:12:00.797141 uname({sys="Linux", node="gd-ip-probe", ...}) = 0 <0.000016>
14:12:00.797326 getuid()                = 0 <0.000020>
14:12:00.797428 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000027>


这里可以清楚看到，红色字体的系统调用花了接近90ms，是里面最耗时的一次socket通信系统调用。前面出问题的时候就是卡在这里。