背景介绍
客户出现用户无法登陆的情况,且在出问题期间出现大量的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;