排查Oracle TNS 10秒延时

我们的一个系统最近更换了测试环境，刚上线就发现一个奇怪的问题——每个SQL查询都至少要延时7-10秒之后才会有反应。系统使用的是Oracle数据库，虽然没有使用数据库连接池但是也不应该会有“10的秒延时”，我Debug了Oracle的客户端库，发现客户端的停顿是出现在等待网络数据，通过tcpdump抓取TNS数据包再次印证了这一点——有10秒钟的时间再等待服务器端返回数据包。所以问题可以确定是出现在Oracle服务器上面。回想了一下Oracle的架构，TNS是负责响应用户请求转发请求到实例，所以对于Oracle来说它可以启动多个TNS提高系统的“并发能力”。（非常巧妙的设计）TNS提供的配置选项非常少，基本上没有什么参数可以调整（你可以查看完整的listener.ora配置，基本上都是对网络传输的一些优化），几乎陷入了死局。有时候解决问题就是这样，知道问题出现某个部分但是限于没有这部分的源代码或者时间不允许我们去翻源代码往往只能通过“猜”->“试”的办法去“暴力破解”。一般这种情况下我会选择一种不一样的Debug方法——通过一些工具去获知系统的内部执行轨迹比如获知系统调用，这种方法一般情况下都非常有效。祭出大杀器—— strace，这是Linux下的一个小工具可以跟踪某个进程的系统调用，通过参数p可以指定PID。f参数会跟踪fork出来的线程或者子进程；r参数会输出系统调用的执行时间。也有人喜欢用DTrace，我觉得这玩意太重，动不动就得写一个脚本啥的。不可否认它要比strace牛B多了，但是我只是想看一下系统调用——所以strace足够了。
执行strace -fr -p 19535
其中19535是TNS的PID。输出分为三列，第一列是PID，第二列是执行时间，第三列是执行的系统调用和传递的参数。我们直接看可疑的部分：

日志里面有两个PID，19535是TNS的主进程，20358是TNS为每个连接开辟的“线程”。最下面有2秒钟的Timeout，原因是poll超时，往上不难分析：TNS主进程接收到用户请求后会新建一个线程（本例是20358），这个线程有一段逻辑打开了202.96.209.133这台服务器的53端口（第一个红箭头）然后发送了一段数据（第二个红箭头），等待服务器响应（超时时间是5秒，poll的最后一个参数）。本例中的10秒延时就是由于这里的Timeout引起的（一共尝试两次）202.96.209.133这台服务器是我配置的DNS地址，53端口则是DNS服务器监听的端口，有意思的是sendto函数的数据部分——这就是一个DNS“查询数据包”（前12个固定头+Question数据包）。查询的域名——kvm则是我本机的计算机名。需要特别注意的是我的hosts文件已经配置了本机地址和kvm的对应，如果按照hostbyname这种dns方法来查询机器名是可以正常拿到本机IP的。而Oracle做了一个有意思的决定——它的DNS解析不依赖于本机hosts配置而是直接读取/etc/resolv.conf获知dns server地址自己构造DNS“查询数据包”完成的域名解析。解决办法也很简单，把/etc/resolv.conf清空就行了（或则自己搞一个内部DNS地址，总之让Oracle可以正常DNS查询或者干脆快速的解析出错就行了）。Oracle为什么会有这个动作我估计是因为它的架构中允许TNS和实例分离，这个解析动作其实是在解析实例所对应的IP地址。

分辨出19535谁是主线程谁是派生的20358其实但从数字就能判断出来，Linux是从小到大分配PID的，所以——"大"的肯定是子线程。不过为了更加“科学”我还是找到信息来印证一下
clone方法其实就是Linux的“new thread”函数，最后一个参数指定了线程的“函数入口”。 这里非常奇怪，TNS会派生出一个20357的线程，然后20357派生出20358就“自杀”了，两次派生的函数入口是同一地址。这一点我也搞不太清楚为什么。

克服惰性是非常难的一件事情，最近在“搞大新闻”很多精力都花费在上面，从本周开始继续——写作。