ITPub博客

首页 > 数据库 > Oracle > what the root cause connect db slow

what the root cause connect db slow

原创 Oracle 作者:ygzhou518 时间:2014-08-06 16:21:06 0 删除 编辑
    新接手的几个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的大小逐渐增加。

          

         
       



来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/24867586/viewspace-1246618/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论

注册时间:2011-02-11

  • 博文量
    167
  • 访问量
    365056