[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