故障处理：Oracle实例Hang死

IT那活儿 2024-01-25

1715

点击上方“IT那活儿”公众号--专注于企业全栈运维技术分享，不管IT什么活儿，干就完了！！！

背景描述

某天，某库发出了一条实例连接异常的语音告警。立即登录该节点进行检查，发现数据库的响应非常缓慢，无法正常登录数据库，此时实例已经处于Hang死状态。情况紧急，手动强制重启实例之后，数据库恢复了正常。

版本信息：

操作系统：RHEL7.5
数据库：Oracel 19.10.0.0.0（6节点RAC）

处理过程

2.1 问析定位

1）登录检查节点 3 运行情况，发现数据库响应缓慢，存在大量 library cache等待事件

2023-07-24 00:27:38.562 0 library cache: mutex X 559
2023-07-24 00:27:54.366           0 library cache lock          11,181
2023-07-24 00:27:54.366           0 library cache: mutex X 34
2023-07-24 00:28:10.173           0 library cache lock           9,353
2023-07-24 00:28:10.173           0 library cache: mutex X 2,299
2023-07-24 00:28:25.686           0 library cache lock           9,497
2023-07-24 00:28:25.686           0 library cache: mutex X 2,680
2023-07-24 00:28:40.697           0 library cache lock          11,523
2023-07-24 00:28:40.697           0 library cache: mutex X 993
2023-07-24 00:28:55.901           0 library cache lock           5,960
2023-07-24 00:28:55.901           0 library cache: mutex X 6,780
2023-07-24 00:29:11.702           0 library cache lock           9,320
2023-07-24 00:29:11.702           0 library cache: mutex X 3,527
2023-07-24 00:29:26.562           0 library cache lock          10,912
2023-07-24 00:29:26.562           0 library cache: mutex X 2,009
2023-07-24 00:29:41.761           0 library cache lock           3,958
2023-07-24 00:29:41.761           0 library cache: mutex X 9,000
2023-07-24 00:29:56.874           0 library cache lock          10,903

2）检查数据库trace，发现连接已经超出最大限制，初步判断是由 library cache等待阻塞导致连接无法及时处理引发

2023-07-24T00:42:51.117067+08:00
ORA-00020: maximum number of processes (20000) exceeded
 ORA-20 errors will not be written to the alert log for
 the next minute. Please look at trace files to see all
 the ORA-20 errors.
2023-07-24T00:42:54.086832+08:00
2023-07-24T00:43:48.127918+08:00
Process W00J submission failed with error = 20
2023-07-24T00:43:51.128106+08:00
Process W01R submission failed with error = 20
2023-07-24T00:43:52.093439+08:00
ORA-00020: maximum number of processes (20000) exceeded
 ORA-20 errors will not be written to the alert log for
 the next minute. Please look at trace files to see all
 the ORA-20 errors.

3）手动查杀相关会话，等待事件有所下降但效果不明显，考虑到尽快恢复业务，01:43 分左右，手动强制关闭并重启实例，最终恢复正常

2023-07-24T01:54:22.324043+08:00
Instance shutdown complete (OS id: 240400)
2023-07-24T01:54:30.637910+08:00
Starting ORACLE instance (normal) (OS id: 247320)
2023-07-24T01:54:30.766177+08:00
****************************************************
 Sys-V shared memory will be used for creating SGA
 ****************************************************
2023-07-24T01:54:30.767043+08:00
**********************************************************************
2023-07-24T01:54:30.767088+08:00
Dump of system resources acquired for SHARED GLOBAL AREA (SGA)
2023-07-24T01:54:30.767163+08:00
 Per process system memlock (soft) limit = 500G
2023-07-24T01:54:30.767204+08:00
 Expected per process system memlock (soft) limit to lock
 instance MAX SHARED GLOBAL AREA (SGA) into memory: 300G
2023-07-24T01:54:30.767282+08:00
**********************************************************************

4）检查相关事件的历史信息，发现和一条INSERT SQL 语句相关，该语句用于向审计记录表插入审计信息

