其他分享
首页 > 其他分享> > [20220228]enq TX - allocate ITL entry的测试3.txt

[20220228]enq TX - allocate ITL entry的测试3.txt

作者:互联网

[20220228]enq TX - allocate ITL entry的测试3.txt

--//上个星期的测试有点乱,重新规划测试.

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

create table t ( x int primary key, y varchar2(4000)) PCTFREE 0 INITRANS 169 TABLESPACE users;
insert into t (x,y) select rownum, rpad('*',10,'*') from dual connect by level <= 171;
commit ;

--//可以发现记录在同一块中,共171条记录.
--//前面的测试使用同一会话,最后死锁结束,换1个方式测试看看.

2.建立测试脚本:
$ cat itl_3.txt
set head off
set verify off
set feedback off
column x format 999999
host sleep $(echo &&1/5 | bc -l )
select 'ITL'||&1,s.sid,s.serial# ,s.process,s.server,p.spid from v$session s,v$process p where s.sid in (select sid from v$mystat where rownum=1) and s.paddr=p.addr;
select x  from t where x = &&1 for update ;
host sleep 3000
commit ;
quit
--//注执行前加入sleep ,保证执行顺序.

$ zzdate
trunc(sysdate)+08/24+46/1440+37/86400 == 2022/02/28 08:46:37 == timestamp'2022-02-28 08:46:37'

$ seq 169 | xargs -IQ echo "sqlplus -s -l scott/book @itl_3.txt Q &" | bash | tee /tmp/itl.txt
--//等待169/5 = 33.8秒后,保证全部回话执行itl_3.txt的脚本执行到select * from t where x = &&1 for update ;

$ cat /tmp/itl.txt | awk '/ITL/{print $1}' | diff <(cut -c4- ) <(seq 169)
--//执行顺序一致.

--//打开新的会话执行如下:
SCOTT@book> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        60         21 51655                    DEDICATED 51656      195          1 alter system kill session '60,21' immediate;

SCOTT@book> @ 10046on 8
Session altered.

SCOTT@book> select x from t where x =170 for update ;
--//挂起!!等待结束。

         X
----------
       170

SCOTT@book> @10046off
Session altered.

--//观察跟踪文件:
 $ grep "WAIT.*TX" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_51656.trc
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1001112 name|mode=1415053316 usn<<16 | slot=1900563 sequence=18 obj#=331601 tim=1646009349046308
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000919 name|mode=1415053316 usn<<16 | slot=11665439 sequence=19 obj#=331601 tim=1646009350047337
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000951 name|mode=1415053316 usn<<16 | slot=1966103 sequence=17 obj#=331601 tim=1646009351048375
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000814 name|mode=1415053316 usn<<16 | slot=6619164 sequence=16 obj#=331601 tim=1646009352049278
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000992 name|mode=1415053316 usn<<16 | slot=9764879 sequence=17 obj#=331601 tim=1646009353050390
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000752 name|mode=1415053316 usn<<16 | slot=4587537 sequence=18 obj#=331601 tim=1646009354051241
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1001041 name|mode=1415053316 usn<<16 | slot=6946825 sequence=17 obj#=331601 tim=1646009355052378
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000757 name|mode=1415053316 usn<<16 | slot=12124181 sequence=19 obj#=331601 tim=1646009356053225
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000891 name|mode=1415053316 usn<<16 | slot=5373980 sequence=17 obj#=331601 tim=1646009357054247
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000920 name|mode=1415053316 usn<<16 | slot=9633805 sequence=19 obj#=331601 tim=1646009358055257
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000894 name|mode=1415053316 usn<<16 | slot=720926 sequence=3218 obj#=331601 tim=1646009359056243
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000908 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009360057244
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000869 name|mode=1415053316 usn<<16 | slot=1900563 sequence=18 obj#=331601 tim=1646009362058240
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2001151 name|mode=1415053316 usn<<16 | slot=11665439 sequence=19 obj#=331601 tim=1646009364059481
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000620 name|mode=1415053316 usn<<16 | slot=1966103 sequence=17 obj#=331601 tim=1646009366060191
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2001026 name|mode=1415053316 usn<<16 | slot=6619164 sequence=16 obj#=331601 tim=1646009368061324
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000776 name|mode=1415053316 usn<<16 | slot=9764879 sequence=17 obj#=331601 tim=1646009370062232
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000903 name|mode=1415053316 usn<<16 | slot=4587537 sequence=18 obj#=331601 tim=1646009372063256
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000954 name|mode=1415053316 usn<<16 | slot=6946825 sequence=17 obj#=331601 tim=1646009374064326
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000872 name|mode=1415053316 usn<<16 | slot=12124181 sequence=19 obj#=331601 tim=1646009376065331
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000801 name|mode=1415053316 usn<<16 | slot=5373980 sequence=17 obj#=331601 tim=1646009378066263
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000842 name|mode=1415053316 usn<<16 | slot=9633805 sequence=19 obj#=331601 tim=1646009380067206
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2001099 name|mode=1415053316 usn<<16 | slot=720926 sequence=3218 obj#=331601 tim=1646009382068420
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000769 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009384069277
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 4002028 name|mode=1415053316 usn<<16 | slot=1900563 sequence=18 obj#=331601 tim=1646009388071418

