一次library cache lock的处理

背景介绍

客户出现用户无法登陆的情况,且在出问题期间出现大量的Library cache lock等待事件,数据库运行缓慢,没有办法根治问题,客户只能通过重启临时解决问题,但是过段时间又会重现该问题。因为该问题是远程进行分析的,客户只提供了ash报告,diag的trace文件,以及dba_hist_active_sess_history的数据。最终依靠这三个东西我们定位了故障原因。

问题原因分析

1.首先我们看出问题期间的ash报告

Top User Events

    Event Event Class % Event Avg Active Sessions
    library cache lock Concurrency 98.14 509.38

    Top Event P1/P2/P3 Values

      Event % Event P1 Value, P2 Value, P3 Value % Activity Parameter 1 Parameter 2 Parameter 3
      library cache lock 98.14 "504403243084006592","504403242095186952","5177346" 0.19 handle address lock address 100*mode+namespace

      从这里我们看到故障时候98%的等待事件都是library cache lock,这里的handle addreee的地址是504403243084006592。

      2.接下来我们来看我们的diag trace文件,我们的diag进程是当数据库出现异常情况后,会将一些信息记录到trace里面。

      client details:
            O/S info: user: nwom, term: unknown, ospid: 1234
            machine: sdwyap1 program: JDBC Thin Client
            application name: JDBC Thin Client, hash value=2546894660
          Current Wait Stack:
           0: waiting for 'DFS lock handle'
              type|mode=0x49560005, id1=0x4c4f434b, id2=0x1
              wait_id=6 seq_num=7 snap_id=1
              wait times: snap=0.000759 sec, exc=0.000759 sec, total=0.000759 sec
              wait times: max=infinite, heur=0.000759 sec
              wait counts: calls=1 os=1
              in_wait=1 iflags=0x5a2
          Wait State:
            fixed_waits=0 flags=0x22 boundary=0x0/-1
          Session Wait History:
              elapsed time of 3.464080 sec since current wait
           0: waited for 'library cache lock'
              handle address=0x7000013bf93c4c0, lock address=0x7000013a6b5a060, 100*mode+namespace=0x4f0003
              wait_id=5 seq_num=6 snap_id=1
              wait times: snap=18 min 51 sec, exc=18 min 51 sec, total=18 min 51 sec
              wait times: max=infinite
              wait counts: calls=2264 os=2264
              occurred after 0.000203 sec of elapsed time

      注意红色标示的部分,我们把这个address=0x7000013bf93c4c0从十六进制转换成十进制,刚好就是504403243084006592。与我们在ASH报告中看到的地址是一样的。那么这个关键的地方就在于下面这一段trace内容。

      LibraryObjectLock:  Address=7000013d25d5df8 Handle=7000013bf93c4c0 RequestMode=S CanBeBrokenCount=1 Incarnation=1 ExecutionCount=0         
              User=7000013338987a0 Session=7000013338987a0 ReferenceCount=0 Flags=[0000] SavepointNum=4 
            LibraryHandle:  Address=7000013bf93c4c0 Hash=abd99ac0 LockMode=X PinMode=0 LoadLockMode=0 Status=VALD 
              ObjectName:  Name=71   
                FullHashValue=f700cec5c4a2393669e9a530abd99ac0 Namespace=ACCOUNT_STATUS(79) Type=NONE(255) Identifier=0 OwnerIdn=2147483644 
              Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=0 ActiveLocks=1 TotalLockCount=11538 TotalPinCount=0

      这里需要说明的是library cache handle是对象的一个指针,而其中的namespace则代表指向对象的类型,这儿我们可以清楚的看到我们指向的类型是ACCOUNT_STATUS,从字面上看也就是账号的状态。那么我们怀疑这个和用户的状态有一定的关系。我们看到前面object的name为71,可以推测出user_id为71的用户可能存在问题。

      SQL> select username from dba_users where user_id=71;
      USERNAME
      ------------------------------
      SDPM

      经过查询,我们发现用户为SDPM,刚好和用户在故障时间段该用户无法登陆是吻合的。进一步分析trace里面的堆栈信息,发现有kziasfc函数。

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD
      240001 A     grid  827732       1   0  60 20 d477d5590 188864 f1000603806181b0 04:51:28      -  0:00 oraclenwom22 (LOCAL=NO) 
      Short stack dump: 
      ksedsts()+644<-ksdxfstk()+44<-ksdxcb()+1700<-sspuser()+116<-47b8<-nsleep()+228<-nanosleep()+496<-kziasfc()+976<-kpolnb()+2528<-kpoauth()+2184<-opiodr()+3608<-ttcpip()+4628<-opitsk()+6956<-opiino()+3000<-opiodr()+3608<-opidrv()+1200<-sou2o()+192<-opimai_real()+428<-ssthrdmain()+340<-main()+216<-__start()+112

      3.通过对DBA_HIST_ACTIVE_SESS_HISTORY的分析,我们发现大量等待Library cache lock的会话都是user_id为71的,且这些会话的状态都是在IN_CONNECTION_MGMT为Y的阶段,换句话来说,也就是会话连接初始创建的一个阶段。

      SAMPLE_TIME	                 USER_ID	EVENT	             TOP_LEVEL_CALL_NAME IN_CONNECTION_MGMT	 PROGRAM
      ---------------------------- -------  ------------------ ------------------- ------------------ ------------------------------
      30-1月 -14 06.59.38.916 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.59.38.916 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.59.28.798 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.59.08.560 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.58.445 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb1 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb1 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                sqlldr@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb1 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb1 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                oracle@sdpmdb1 (TNS V1-V3)
      30-1月 -14 06.58.28.031 下午	    71	library cache lock OAUTH	             Y	                ora_ploader@sdwyap2 (TNS V1-V3)

      故障定位

      根据上述多方面的判断,USER_ID为71的用户也就是SDPM在数据库创建连接的状态,出现了Library cache lock的等待,而在diag trace中发现该等待所指向的类型是ACCOUNT_STATUS,堆栈函数中包含了kziasfc函数,符合官方文档MOS 1309738.1所述的由于用户密码错误导致的大量library cache lock等待,是因用户密码错误触发了11G用户登陆延迟验证的新特性(安全保护机制)所致。该机制主要是当用户连续的输入错误的密码,Oracle所需要的密码验证时间会逐步增加,这可以有效的避免有人试图通过暴力方式来破解密码。在三次密码错误之后,延迟时间是递增的,从开始的两秒递增到六秒以上。这样过多的会话执行相同的登录操作,library cache lock等待的会话不断的增加。

      解决办法

      设置数据库参数,关闭密码错误后延迟验证的新特性。

      alter system set event ="28401 TRACE NAME CONTEXT FOREVER, LEVEL 1" scope=spfile;
      分享到: 更多