[20220531]模拟inactive session等待事件.txt

--//上个星期做了生产系统inactive session等待事件的探究.猜测可能是防水墙审计一些应用无法登陆,通过job kill这些回话导致的情
--//况.有许多问题不是很理解,在测试环境模拟看看.

1.环境:
SCOTT@book> @ 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

SYS@book> @ 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

2.建立测试脚本:

$ cat ee1.txt
--//select count(*) from emp,all_objects,all_objects;
select /*+ test &&1 */ count(*) from emp,all_objects,all_objects;
--//host sleep &1
quit
--//注：采用host sleep &1测试不出来或者讲问题不能再现。我就不贴出测试host sleep &1的结果了.

$ cat ee2.txt
set head off feedback off
select sid,serial# from v$session where username='SCOTT' and module='SQL*Plus';
set head on feedback on
quit

$ cat ee3.txt
--//alter system kill session '&&1,&&2' ;
alter system kill session '&&1,&&2' immediate;
quit

--//简单说明:使用ee1.txt 脚本启动多个回话. ee2.txt 脚本收集要kill session的sid,serial#.
--//ee3.txt执行kill session. 注意测试存在两个方式没有immediate以及有immediate的情况.

3.测试1:
--//先测试采用immediate kill session的情况。
--//同时启动10个回话.
$ seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @ee1.txt Q

zzdate
sqlplus -s -l / as sysdba @ ee2.txt | xargs -IQ -P 10   echo sqlplus -s -l  / as sysdba @ee3.txt Q  | bash
zzdate