--//观察最后1个ITL槽的情况。单独检索slot=9699359.
$ grep "WAIT.*TX" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_51656.trc | grep slot=9699359
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1000908 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009360057244
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 2000769 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009384069277
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 4001984 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009432093269
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 8002922 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009495413338
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 16005839 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009566712352
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 32010527 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009653988243
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 64001553 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009773352234
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 128002159 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646009956764292
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 256007845 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646010268113364
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 512010697 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646010835514244
WAIT #140362055751624: nam='enq: TX - allocate ITL entry' ela= 1337949215 name|mode=1415053316 usn<<16 | slot=9699359 sequence=18 obj#=331601 tim=1646012228784060

--//你可以发现一个特点.12个ITL槽为1组,开始1秒,然后2秒,然后4秒,然后5秒,最后1个ITL等待秒数是 2^(迭代次数-1).再然后还是5秒,最后1个ITL等待秒数是 2^(迭代次数-1),如此循环.
--//结束测试,注意最后1次不是2^10=102秒。

--//看看那些会话:
$ cat /tmp/itl.txt | awk '/ITL/{print $1}' | diff <(cut -c4- ) <(seq 169)
--//这次测试顺序一致,看看使用那些ITL槽。

SCOTT@book> @wcy trunc(sysdate)+08/24+46/1440+37/86400 sysdate "event='enq: TX - allocate ITL entry'"

-- 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
------ ---------- ---------- ------ ----------------------------------------------------------------------------- ------------------- -------------------
  82%        2359         .6      1 -> 258,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,258,7] 2022-02-28 08:49:19 2022-02-28 09:37:08
   2%          47          0      1 -> 88,11,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,88,11] 2022-02-28 08:49:10 2022-02-28 09:14:10
   2%          47          0      1 -> 54,19,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,54,19] 2022-02-28 08:49:08 2022-02-28 09:14:00
   2%          47          0      1 -> 173,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,173,7] 2022-02-28 08:49:14 2022-02-28 09:14:30
   2%          47          0      1 -> 38,1,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,38,1]   2022-02-28 08:49:09 2022-02-28 09:14:05
   2%          47          0      1 -> 224,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,224,7] 2022-02-28 08:49:18 2022-02-28 09:14:50
   2%          47          0      1 -> 123,9,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,123,9] 2022-02-28 08:49:12 2022-02-28 09:14:20
   2%          47          0      1 -> 139,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,139,7] 2022-02-28 08:49:15 2022-02-28 09:14:35
   2%          47          0      1 -> 156,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,156,7] 2022-02-28 08:49:13 2022-02-28 09:14:25
   2%          47          0      1 -> 190,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,190,7] 2022-02-28 08:49:16 2022-02-28 09:14:40
   2%          47          0      1 -> 207,7,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,207,7] 2022-02-28 08:49:17 2022-02-28 09:14:45
   2%          47          0      1 -> 71,13,@1=>60,21,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,71,13] 2022-02-28 08:49:11 2022-02-28 09:14:15
12 rows selected.
--//其它都是47秒。仅仅1个等待2359秒(也就是最后12ITL槽的最后1个ITL槽)。

WITH itl
     AS (  SELECT TO_CHAR (sample_time, 'yyyy-mm-dd hh24:mi:ss') ss
                 ,blocking_session
                 ,blocking_session_serial#
             FROM V$ACTIVE_SESSION_HISTORY
            WHERE     event = 'enq: TX - allocate ITL entry'
                  AND sample_time >= timestamp'2022-02-28 08:46:37'
         ORDER BY sample_time)
  SELECT blocking_session, blocking_session_serial#, COUNT (*)
    FROM itl
GROUP BY  blocking_session, blocking_session_serial#
ORDER BY 3;

BLOCKING_SESSION BLOCKING_SESSION_SERIAL#   COUNT(*)
---------------- ------------------------ ----------
             139                        7         47
             190                        7         47
              54                       19         47
             173                        7         47
              38                        1         47
              71                       13         47
             123                        9         47
             156                        7         47
             224                        7         47
             207                        7         47
              88                       11         47
             258                        7       2359
