[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 会话也许就不会出现这个提示了。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2898061/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
