what the root cause connect db slow

最新推荐文章于 2024-09-30 17:19:22 发布

ciyangliln703681

最新推荐文章于 2024-09-30 17:19:22 发布

阅读量98

点赞数

文章标签：数据库

新接手的几个DB出现问题，折腾一周的问题终于结案，记录在此。

2014.08.29日09：52收到 Mail 如下：

    第一反应怀疑网络出现延迟掉包：
           但是此时tnsping tns延时15000ms，ping ip正常。
    检查DB、监听状态：
           利用glance命令发现存在大量的状态为died的listener子进程.---------OS 为HP-UNIX 11.23 ORACLE 9.2.0.8
    利用sqlplus / as sysdba 与sqlplus user/passwd@tns验证发现，sqlplus / as sysdba登录、返回OK，sqlplus user/passwd@tns过程比较缓慢。

   生成Trace文件用于分析：
          1，client端配置 sqlnet.ora文件

### Step 1: Client sqlnet.ora

TNSPING.TRACE_LEVEL = ADMIN
TNSPING.TRACE_DIRECTORY = d:\ygzhou

### Step 2: Client sqlnet.ora

               trace_level_client=16
               trace_directory_client=d:\ygzhou
               trace_file_client=client
               trace_unique_client=on
               trace_timestamp_client=on
        2.client端生产trace文件
               sqlplus user/passw@tns

        3,Server端利用
           tusc -aefo /oracle/tuscsqlplus0805_bf1.out -T "%T" sqlplus user/passwd@tns
           tusc -aefo /oracle/tuscsqlplus0805_bf2.out -T "%T" sqlplus /as sysdba
    生成trace文件分析整个连接数据库的过程耗时信息：
10:33:32 getpid() ........................................................ = 892 (891)
10:33:32 gettimeofday(0x9fffffffffffc700, NULL) .......................... = 0
10:33:32 gettimeofday(0x9fffffffffffcd90, NULL) .......................... = 0
10:33:32 write(5, "\0W \0\001\0\0\0018 01, \0\0\b\0".., 87) .............. = 87
10:33:34 read(5, 0x60000000001b0e56, 2064) ............................... [sleeping] <==== Time consumed in SYSTEM CALL which is not Oracle stuff.
10:33:36 read(5, "\0I \0\004\0\0\0" \0\0= ( D E S ".., 2064) ............. = 73
10:33:36 close(5) ........................................................ = 0
10:33:36 lseek(4, 25600, SEEK_SET) ....................................... = 25600
10:33:36 read(4, "\0\r\raf\0\0\0V \rb0\0\0\0m \rb1".., 512) .............. = 512
10:33:36 gettimeofday(0x9fffffffffffd740, NULL) .......................... = 0

    由此可以发现tnsping的过程中在system call过程中sleep 2S钟时间。

    经过HP工程师分析原因：这个为oracle 9.2.0.8版本的一个已知bug问题，由于memory leak.导致listener进程耗用jmemory >=560MB

    建议restart listener或者补丁Bug 5576565 : LISTENER MEMORY LEAK AFTER APPLYING PATCH 9.2.0.8

    至此问题解决，采用临时重启listener的方式完成本次异常问题。

OK，问题现在出现了！

     从老板的思维里我的DB运行了10年没有出现这个问题，为什么现在出现？
     解释说是因为oracle bug。为什么这个bug会出现，是什么触发这个bug？

分析listener.log中的链接数据量正常，在异常时间段与正常时间段连接数变化不大，不足以解释触发bug的原因!

转换思路：
      老板：我的DB运行了10年...

如果bug存在本是一个客观的事实，但是为什么一直都没有触发？

检查os层面的job，峰回路转！

本是存在周期重启listener的job，但是被人为禁用，最后重启时间为2014-06-25 日。

终于可以解释通整个异常：
      2014-06-25停掉重启监听的job后，由于该版本的监听本身存在bug，随着时间的推移、由于小内存溢出问题，监听耗用memory的大小逐渐增加。