SYS@book> @ wcy trunc(sysdate)+09/24+29/1440+17/86400 trunc(sysdate)+09/24+29/1440+48/86400 "event='inactive session'"
-- Display ASH Wait Chain Signatures script v0.6 BETA by Tanel Poder ( http://blog.tanelpoder.com )
no rows selected

--//可以看出采用immediate kill session 不会出现inactive session 等待事件。

4.测试2：
--//修改ee3.txt 脚本，不采用immediate参数。
$ cat ee3.txt
alter system kill session '&&1,&&2' ;
--//alter system kill session '&&1,&&2' immediate;
quit

--//同时启动10个回话.session 1：
$ seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @ee1.txt Q

--//session 2：
SYS@book> select sid,serial#,sql_id from v$session where username='SCOTT' and module='SQL*Plus';
       SID    SERIAL# SQL_ID
---------- ---------- -------------
        53         47 7zu90y1p0hgc5
        70         15 1ntbg5gvxqpfd
       104          9 11m3ncc7m3yx8
       122          9 fa54u9k0r8dfn
       138          9 4309m1zs0dt31
       154          9 cqq7gtq45wxxj
       172          7 apqywqcrmj20g
       189          7 9wbujw07bx159
       206          7 37b3pyat08r6m
       223          7 d91dc8j7j5w99
10 rows selected.
--//这样10个session执行的sql语句sql_id不同。

zzdate
sqlplus -s -l / as sysdba @ ee2.txt | xargs -IQ echo sqlplus -s -l  / as sysdba @ee3.txt Q  | bash
--//注意xargs 没有-P 10参数。
zzdate

--//session 2：
SYS@book> @ wcy trunc(sysdate)+09/24+37/1440+19/86400 trunc(sysdate)+09/24+37/1440+58/86400 "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%           1          0      1 -> 104,9,@1=>240,17,@1=>inactive session -> [idle blocker 1,104,9]  2022-05-31 09:37:44 2022-05-31 09:37:44
  10%           1          0      1 -> 138,9,@1=>53,51,@1=>inactive session -> [idle blocker 1,138,9]   2022-05-31 09:37:46 2022-05-31 09:37:46
  10%           1          0      1 -> 154,9,@1=>53,53,@1=>inactive session -> [idle blocker 1,154,9]   2022-05-31 09:37:47 2022-05-31 09:37:47
  10%           1          0      1 -> 206,7,@1=>53,59,@1=>inactive session -> [idle blocker 1,206,7]   2022-05-31 09:37:50 2022-05-31 09:37:50
  10%           1          0      1 -> ,,@=>53,61,@1=>inactive session                                  2022-05-31 09:37:51 2022-05-31 09:37:51
  10%           1          0      1 -> ,,@=>53,55,@1=>inactive session                                  2022-05-31 09:37:48 2022-05-31 09:37:48
  10%           1          0      1 -> ,,@=>240,13,@1=>inactive session                                 2022-05-31 09:37:42 2022-05-31 09:37:42
  10%           1          0      1 -> ,,@=>53,49,@1=>inactive session                                  2022-05-31 09:37:45 2022-05-31 09:37:45
  10%           1          0      1 -> 70,15,@1=>240,15,@1=>inactive session -> [idle blocker 1,70,15]  2022-05-31 09:37:43 2022-05-31 09:37:43
  10%           1          0      1 -> 189,7,@1=>53,57,@1=>inactive session -> [idle blocker 1,189,7]   2022-05-31 09:37:49 2022-05-31 09:37:49
10 rows selected.

SYS@book> @ashtop event,sid,serial "event='inactive session'" trunc(sysdate)+09/24+37/1440+19/86400 trunc(sysdate)+09/24+37/1440+58/86400
    Total                                                                                            Distinct Distinct
  Seconds     AAS %This   EVENT             SID     SERIAL FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps
--------- ------- ------- ---------------- ---- ---------- ------------------- ------------------- ---------- --------
        1      .0   10% | inactive session   53         49 2022-05-31 09:37:45 2022-05-31 09:37:45          1        1
        1      .0   10% | inactive session   53         51 2022-05-31 09:37:46 2022-05-31 09:37:46          1        1
        1      .0   10% | inactive session   53         53 2022-05-31 09:37:47 2022-05-31 09:37:47          1        1
        1      .0   10% | inactive session   53         55 2022-05-31 09:37:48 2022-05-31 09:37:48          1        1
        1      .0   10% | inactive session   53         57 2022-05-31 09:37:49 2022-05-31 09:37:49          1        1
        1      .0   10% | inactive session   53         59 2022-05-31 09:37:50 2022-05-31 09:37:50          1        1
        1      .0   10% | inactive session   53         61 2022-05-31 09:37:51 2022-05-31 09:37:51          1        1
        1      .0   10% | inactive session  240         13 2022-05-31 09:37:42 2022-05-31 09:37:42          1        1
        1      .0   10% | inactive session  240         15 2022-05-31 09:37:43 2022-05-31 09:37:43          1        1
        1      .0   10% | inactive session  240         17 2022-05-31 09:37:44 2022-05-31 09:37:44          1        1
10 rows selected.
--//sid=53,注意serial的变化+2.为什么会出现这样的变化。开始以为我没人登录了，仔细看前面的执行，实际上瞬间开启了10个kill session的进程。
--//注意xargs 我没有使用-p 参数，也就是在kill 会话不带immediate时影响了阻塞了后续登录。
sqlplus -s -l / as sysdba @ ee2.txt | xargs -IQ echo sqlplus -s -l  / as sysdba @ee3.txt Q  | bash

--//注意看一个细节。出现sid=240 3行，FIRST_SEEN=2022-05-31 09:37:42最早出现，也是这一个会话kill sid=53,等3秒后sid=53可以重用，执行完成完成后不断退出。
--//这样出现SERIAL +2(sid=53)的情况，这样就可以很好的解析上面看到的情况。

--//也就是使用kill参数immediae时，如果有用户登录，会收到阻塞，出现inactive session 等待事件。

5.测试3：
--//如果我顺序kill这些会话情况如何呢？修改ee3.txt脚本注解quit。
$ cat ee3.txt
alter system kill session '&&1,&&2' ;
--alter system kill session '&&1,&&2' immediate;
--quit

--//session 1:
$ seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @ee1.txt Q

zzdate
sqlplus -s -l / as sysdba @ ee2.txt | xargs -IQ   echo  @ee3.txt Q  >| ee4.txt
$ cat ee4.txt
@ee3.txt 53         81
@ee3.txt 70         25
@ee3.txt 104         13
@ee3.txt 122         11
@ee3.txt 138         11
@ee3.txt 154         11
@ee3.txt 172          9
@ee3.txt 189          9
@ee3.txt 206          9
@ee3.txt 223          9

--//等ee4.txt执行后执行如下：
zzdate

--//session 2:
SYS@book> @ee4.txt

SYS@book> @ wcy trunc(sysdate)+09/24+54/1440+41/86400 trunc(sysdate)+09/24+55/1440+41/86400 "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
------ ---------- ------- ------ -------------------------------------------------------------------- ------------------- -------------------
  30%           3      .1      1 -> ,,@=>87,25,@1=>inactive session                                   2022-05-31 09:55:27 2022-05-31 09:55:32
  20%           2      .0      1 -> 104,13,@1=>87,25,@1=>inactive session -> [idle blocker 1,104,13]  2022-05-31 09:55:29 2022-05-31 09:55:31
  20%           2      .0      1 -> 206,9,@1=>87,25,@1=>inactive session -> [idle blocker 1,206,9]    2022-05-31 09:55:35 2022-05-31 09:55:36
  10%           1      .0      1 -> 122,11,@1=>87,25,@1=>inactive session -> [idle blocker 1,122,11]  2022-05-31 09:55:30 2022-05-31 09:55:30
  10%           1      .0      1 -> 172,9,@1=>87,25,@1=>inactive session -> [idle blocker 1,172,9]    2022-05-31 09:55:33 2022-05-31 09:55:33
  10%           1      .0      1 -> 189,9,@1=>87,25,@1=>inactive session -> [idle blocker 1,189,9]    2022-05-31 09:55:34 2022-05-31 09:55:34
6 rows selected.
--//有点小小意外，我开始以为这样就不会出现inactive session等待事件，实际上还是出现。而sid=87正是session 2，我执行ee4.txt的会话。
SYS@book> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        87         25 47655                    DEDICATED 47656       29         12 alter system kill session '87,25' immediate;

SYS@book> @ashtop event,sid,serial,BLOCKING_SESSION,BLOCKING_SESSION_SERIAL# "event='inactive session'" trunc(sysdate)+09/24+54/1440+41/86400 trunc(sysdate)+09/24+55/1440+41/86400
    Total                                                                                                                                     Distinct Distinct
  Seconds     AAS %This   EVENT            SID     SERIAL BLOCKING_SESSION BLOCKING_SESSION_SERIAL# FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps
--------- ------- ------- ---------------- --- ---------- ---------------- ------------------------ ------------------- ------------------- ---------- --------
        3      .1   30% | inactive session  87         25                                           2022-05-31 09:55:27 2022-05-31 09:55:32          1        3
        2      .0   20% | inactive session  87         25              104                       13 2022-05-31 09:55:29 2022-05-31 09:55:31          1        2
        2      .0   20% | inactive session  87         25              206                        9 2022-05-31 09:55:35 2022-05-31 09:55:36          1        2
        1      .0   10% | inactive session  87         25              122                       11 2022-05-31 09:55:30 2022-05-31 09:55:30          1        1
        1      .0   10% | inactive session  87         25              172                        9 2022-05-31 09:55:33 2022-05-31 09:55:33          1        1
        1      .0   10% | inactive session  87         25              189                        9 2022-05-31 09:55:34 2022-05-31 09:55:34          1        1
6 rows selected.

$ cat ee4.txt
@ee3.txt 53         81
@ee3.txt 70         25
@ee3.txt 104        13
@ee3.txt 122        11
@ee3.txt 138        11
@ee3.txt 154        11
@ee3.txt 172        9
@ee3.txt 189        9
@ee3.txt 206        9
@ee3.txt 223        9

--//3+2+2+1+1+1 = 10秒。

6.测试4：
--//--//如果我顺序kill这些会话情况, 并且每次kill 后，sleep 1秒呢。
--//session 1:
$ seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @ee1.txt Q


zzdate
sqlplus -s -l / as sysdba @ ee2.txt | xargs -IQ   echo  -e "@ee3.txt Q \nhost sleep  1" >| ee4_1.txxt

$ cat ee4_1.txt
@ee3.txt 104         17
host sleep  1
@ee3.txt 122         13
host sleep  1
@ee3.txt 138         13
host sleep  1
@ee3.txt 154         13
host sleep  1
@ee3.txt 172         11
host sleep  1
@ee3.txt 189         11
host sleep  1
@ee3.txt 206         11
host sleep  1
@ee3.txt 223         11
host sleep  1
@ee3.txt 240         29
host sleep  1
@ee3.txt 257         61
host sleep  1

--//等ee4_1.txt执行后执行如下：
zzdate

--//session 2:
SYS@book> @ ee4_1.txt
SYS@book> @ wcy trunc(sysdate)+10/24+09/1440+05/86400 trunc(sysdate)+10/24+11/1440+19/86400 "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
------ ---------- ------- ------ ------------------------------------------------------------------- ------------------- -------------------
  50%           5      .0      1 -> ,,@=>87,25,@1=>inactive session                                  2022-05-31 10:10:54 2022-05-31 10:11:12
  20%           2      .0      1 -> 172,11,@1=>87,25,@1=>inactive session -> [idle blocker 1,172,11] 2022-05-31 10:11:02 2022-05-31 10:11:04
  10%           1      .0      1 -> 206,11,@1=>87,25,@1=>inactive session -> [idle blocker 1,206,11] 2022-05-31 10:11:06 2022-05-31 10:11:06
  10%           1      .0      1 -> 138,13,@1=>87,25,@1=>inactive session -> [idle blocker 1,138,13] 2022-05-31 10:10:58 2022-05-31 10:10:58
  10%           1      .0      1 -> 240,29,@1=>87,25,@1=>inactive session -> [idle blocker 1,240,29] 2022-05-31 10:11:10 2022-05-31 10:11:10

--//sleep 2秒呢？重复测试，结果如下:
SYS@book> @ wcy trunc(sysdate)+10/24+13/1440+57/86400 trunc(sysdate)+10/24+14/1440+52/86400 "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
------ ---------- ------- ------ ---------------------------------- ------------------- -------------------
 100%          10      .2      1 -> ,,@=>87,25,@1=>inactive session 2022-05-31 10:14:12 2022-05-31 10:14:39

SYS@book> @ashtop event,sid,serial,BLOCKING_SESSION,BLOCKING_SESSION_SERIAL# "event='inactive session'" trunc(sysdate)+10/24+13/1440+57/86400 trunc(sysdate)+10/24+14/1440+52/86400
    Total                                                                                                                                     Distinct Distinct
  Seconds     AAS %This   EVENT            SID     SERIAL BLOCKING_SESSION BLOCKING_SESSION_SERIAL# FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps
--------- ------- ------- ---------------- --- ---------- ---------------- ------------------------ ------------------- ------------------- ---------- --------
       10      .2  100% | inactive session  87         25                                           2022-05-31 10:14:12 2022-05-31 10:14:39          1       10

--//这样就不存在阻塞了。但是可以看出每次kill 一个会话就出现1次inactive session等待事件。应该是每次等待1秒。

--//补充我还测试了sleep 1.9秒的情况：
SYS@book> @ wcy  trunc(sysdate)+10/24+22/1440+47/86400 trunc(sysdate)+10/24+24/1440+57/86400 "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
------ ---------- ------- ------ ------------------------------------------------------------------ ------------------- -------------------
  90%           9      .1      1 -> ,,@=>87,25,@1=>inactive session                                 2022-05-31 10:24:05 2022-05-31 10:24:31
  10%           1      .0      1 -> 70,47,@1=>87,25,@1=>inactive session -> [idle blocker 1,70,47]  2022-05-31 10:24:07 2022-05-31 10:24:07

7.附上测试脚本：
$ alias zzdate
alias zzdate='date +"trunc(sysdate)+%H/24+%M/1440+%S/86400 == %Y/%m/%d %T == timestamp'\''%Y-%m-%d %T'\''"'

--//wcy.sql 脚本利用tpt的ash_wait_chains.sql脚本。
$ cat wcy.sql
@ tpt/ash/ash_wait_chains BLOCKING_SESSION||','||BLOCKING_SESSION_SERIAL#||',@'||BLOCKING_INST_ID||'=>'||session_id||','||SESSION_SERIAL#||',@'||inst_id||'=>'||event "&&3"  "&&1" "&&2"