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