暂无图片
暂无图片
3
暂无图片
暂无图片
暂无图片

Oracle 12c New Feature: Last Login Time 引发的故障

原创 张玉龙 2021-11-01
3385

故障现象

一早来,业务问我,数据库有问题吗,发了一个类似下面的截图说用户连不上了。

[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@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

  1. Oracle19c 建议的 One-off patch之disable LAST SUCCESSFUL LOGIN TIME
    https://www.anbob.com/archives/6411.html

  2. 对于登录相关的 LAST SUCCESSFUL LOGIN TIME的Library cache lock又出新参数
    https://www.anbob.com/archives/6444.html

最后修改时间:2021-11-04 08:40:28
「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论