[20220531]inactive session等待事件2.txt

来源：这里教程网时间：2026-03-03 17:40:52 作者：

[20220531]inactive session等待事件2.txt --//检查生产系统，发现inactive session 和 enq: FU - contention 等待事件,从来没有遇到过,仔细探究看看： --//本文集中inactive session等待事件,在分析过程中走了许多弯路,重新整理. 1.环境： > @ ver1 PORT_STRING VERSION BANNER ------------------------------ -------------- -------------------------------------------------------------------------------- x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production 2.ashtop查看： > @ashtop event 1=1 &day Total Distinct Distinct Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps --------- ------- ------- ------------------------------ ------------------- ------------------- ---------- -------- 334312 3.9 93% | 2022-05-16 10:52:20 2022-05-17 10:52:12 15444 32265 13951 .2 4% | inactive session 2022-05-16 10:52:18 2022-05-17 10:52:11 6248 8976 2854 .0 1% | enq: FU - contention 2022-05-16 11:11:39 2022-05-17 10:14:18 1 2854 2342 .0 1% | RMAN backup & recovery I/O 2022-05-16 19:30:08 2022-05-17 01:52:46 1 496 1236 .0 0% | control file sequential read 2022-05-16 10:57:37 2022-05-17 10:51:08 528 996 734 .0 0% | enq: TX - row lock contention 2022-05-16 15:43:39 2022-05-16 17:16:01 3 734 --//inactive session 和 enq: FU - contention等待事件，先集中探究inactive session,关于enq: FU - contention另外写一篇文章. > @ ev_name "inactive session" EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS ------ ---------- ---------------- ----------- ----------- -------------------- ------------- ----------- ---------- 422 3757863830 inactive session session# waited instance|serial 1893977003 0 Other 3.分析: > @ ashtop sql_id,machine "event='inactive session'" &day Total Distinct Distinct Seconds AAS %This SQL_ID MACHINE FIRST_SEEN LAST_SEEN Execs Seen Tstamps --------- ------- ------- ------------- -------------------- ------------------- ------------------- ---------- -------- 6 .0 0% | 00pxd4aar1nug fyhis2 2022-05-18 20:27:36 2022-05-18 20:27:38 2 3 6 .0 0% | 017smqud0wmq1 fyhis2 2022-05-19 09:33:28 2022-05-19 09:33:30 2 3 6 .0 0% | 01rt1d6530tsb fyhis2 2022-05-19 09:25:12 2022-05-19 09:25:14 2 3 6 .0 0% | 01tzhda22b2gw fyhis2 2022-05-19 08:19:13 2022-05-19 08:19:15 2 3 6 .0 0% | 029k77b1npypb fyhis2 2022-05-18 12:16:55 2022-05-18 12:16:57 2 3 6 .0 0% | 02qy363816jac fyhis2 2022-05-18 19:30:58 2022-05-18 19:31:00 2 3 .... 30 rows selected. > @ sql_id 00pxd4aar1nug --SQL_ID = 00pxd4aar1nug DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN tlogon.killsession(8481,3615); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END; ; --//查看几个都是类似的语句。 --//猜测防水墙执行的kill会话的语句。格式化如下: DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN tlogon.killsession(8481,3615); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END; / --//猜测应该是防水墙对于无法登陆的回话kill. $ tail -f alert_ywdb1.log ORA-06512: at line 5 opiodr aborting process unknown ospid (25783) as a result of ORA-28 Tue May 17 09:11:27 2022 Errors in file /u01/app/oracle/diag/rdbms/ywdb/ywdb1/trace/ywdb1_ora_15721.trc: ORA-00604: error occurred at recursive SQL level 1 ORA-00028: your session has been killed ORA-06512: at "SYS.DBMS_LOCK", line 205 ORA-06512: at "HZMCASSET.TLOGON", line 1552 ORA-06512: at "HZMCASSET.TLOGON", line 1566 ORA-06512: at "HZMCASSET.TLOGON", line 1620 ORA-06512: at "HZMCASSET.TLOGON", line 2523 --//1566-1552 = 14 --//1620-1552 = 68 --//2523-1552 = 971 ORA-06512: at line 1 ORA-06512: at line 5 opiodr aborting process unknown ospid (15721) as a result of ORA-28 Tue May 17 09:11:30 2022 $ oerr ora 28 00028, 00000, "your session has been killed" // *Cause: A privileged user has killed your session and you are no longer // logged on to the database. // *Action: Login again if you wish to continue working. --//tlogon包体是加密的,不过网上很容易找到破解软件.unwrap包后，执行代码如下,注我加了行号: 94 PROCEDURE KILLSESSION(V_SID NUMBER, V_SERIAL# NUMBER) IS 95 L_SQL VARCHAR2(4000); 96 BEGIN 97 L_SQL := 'alter system kill session ' || '''' || V_SID || ',' || 98 V_SERIAL# || ''''; 99 100 EXECUTE IMMEDIATE L_SQL; 101 EXCEPTION 102 WHEN OTHERS THEN 103 ROLLBACK; 104 END; --//很简单,根据参数kill session,注意并没有immediate参数。也就是对于无法满足登陆条件的回话,直接kill. --//继续看了源代码,还有一段: 1542 PROCEDURE SUBMITKILLSESSION(V_SID NUMBER, V_SERIAL# NUMBER) IS 1543 L_JOB NUMBER; 1544 L_SQL VARCHAR2(4000); 1545 BEGIN 1546 SYS.DBMS_JOB.SUBMIT(L_JOB, 1547 'tlogon.killsession(' || TO_CHAR(V_SID) || ',' || 1548 TO_CHAR(V_SERIAL#) || ');', 1549 SYSDATE, 1550 INSTANCE => SYS_CONTEXT('userenv', 'instance')); 1551 COMMIT; 1552 SYS.DBMS_LOCK.SLEEP(3); ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 1553 END; 1554 BEGIN 1555 IF TLOGONAUDIT.ACTIONLEVEL = REJECT THEN 1556 TVAR.G_1031 := TRUE; 1557 IF LOWER(SYS_CONTEXT('userenv', 'isdba')) = 'true' THEN 1558 SUBMITKILLSESSION(TLOGONAUDIT.SID, TLOGONAUDIT.SERIAL); 1559 END IF; 1560 1561 IF LOWER(SYS_CONTEXT('idctx', 'isdba')) = 'true' THEN 1562 SUBMITKILLSESSION(TLOGONAUDIT.SID, TLOGONAUDIT.SERIAL); 1563 END IF; 1564 1565 IF ISTRIGGERADMIN = TRUE THEN 1566 SUBMITKILLSESSION(TLOGONAUDIT.SID, TLOGONAUDIT.SERIAL); ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 1567 END IF; 1568 1569 1570 1571 RAISE PRIVS_ERROR; 1572 END IF; 1573 TVAR.G_SESSID := TLOGONAUDIT.ID; 1574 1575 EXCEPTION 1576 WHEN OTHERS THEN 1577 L_ERRCODE := SQLCODE; 1578 L_ERRMSG := SUBSTR(SQLERRM, 1, 100); 1579 ROLLBACK; 1580 RAISEAPPERROR(L_ERRCODE, 1581 ERR_LOGONRULE, 1582 STRLOGONRULE || ' doaction ' || L_ERRMSG); 1583 END; 1584 1585 FUNCTION CHECKACCOUNT RETURN BOOLEAN IS 1586 BEGIN 1587 IF SYS_CONTEXT('userenv', 'session_user') = 1588 SYS_CONTEXT('userenv', 'current_user') THEN 1589 IF TLOGONAUDIT.APPNAME LIKE 'CAPAA-%' OR 1590 TLOGONAUDIT.APPNAME = 'JOB' THEN 1591 RETURN TRUE; 1592 ELSE 1593 RETURN FALSE; 1594 END IF; 1595 END IF; 1596 RETURN TRUE; 1597 END; 1598 ... 1606 PROCEDURE DORESPONSE IS ... 1620 DOACTION; ... 2523 DORESPONSE; --//alert内容: Tue May 17 09:11:27 2022 Errors in file /u01/app/oracle/diag/rdbms/ywdb/ywdb1/trace/ywdb1_ora_15721.trc: ORA-00604: error occurred at recursive SQL level 1 ORA-00028: your session has been killed ORA-06512: at "SYS.DBMS_LOCK", line 205 ORA-06512: at "HZMCASSET.TLOGON", line 1552 ORA-06512: at "HZMCASSET.TLOGON", line 1566 ORA-06512: at "HZMCASSET.TLOGON", line 1620 ORA-06512: at "HZMCASSET.TLOGON", line 2523 --//根据alert的报错,可以推断先执行DORESPONSE,DOACTION,SUBMITKILLSESSION,然后调用SYS.DBMS_LOCK.SLEEP(3). --//我开始以为没有给SYS.DBMS_LOCK.SLEEP授权执行权限,导致出现在alert出现以上错误.仔细检查发现授权存在. --// GRANT EXECUTE ON SYS.DBMS_LOCK TO HZMCASSET; > Select job, what c40 , instance from DBA_JOBS where schema_user = 'HZMCASSET'; JOB C40 INSTANCE ---------- ---------------------------------------- ---------- 61191 tlogon.killsession(581,17111); 1 61192 tlogon.killsession(581,17111); 1 > Select job, what c40 , instance from DBA_JOBS where schema_user = 'HZMCASSET'; no rows selected --//后台不断的kill这些会话。我发现有时候出现2行，有时候出现1行,为什么?我开始不理解开发为什么使用job的方式, --//直接调用KILLSESSION 过程不就可以了吗?后来才明白oracle不能kill自己.会出现如下提示: --// ORA-00027: cannot kill current session --//后来想明白了,出现2行的情况下,第一次调用job失败,然后启动另外1个job执行成功.这样前面job继续执行时正好在 --//执行SYS.DBMS_LOCK.SLEEP(3)操作(因为sleep 3秒),第2个job已经kill了回话,这样就会在alert记录如下: Tue May 17 09:11:27 2022 Errors in file /u01/app/oracle/diag/rdbms/ywdb/ywdb1/trace/ywdb1_ora_15721.trc: ORA-00604: error occurred at recursive SQL level 1 ORA-00028: your session has been killed ORA-06512: at "SYS.DBMS_LOCK", line 205 ORA-06512: at "HZMCASSET.TLOGON", line 1552 ORA-06512: at "HZMCASSET.TLOGON", line 1566 ORA-06512: at "HZMCASSET.TLOGON", line 1620 ORA-06512: at "HZMCASSET.TLOGON", line 2523 --//第一次为什么会失败,按照前面ashtop脚本的输出,可以定位出现了inactive session等待事件,阻塞了kill操作. --//为什么这样的操作会出现inactive session等待事件呢?继续分析: --//查看跟踪文件，应该是MODULE NAME:(JDBC Thin Client)时无法登录。 *** 2022-05-17 10:17:18.201 *** SESSION ID:(8757.6731) 2022-05-17 10:17:18.201 *** CLIENT ID:() 2022-05-17 10:17:18.201 *** SERVICE NAME:(ywdb) 2022-05-17 10:17:18.201 *** MODULE NAME:(JDBC Thin Client) 2022-05-17 10:17:18.201 *** ACTION NAME:() 2022-05-17 10:17:18.201 --//没有其他相关信息,也无法知道是那个用户登录 --//很奇怪应用出现错误,无法登陆,没有任何开发反馈,无语. > @ wcy &1min "event='inactive session'" -- Display ASH Wait Chain Signatures script v0.6 BETA by Tanel Poder ( http://blog.tanelpoder.com ) %This SECONDS AAS #Blkrs WAIT_CHAIN FIRST_SEEN LAST_SEEN ------ ---------- ---------- ------ -------------------------------------------------------------------------------- ------------------- ------------------- 10% 3 .1 1 -> 590,9377,@2=>7628,11383,@2=>inactive session -> [idle blocker 2,590,9377] 2022-05-19 11:43:07 2022-05-19 11:43:09 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 10% 3 .1 1 -> 590,9377,@2=>295,56079,@2=>inactive session -> [idle blocker 2,590,9377] 2022-05-19 11:43:07 2022-05-19 11:43:09 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 10% 3 .1 1 -> 590,9423,@2=>295,56083,@2=>inactive session -> [idle blocker 2,590,9423] 2022-05-19 11:43:32 2022-05-19 11:43:34 10% 3 .1 1 -> 590,9423,@2=>7628,11385,@2=>inactive session -> [idle blocker 2,590,9423] 2022-05-19 11:43:32 2022-05-19 11:43:34 7% 2 0 1 -> 590,9349,@2=>3128,17545,@2=>inactive session -> [idle blocker 2,590,9349] 2022-05-19 11:42:47 2022-05-19 11:42:48 7% 2 0 1 -> 7338,30489,@1=>7340,14317,@1=>inactive session -> [idle blocker 1,7338,30489] 2022-05-19 11:43:25 2022-05-19 11:43:26 7% 2 0 1 -> 7338,30487,@1=>14,22465,@1=>inactive session -> [idle blocker 1,7338,30487] 2022-05-19 11:43:20 2022-05-19 11:43:21 7% 2 0 1 -> 7338,30489,@1=>14,22467,@1=>inactive session -> [idle blocker 1,7338,30489] 2022-05-19 11:43:25 2022-05-19 11:43:26 7% 2 0 1 -> 590,9349,@2=>7628,11379,@2=>inactive session -> [idle blocker 2,590,9349] 2022-05-19 11:42:47 2022-05-19 11:42:48 3% 1 0 1 -> ,,@=>7340,14317,@1=>inactive session 2022-05-19 11:43:27 2022-05-19 11:43:27 3% 1 0 1 -> 590,9351,@2=>7628,11381,@2=>inactive session -> [idle blocker 2,590,9351] 2022-05-19 11:42:52 2022-05-19 11:42:52 3% 1 0 1 -> ,,@=>7628,11379,@2=>inactive session 2022-05-19 11:42:49 2022-05-19 11:42:49 3% 1 0 1 -> ,,@=>14,22467,@1=>inactive session 2022-05-19 11:43:27 2022-05-19 11:43:27 3% 1 0 1 -> ,,@=>295,56085,@2=>inactive session 2022-05-19 11:43:37 2022-05-19 11:43:37 3% 1 0 1 -> ,,@=>3128,17545,@2=>inactive session 2022-05-19 11:42:49 2022-05-19 11:42:49 3% 1 0 1 -> ,,@=>295,56081,@2=>inactive session 2022-05-19 11:43:12 2022-05-19 11:43:12 16 rows selected. --//仔细看阻塞的链条.似乎阻塞链接出现在相同实例,注意看一个细节sid=7628,serial# 会变化(+2). --//噢，视乎想明白了，因为不断有用户登录，出现serial# 会变化加2的情况，另外写blog验证这个情况。 4.总结: --//通过以上分析可以得到一个结论,大量job在kill session时,会出现inactive session. --//应该可以在测试环境模拟出inactive session等待事件. --//开发应该immediate kill 会话也许就不会出现这个提示了。