故障現象
一早來，業務問我，數據庫有問題嗎，發了一個類似下面的截圖說用戶連不上了。
[oracle@rac1 ~]$ sqlplus zylong/zylong@192.168.0.10:1521/orcl
SQL*Plus: Release 19.0.0.0.0 - Production on Mon Nov 1 09:53:46 2021
Version 19.11.0.0.0
Copyright (c) 1982, 2020, Oracle. All rights reserved.
<<<<<<<<<<<<<<<<<<<<<<<<< # 掛起，超時顯示ORA-04021報錯
ERROR:
ORA-04021: timeout occurred while waiting to lock object 107
當時還沒有報出ORA-04021報錯，一直掛著，于是我就對數據庫檢查了一番，查本地磁盤空間正常，歸檔空間正常，用戶狀態正常，監聽正常，數據庫alert日志也正常，使用其他用戶登錄正常，就這個用戶不能登錄。
查詢此用戶的等待事件，大量的library cache lock
SQL> set numw 20
SQL> select con_id,username,event,p1,p2,p3,last_call_et from v$session where username=upper('zylong') and status!='INACTIVE';
CON_ID USERNAME EVENT P1 P2 P3 LAST_CALL_ET
------ ----------------------- ------------------------------------ -------------------- -------------------- -------------------- --------------------
7 zylong library cache lock 45015708272 44295738072 8323074 753
7 zylong library cache lock 45015708272 34047265144 8323074 753
7 zylong library cache lock 45015708272 73865793920 8323074 753
7 zylong library cache lock 45015708272 29450117360 8323074 746
7 zylong library cache lock 45015708272 34649553984 8323074 753
7 zylong library cache lock 45015708272 47329041440 8323074 753
7 zylong library cache lock 45015708272 44281610752 8323074 753
7 zylong library cache lock 45015708272 44680843968 8323074 753
7 zylong library cache lock 45015708272 29088738304 8323074 753
7 zylong library cache lock 45015708272 45463714896 8323074 753
7 zylong library cache lock 45015708272 11763471408 8323074 753
7 zylong library cache lock 45015708272 7089814448 8323074 753
7 zylong library cache lock 45015708272 7190841040 8323074 753
7 zylong library cache lock 45015708272 45727694264 8323074 753
7 zylong library cache lock 45015708272 29514801880 8323074 753
7 zylong library cache lock 45015708272 45400941088 8323074 753
7 zylong library cache lock 45015708272 46857941256 8323074 753
7 zylong library cache lock 45015708272 28912446224 8323074 753
7 zylong SQL*Net message to client 1413697536 1 0 0
7 zylong library cache lock 45015708272 73782262016 8323074 753
7 zylong gc cr request 313 2241577 1 0
7 zylong library cache lock 45015708272 55249461128 8323074 753
7 zylong library cache lock 45015708272 45011572904 8323074 222
7 zylong library cache lock 45015708272 11359884584 8323074 753
7 zylong library cache lock 45015708272 33929685512 8323074 753
7 zylong library cache lock 45015708272 45322411920 8323074 753
7 zylong library cache lock 45015708272 6259354512 8323074 322
7 zylong library cache lock 45015708272 7434264256 8323074 753
7 zylong library cache lock 45015708272 34761525680 8323074 753
7 zylong enq: TX - row lock contention 1415053318 2097163 1749981 3683
7 zylong library cache lock 45015708272 7483659600 8323074 753
7 zylong library cache lock 45015708272 53117430168 8323074 753
7 zylong library cache lock 45015708272 29114680592 8323074 754
7 zylong library cache lock 45015708272 35259998832 8323074 753
7 zylong library cache lock 45015708272 44815780096 8323074 753
7 zylong library cache lock 45015708272 12702913336 8323074 753
7 zylong library cache lock 45015708272 7311180264 8323074 753
7 zylong library cache lock 45015708272 74195848184 8323074 753
7 zylong library cache lock 45015708272 29050270464 8323074 753
7 zylong library cache lock 45015708272 74570849968 8323074 753
7 zylong library cache lock 45015708272 29438472736 8323074 399
7 zylong library cache lock 45015708272 46973671688 8323074 753
7 zylong library cache lock 45015708272 73576444472 8323074 753
7 zylong library cache lock 45015708272 28788937488 8323074 753
7 zylong library cache lock 45015708272 7054446560 8323074 265
7 zylong library cache lock 45015708272 74444654688 8323074 867
7 zylong library cache lock 45015708272 73610426000 8323074 35
7 zylong library cache lock 45015708272 45806155072 8323074 286
7 zylong library cache lock 45015708272 34497853112 8323074 13
7 zylong library cache lock 45015708272 73554239120 8323074 585
7 zylong library cache lock 45015708272 29505514120 8323074 586
7 zylong library cache lock 45015708272 73977126296 8323074 803
7 zylong library cache lock 45015708272 8521679328 8323074 285
7 zylong library cache lock 45015708272 11542066912 8323074 773
7 zylong library cache lock 45015708272 34491470232 8323074 18
7 zylong library cache lock 45015708272 12456319768 8323074 815
7 zylong library cache lock 45015708272 28327281600 8323074 783
7 zylong library cache lock 45015708272 6263935184 8323074 635
7 zylong library cache lock 45015708272 28055520024 8323074 815
7 zylong library cache lock 45015708272 29469195360 8323074 803
7 zylong library cache lock 45015708272 29269468184 8323074 883
7 zylong library cache lock 45015708272 28039214464 8323074 803
7 zylong library cache lock 45015708272 8131252688 8323074 754
7 zylong library cache lock 45015708272 8457524272 8323074 754
7 zylong library cache lock 45015708272 74579988512 8323074 753
7 zylong library cache lock 45015708272 7183580904 8323074 754
7 zylong library cache lock 45015708272 8292110304 8323074 753
7 zylong library cache lock 45015708272 47530526208 8323074 656
68 rows selected.
故障分析
SQL> oradebug setmypid Statement processed. SQL> oradebug tracefile_name /u02/app/oracle/diag/rdbms/cdbname/cdbname1/trace/cdbname1_ora_40833.trc SQL> oradebug hanganalyze 3 Hang Analysis in /u02/app/oracle/diag/rdbms/cdbname/cdbname1/trace/cdbname1_ora_40833.trc SQL> oradebug -g all hanganalyze 3 Hang Analysis in /u02/app/oracle/diag/rdbms/cdbname/cdbname1/trace/cdbname1_diag_27412.trc
Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'<='library cache lock'
Chain 1 Signature Hash: 0xc1d502c7
[b] Chain 2 Signature: 'CPU or Wait CPU'<='PX Deq: Execute Reply'
Chain 2 Signature Hash: 0x822b6140
[c] Chain 3 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'<='library cache lock'
Chain 3 Signature Hash: 0xc1d502c7
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (cdbname.cdbname1)
os id: 107393
process id: 962, oracle@rac1
session id: 103
session serial #: 1876
module name: 7 (oracle@rac1tr@zcloud (TNS V1-V3))))
pdb id: 7 (orcl)
}
is waiting for 'library cache lock' with wait info:
{
p1: 'handle address'=0xa7b253270
p2: 'lock address'=0x1138f73a70
p3: '100*mode+namespace'=0x7f0002
Name: orcl.107 [Nsp: 127 Typ: 255 Id: 0]
px1: 'pdb uid'=0x53556d15
px2: 'master hint'=0x0
time in wait: 1 min 3 sec
timeout after: 13 min 56 sec
wait id: 15
blocking: 0 sessions
current sql_id: 0
current sql: <none>
short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+223<-__sighandler()<-semtimedop()+10<-skgpwwait()+187<-ksliwat()+2230<-kslwaitctx()+200<-kjusuc()+4750<-ksipgetctxia()+1980<-ksixpgetia()+124<-kqlmLock()+805<-kqlmClusterLock()+1093<-kgllkal()+1058<-kglLock()+1415<-kglget()+293<-kziaRetrieveLSLT()+298<-kpolnb()+2876<-kpoauth()+1805<-opiodr()+1202<-ttcpip()+1239<-opitsk()+1897<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
wait history:
* time between current wait and wait #1: 0.000518 sec
1. event: 'PGA memory operation'
time waited: 0.000002 sec
wait id: 14 p1: ''=0x10000
p2: ''=0x1
* time between wait #1 and #2: 0.000489 sec
2. event: 'PGA memory operation'
time waited: 0.000003 sec
wait id: 13 p1: ''=0x30000
p2: ''=0x1
* time between wait #2 and #3: 0.000218 sec
3. event: 'PGA memory operation'
time waited: 0.000001 sec
wait id: 12 p1: ''=0x10000
p2: ''=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (cdbname.cdbname1)
os id: 22834
process id: 202, oracle@rac1
session id: 2019
session serial #: 34291
module name: 7 (oracle@rac1tzcloud (TNS V1-V3)3))))
pdb id: 7 (orcl)
}
which is waiting for 'enq: TX - row lock contention' with wait info:
{
p1: 'name|mode'=0x54580006
p2: 'usn<<16 | slot'=0x20000b
p3: 'sequence'=0x1ab3dd
px1: 'pdb uid'=0x53556d15
px2: 'master hint'=0x0
time in wait: 64 min 53 sec
timeout after: never
wait id: 32
blocking: 137 sessions
current sql_id: 2679977578
current sql: update user$ set spare6=DECODE(to_char(:2, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :2) where user#=:1
short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+223<-__sighandler()<-semtimedop()+10<-skgpwwait()+187<-ksliwat()+2230<-kslwaitctx()+200<-kjusuc()+4750<-ksipgetctxia()+1980<-ksqcmi()+2757<-ksqgtlctx()+6620<-ksqgelctx()+838<-ktuGetTxForXid()+324<-ktcwit1()+502<-kdddgb()+5858<-kdusru()+458<-kauupd()+356<-updrow()+1734<-qerupUpdRow()+671<-qerupFetch()+594<-updaul()+1416<-updThreePhaseExe()+340<-updexe()+443<-opiexe()+11741<-kpoal8()+2226<-opiodr()+1202<-kpoodrc()+40<-rpiswu2()+2077<-kpoodr()+660<-upirtrc()+2783<
wait history:
* time between current wait and wait #1: 0.000046 sec
1. event: 'IPC group service call'
time waited: 0.000003 sec
wait id: 31 p1: 'function id'=0xb
* time between wait #1 and #2: 0.000218 sec
2. event: 'gc cr block 2-way'
time waited: 0.000330 sec
wait id: 30 p1: ''=0x124
p2: ''=0x64
p3: ''=0x4f
* time between wait #2 and #3: 0.000037 sec
3. event: 'IPC group service call'
time waited: 0.000001 sec
wait id: 29 p1: 'function id'=0xb
}
and is blocked by
=> Oracle session identified by:
{
instance: 2 (cdbname.cdbname2)
os id: 13073
process id: 927, oracle@rac2
session id: 6105
session serial #: 18816
module name: 7 (PL/SQL Developerzcloud (TNS V1-V3)3))
pdb id: 7 (orcl)
}
which is waiting for 'SQL*Net message from client' with wait info:
{
p1: 'driver id'=0x54435000
p2: '#bytes'=0x1
time in wait: 64 min 52 sec
timeout after: never
wait id: 1782
blocking: 138 sessions
current sql_id: 0
current sql: <none>
short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+223<-__sighandler()<-read()+14<-snttread()+16<-nttfprd()+354<-nsbasic_brc()+399<-nioqrc()+438<-opikndf2()+999<-opitsk()+907<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
wait history:
* time between current wait and wait #1: 0.000172 sec
1. event: 'enq: PS - contention'
time waited: 0.000118 sec
wait id: 1781 p1: 'name|mode'=0x50530006
p2: 'instance'=0x2
p3: 'slave ID'=0x1
* time between wait #1 and #2: 0.000031 sec
2. event: 'PX Deq: Slave Session Stats'
time waited: 0.000001 sec
wait id: 1780 p1: 'sleeptime/senderid'=0x0
p2: 'passes'=0x0
* time between wait #2 and #3: 0.000006 sec
3. event: 'PX Deq: Slave Session Stats'
time waited: 0.000022 sec
wait id: 1779 p1: 'sleeptime/senderid'=0x1
p2: 'passes'=0x1
}
Chain 1 Signature: 'SQL*Net message from client'<='enq: TX - row lock contention'<='library cache lock'
Chain 1 Signature Hash: 0xc1d502c7
-------------------------------------------------------------------------------
發現了 update user$ set spare6=DECODE(to_char(:2, ‘YYYY-MM-DD’), ‘0000-00-00’, to_date(NULL), :2) where user#=:1
故障處理
SQL> @usid 6105
USERNAME SID AUDSID OSUSER MACHINE PROGRAM SPID OPID CPID LASTCALL STATUS LOGON_TIME
---------- -------------- ----------- ---------------- --------- -------------- ------- ------ ---------- ---------- -------- -----------------
zylong '6105,18816' 31629560 Administrator \PC2018 plsqldev.exe 13073 927 3604:5596 4003 INACTIVE 20211101 08:42:32
SQL> @kill sid=6105
COMMANDS_TO_VERIFY_AND_RUN
--------------------------------------------------------------------------------------------------------------
alter system kill session '6105,18816' immediate -- zylong@WORKGROUP\PC2018 (plsqldev.exe);
SQL> alter system kill session '6105,18816' immediate -- zylong@WORKGROUP\PC2018 (plsqldev.exe);
System altered.
通過監聽日志找到這個主機的IP地址
[oracle@rac2 trace]$ cat listener.log |grep PC2018|head -10
01-NOV-2021 08:39:58 * (CONNECT_DATA=(SERVICE_NAME=orcl)(CID=(PROGRAM=C:\Program?Files\PLSQL?Developer\plsqldev.exe)
(HOST=PC2018)(USER=Administrator))(SERVER=dedicated)(INSTANCE_NAME=cdbname2)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.10.10.17)(PORT=50662)) * establish * orcl * 0
故障原因
客戶端\PC2018更新了 Last Login Time (update user$ set spare6=DECODE(to_char(:2, ‘YYYY-MM-DD’), ‘0000-00-00’, to_date(NULL), :2) where user#=:1) ,不知道啥原因沒有提交，鎖住基表user$，導致其他session登錄時無法更新user$。
更詳細的解釋，請參考我們大神的博客
- Oracle 12c New Feature: Last Login Time for Non-Sys Users
https://www.anbob.com/archives/2783.html
[oracle@rac1 ~]$ sqlplus zylong/zylong@192.168.0.10:1521/orcl
SQL*Plus: Release 19.0.0.0.0 - Production on Mon Nov 1 11:42:25 2021
Version 19.11.0.0.0
Copyright (c) 1982, 2020, Oracle. All rights reserved.
Last Successful login time: Mon Nov 01 2021 11:42:25 +08:00 <<<<# 記錄在user$表的SPARE6列.
Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.11.0.0.0
SQL>
# Oracle不顯示sys或操作系統認證的登錄
SQL> @desc dba_users
Name Null? Type
------------------------------- -------- ----------------------------
1 USERNAME NOT NULL VARCHAR2(128)
2 USER_ID NOT NULL NUMBER
3 PASSWORD VARCHAR2(4000)
4 ACCOUNT_STATUS NOT NULL VARCHAR2(32)
5 LOCK_DATE DATE
6 EXPIRY_DATE DATE
7 DEFAULT_TABLESPACE NOT NULL VARCHAR2(30)
8 TEMPORARY_TABLESPACE NOT NULL VARCHAR2(30)
9 LOCAL_TEMP_TABLESPACE VARCHAR2(30)
10 CREATED NOT NULL DATE
11 PROFILE NOT NULL VARCHAR2(128)
12 INITIAL_RSRC_CONSUMER_GROUP VARCHAR2(128)
13 EXTERNAL_NAME VARCHAR2(4000)
14 PASSWORD_VERSIONS VARCHAR2(17)
15 EDITIONS_ENABLED VARCHAR2(1)
16 AUTHENTICATION_TYPE VARCHAR2(8)
17 PROXY_ONLY_CONNECT VARCHAR2(1)
18 COMMON VARCHAR2(3)
19 LAST_LOGIN TIMESTAMP(9) WITH TIME ZONE
20 ORACLE_MAINTAINED VARCHAR2(1)
21 INHERITED VARCHAR2(3)
22 DEFAULT_COLLATION VARCHAR2(100)
23 IMPLICIT VARCHAR2(3)
24 ALL_SHARD VARCHAR2(3)
25 PASSWORD_CHANGE_DATE DATE
SQL> select to_char(last_login,'yyyy-mm-dd hh24:mi:ss') from dba_users where username='zylong';
TO_CHAR(LAST_LOGIN,
-------------------
2021-11-01 14:20:13
如果在 login 時 hang 或 libaray cache lock ,SQL 如下
update user$ set spare6=DECODE(to_char(:2, ‘YYYY-MM-DD’), ‘0000-00-00’, to_date(NULL), :2) where user#=:1
user$.spare6對應的就是last_login , ORACLE已經對12c和19c推出了bug 補丁用入引入禁用LSLT, 需要安裝Patch 32164034 才會引入_disable_last_successful_login_time 。
-
Oracle19c 建議的 One-off patch之disable LAST SUCCESSFUL LOGIN TIME
https://www.anbob.com/archives/6411.html -
對于登錄相關的 LAST SUCCESSFUL LOGIN TIME的Library cache lock又出新參數
https://www.anbob.com/archives/6444.html
最后修改時間：2021-11-04 08:40:28
「喜歡這篇文章，您的關注和贊賞是給作者最好的鼓勵」
關注作者
【版權聲明】本文為墨天輪用戶原創內容，轉載時必須標注文章的來源（墨天輪），文章鏈接，文章作者等基本信息，否則作者和墨天輪有權追究責任。如果您發現墨天輪中有涉嫌抄襲或者侵權的內容，歡迎發送郵件至：contact@modb.pro進行舉報，并提供相關證據，一經查實，墨天輪將立刻刪除相關內容。