12 rows selected.
--//你可以发现使用12个槽是固定的.

SELECT  sample_time c30,blocking_session, blocking_session_serial#
    FROM V$ACTIVE_SESSION_HISTORY
   WHERE     event = 'enq: TX - allocate ITL entry'
         AND sample_time >= timestamp'2022-02-28 08:46:37'
ORDER BY sample_time;

C30                            BLOCKING_SESSION BLOCKING_SESSION_SERIAL#
------------------------------ ---------------- ------------------------
2022-02-28 08:49:08.285                      54                       19
2022-02-28 08:49:09.285                      38                        1
2022-02-28 08:49:10.285                      88                       11
2022-02-28 08:49:11.285                      71                       13
2022-02-28 08:49:12.295                     123                        9
2022-02-28 08:49:13.295                     156                        7
2022-02-28 08:49:14.295                     173                        7
2022-02-28 08:49:15.295                     139                        7
2022-02-28 08:49:16.295                     190                        7
2022-02-28 08:49:17.295                     207                        7
2022-02-28 08:49:18.295                     224                        7
2022-02-28 08:49:19.305                     258                        7
2022-02-28 08:49:20.305                      54                       19
2022-02-28 08:49:21.305                      54                       19
2022-02-28 08:49:22.305                      38                        1
2022-02-28 08:49:23.305                      38                        1
2022-02-28 08:49:24.305                      88                       11
2022-02-28 08:49:25.305                      88                       11
2022-02-28 08:49:26.305                      71                       13
2022-02-28 08:49:27.305                      71                       13
2022-02-28 08:49:28.305                     123                        9
2022-02-28 08:49:29.332                     123                        9
2022-02-28 08:49:30.332                     156                        7
2022-02-28 08:49:31.342                     156                        7
2022-02-28 08:49:32.342                     173                        7
2022-02-28 08:49:33.342                     173                        7
2022-02-28 08:49:34.352                     139                        7
2022-02-28 08:49:35.352                     139                        7
2022-02-28 08:49:36.352                     190                        7
2022-02-28 08:49:37.352                     190                        7
2022-02-28 08:49:38.352                     207                        7
2022-02-28 08:49:39.352                     207                        7
2022-02-28 08:49:40.352                     224                        7
2022-02-28 08:49:41.352                     224                        7
2022-02-28 08:49:42.352                     258                        7
2022-02-28 08:49:43.352                     258                        7
2022-02-28 08:49:44.352                      54                       19
2022-02-28 08:49:45.352                      54                       19
2022-02-28 08:49:46.362                      54                       19
2022-02-28 08:49:47.362                      54                       19
....

...
--//监测会话sid = 54,38,88,71,123,156,173,139,190,207,224,258对应的ITL槽. 最后是258.
--//^54$|^38$|^88$|^71$|^123$|^156$|^173$|^139$|^190$|^207$|^224$|^258$

$ awk '/ITL/{print $2}' /tmp/itl.txt | egrep  -n "^54$|^38$|^88$|^71$|^123$|^156$|^173$|^139$|^190$|^207$|^224$|^258$"
26:54
27:38
28:88
29:71
30:123
31:156
32:173
33:139
34:190
35:207
36:224
37:258
--//选择其中1段ITL槽,不知道算法。

--//这样http://antognini.ch/2011/04/itl-waits-changes-in-recent-releases/提供的伪码还是正确的,只不过itl.FIRST..itl.LAST
--//最多选择12个ITL槽.

iteration = 0
LOOP
  iteration++
  FOR i IN itl.FIRST..itl.LAST
  LOOP
    EXIT WHEN itl(i) IS FREE
    IF i <> itl.LAST THEN
        WAIT ON itl(i) FOR min(power(2,iteration-1),5) SECONDS
    ELSIF iteration <= 10 THEN
        WAIT ON itl(i) FOR power(2,iteration-1) SECONDS
    ELSE
        WAIT ON itl(i) FOREVER
    END IF
  END LOOP
  EXIT WHEN free_itl_found
END LOOP

--//按照这个计算,迭代10次需要
--//12*1+12*2+12*4 = 84
--//11*5*7 = 385
--//8+16+32+64+128+256+512 = 1016
--//84+385+1016 = 1485
--//需要1485秒,也就是经过1485/60 = 24.75分钟,在最后1个ITL槽上无限等待它的释放.
--//经过1485+1024 = 2509 秒基本可以缺点算法。

--//附上wcy.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

标签:02,ITL,20220228,TX,08,28,enq
来源: https://www.cnblogs.com/lfree/p/15944529.html