-- b3853arjnybzv
INSERT INTO AUDSYS.AUD$UNIFIED (AUDIT_TYPE, SESSIONID, PROXY_SESSIONID, OS_USER, HOST_NAME, TERMINAL
          , INSTANCE_ID, DBID, AUTHENTICATION_TYPE, USERID, PROXY_USERID, EXTERNAL_USERID, GLOBAL_USERID, CLIE
            NT_PROGRAM_NAME, DBLINK_INFO, XS_USER_NAME, XS_SESSIONID, ENTRY_ID, STATEMENT_ID, EVENT_TIMESTAMP, A
            CTION, RETURN_CODE, OS_PROCESS, TRANSACTION_ID, SCN, EXECUTION_ID, OBJ_OWNER, OBJ_NAME, CLIENT_IDENT
            IFIER, NEW_OWNER, NEW_NAME, OBJECT_EDITION, SYSTEM_PRIVILEGE_USED, SYSTEM_PRIVILEGE, AUDIT_OPTION, O
……

5）检查相关 trace，进一步验证了等待和该 SQL 有关

*** 2023-07-24T01:52:33.940747+08:00
HM: Early Warning - Session ID 8005 serial# 53205 OS PID 119329 (FG)
     is waiting on 'library cache lock' for 33 seconds, wait id 769
     p1: 'handle address'=0x69f80a2c8, p2: 'lock address'=0x589f111a8, p3: '100*mode+namespace'=0x520002
    Blocked by Session ID 22260 serial# 57425 on instance 3
     which is waiting on 'library cache lock' for 31 seconds
     p1: 'handle address'=0x69f80a2c8, p2: 'lock address'=0x51e3eeaa0, p3: '100*mode+namespace'=0x520003
    Final Blocker is Session ID 14289 serial# 52127 on instance 3
     which is 'not in a wait' for 0 seconds
                                                     IO 
 Total Self- Total Total Outlr Outlr Outlr 
  Hung Rslvd Rslvd Wait WaitTm Wait WaitTm Wait 
  Sess Hangs Hangs Count Secs Count Secs Count Wait Event
------ ------ ------ ------ ------ ------ ------ ------ -----------
     0      0      0 286951398 96425517      0      0      0 library cache lock
 
HM: Current SQL: INSERT INTO AUDSYS.AUD$UNIFIED (AUDIT_TYPE, SESSIONID, PROXY_SESSIONID, OS_USER, HOST_NAME, TERMINAL, INSTANCE_ID, DBID, AUTHENTICATION_TYPE, USERID, PROXY_USERID, EXTERNAL_USERID, GLOBAL_USERID, CLIENT_PROGRAM_NAME, DBLINK_INFO, XS_USER_NAME, XS_SESSIONID, ENTRY_ID, STATEMENT_ID, EVENT_TIMESTAMP, ACTION, RETURN_CODE,

6）检查事件相关参数，同时通过 AWR 报告 LIBRARY CACHE ACTIVITY 数据交叉验证，发现 library cache 大量发生在SQL AREA BUILD，这说明游标有大量重新加载失败现象，最常见的原因是和游标相关的基表(AUD$UNIFIED)执行了 DDL 操作

Namespace
Mode COUNT(*)
--------------- ----------
   0x7f0003                1
   0x7f0002               38
   0x520003              156
   0x520002          1544911

NAMESPACE_ID NAMESPACE
  ---------- -----------------
           0 SQL AREA
           1 TABLE/PROCEDURE
           2 BODY
          55 TEMPORARY INDEX
          64 EDITION
          69 DBLINK
          72 OBJECT ID
          73 SCHEMA
          74 DBINSTANCE
          75 SQL AREA STATS
          79 ACCOUNT_STATUS
          82 SQL AREA BUILD <<<<<<<< 0x52 = 82
  
BODY 4,052     0.00
CLUSTER                    3     0.00
DBLINK 172,627     0.00
EDITION 37,057     0.00
INDEX 7     0.00
SCHEMA 49,255     0.00
SQL AREA 334,178     0.01
SQL AREA BUILD 2,053,166     0.00  <<<<<< 此时段问题出现
SQL AREA STATS 20    85.00
TABLE/PROCEDURE 90,613     0.00
TRIGGER 3     0.00

AWR --- LIBRARY CACHE ACTIVITY 7/24 00:30 – 7/24 01:00
Namespace Get Requests Pct Miss
--------------- ------------ --------
ACCOUNT_STATUS 26,796     0.00
AUDIT POLICY 40,306     0.00
BODY 714     0.00
CLUSTER                    5     0.00
DBLINK 51,283     0.00
EDITION 18,940     0.00
INDEX 50     0.00
SCHEMA 6,703     0.00
SQL AREA 94,197     0.07
SQL AREA BUILD 3,336,301     0.00  <<<<<< 此时段问题持续加剧
SQL AREA STATS 66    75.76
TABLE/PROCEDURE 8,609     0.01
TRIGGER 6     0.00

7）经过检查，与 AUD$UNIFIED 相关的 DDL 是审计记录清理操作，该操作每天00:20:00 自动调度，按天清理过期的审计数据，内部通过 DROP 分区实现，在该库上每次执行耗时50 秒左右

JOB_NAME                   STATUS     ACTUAL_START_DATE                   DURATION   LOG_DATE                  
-------------------------- ---------- ----------------------------------- ---------- ------------------
PURGE_AUDIT_UNIFIED        SUCCEEDED  20-JUL-23 12.20.00.470983 AM +08:00 00:00:48   2023-07-20 00:20:48.724169
PURGE_AUDIT_UNIFIED        SUCCEEDED  23-JUL-23 12.20.00.648631 AM +08:00 00:00:46   2023-07-23 00:20:46.844300
PUSH_AUDIT_TSTAMP_UNIFIED  SUCCEEDED  24-JUL-23 12.10.00.442670 AM +08:00 00:00:00   2023-07-24 00:10:00.483407
PURGE_AUDIT_UNIFIED        SUCCEEDED  24-JUL-23 12.20.00.689377 AM +08:00 00:00:47   2023-07-24 00:20:47.423302
PUSH_AUDIT_TSTAMP_UNIFIED  SUCCEEDED  25-JUL-23 12.10.00.627857 AM +08:00 00:00:00   2023-07-25 00:10:00.675181
PURGE_AUDIT_UNIFIED        SUCCEEDED  25-JUL-23 12.20.00.724933 AM +08:00 00:00:44   2023-07-25 00:20:44.836736

8）检查该库审计记录，发现数据量远高于其它核心库，每天 9G 左右。而与连接相关的操作(LOGON/LOGOFF)占了绝大多数，日常每分钟约 15000 ~ 20000 次，远高于其它库的 100 ~ 500 左右

PARTITION_NAME HIGH_VALUE                TOTAL_MB
--------------- --------------------------------- --------
SYS_P22578 TIMESTAMP' 2023-07-22 00:00:00'      9,488
SYS_P22618 TIMESTAMP' 2023-07-23 00:00:00'      9,484
SYS_P22566 TIMESTAMP' 2023-07-24 00:00:00'      9,414
SYS_P22625 TIMESTAMP' 2023-07-25 00:00:00'      9,433

本库 LOGON/LOGOFF 统计，UTC 时间 07/23 16:00，北京时间 07/24 00:00

其它库 LOGON/LOGOFF 统计，UTC 时间 07/23 16:00，北京时间 07/24 00:00

9）根据以上信息，可以确定问题是由每天 02:00 开始的审计记录清理操作直接触发，考虑到并非每天都出现此问题，且该库高于其它库两个数量级的连接频率，怀疑有潜在的BUG，因此提交 SR 向 Oracle 官方确认，最终确定问题和BUG 35225526 有关。

2.2 问题总结

该库开启了审计功能（前期安全要求），每天 02:00:00 定时按天清理过期的审计记录，清理操作由 DDL完成，因此会导致和表 AUD$UNIFIED 相关的游标失效，需要reload，在此期间触发了 BUG 35225526，引发了少量 library cache lock 等待。

library cache lock等待导致对审计表的 INSERT操作性能有所下降，但高频的连接操作需要对审计表保持高性能 INSERT 操作，这形成一个互相影响的恶性循环，导致连接请求无法及时处理完成，进程数不断上涨，直至达到上限。

2.3 解决办法

通过手动强制重启实例解决。

总结及措施

3.1 BUG相关信息

根据 Oracle 官方回复，问题确认由BUG 35225526 造成。

Bug 32991289 - Many Child Cursors Being Created With Non-Sharing Reason 'Marked for Purge' and Possible Cursor Build Lock Contention ( Doc ID 32991289.8 )
以上 Bug 由于修复不完整已经被如下的修复所取代：
Bug 35225526 - fra:e18pod epm | ORA-942: Table or View Does Not Exist When Running Select Query ( Doc ID 35225526.8 )
当表上发生 DDL 的时候，表上的 cursor 会发生 cursor invalidation，目前的设计是在 cursor 处于 invalidation 状态的时候，新的进程在 parse 该 cursor 的时候不复用这些 invalidation 状态的 cursor，但是这种设计会导致持续的 reload failures 以及严重的 SQL AREA BUILD 上的 library cache lock。 Bug 32991289 的修复改进了该设计，减少了 cursor invalidation 导致的 cursor reload failures。

官方回复链接：https://support.oracle.com/epmos/faces/BugDisplay?id=32991289&parent=SrDetailText&sourceId=3-33762167191

3.2 建议措施

暂时停止该库的 LOGON/LOGOFF 操作审计。
业务使用长连接，降低用户连接频率至正常值。
业务降低连接总量和连接频率。
数据库更新小补丁 35225526，或更新大补丁 19.20.0.0.0。

END

本文作者：王傲天(上海新炬中北团队）

本文来源：“IT那活儿”公众号

oracle

文章转载自IT那活儿，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。