[20231026]enq TX - allocate ITL entry的測試4.txt

lfree發表於2023-11-01

[20231026]enq TX - allocate ITL entry的測試4.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條記錄.

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 $(echo &&1/5 | bc -l ),保證執行按照自己定義的順序插入資料,這樣可以按照順序使用ITL槽。
--//整個測試需要至少3000+34秒,需要足夠的耐心。

$ cat itl_test.sh
#! /bin/bash
# test enq TX - allocate ITL entry
zzdate | tee /tmp/itl.txt
zzdate | tee /tmp/itl_trace.txt

# 169/5 = 33.8秒後,保證全部回話執行itl_3.txt的指令碼執行到select * from t where x = &&1 for update ;
seq 169 | xargs -IQ echo "sqlplus -s -l scott/book @itl_3.txt Q &" | bash | tee -a /tmp/itl.txt > /dev/null  &
echo sleep 35
sleep 35
# sleep 35,保證前面的全部回話執行itl_3.txt的指令碼執行到select * from t where x = &&1 for update ;
sqlplus -s -l scott/book <<EOF  | tee -a /tmp/itl_trace.txt
@ spid
@ t
@ 10046on 8
select x from t where x =170 for update ;
@ xid
commit;
@10046off
EOF

zzdate | tee -a /tmp/itl.txt
zzdate | tee -a /tmp/itl_trace.txt

3.測試:
 $ source itl_test.sh
trunc(sysdate)+09/24+39/1440+23/86400 == 2023/11/01 09:39:23 == timestamp'2023-11-01 09:39:23'
trunc(sysdate)+09/24+39/1440+23/86400 == 2023/11/01 09:39:23 == timestamp'2023-11-01 09:39:23'
sleep 35
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        91         55 25087                    DEDICATED 25089      197          5 alter system kill session '91,55' immediate;

TRACEFILE
----------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/book/book/trace/book_ora_25089.trc
Session altered.

   X
----
 170

XIDUSN_XIDSLOT_XIDSQN
------------------------------
45.3.7
--//45 = 0x002d

Commit complete.
Session altered.

trunc(sysdate)+10/24+29/1440+31/86400 == 2023/11/01 10:29:31 == timestamp'2023-11-01 10:29:31'
trunc(sysdate)+10/24+29/1440+31/86400 == 2023/11/01 10:29:31 == timestamp'2023-11-01 10:29:31'

--//總共監測 (21+29)*60+31-23 = 3008秒.

4.分析:
$ grep "^WAIT.*TX" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_25089.trc | head -24
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000407 name|mode=1415053316 usn<<16 | slot=7929870 sequence=6 obj#=90609 tim=1698802799316318
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000918 name|mode=1415053316 usn<<16 | slot=393246 sequence=1961 obj#=90609 tim=1698802800317339
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000900 name|mode=1415053316 usn<<16 | slot=7798795 sequence=7 obj#=90609 tim=1698802801318328
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000901 name|mode=1415053316 usn<<16 | slot=7995413 sequence=6 obj#=90609 tim=1698802802319338
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000927 name|mode=1415053316 usn<<16 | slot=10223627 sequence=6 obj#=90609 tim=1698802803320356
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000873 name|mode=1415053316 usn<<16 | slot=720922 sequence=8 obj#=90609 tim=1698802804321325
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000887 name|mode=1415053316 usn<<16 | slot=1900561 sequence=6 obj#=90609 tim=1698802805322315
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000928 name|mode=1415053316 usn<<16 | slot=8650762 sequence=6 obj#=90609 tim=1698802806323334
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000887 name|mode=1415053316 usn<<16 | slot=9830430 sequence=6 obj#=90609 tim=1698802807324312
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000929 name|mode=1415053316 usn<<16 | slot=4587521 sequence=6 obj#=90609 tim=1698802808325329
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000891 name|mode=1415053316 usn<<16 | slot=8978450 sequence=6 obj#=90609 tim=1698802809326329
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000886 name|mode=1415053316 usn<<16 | slot=9175053 sequence=7 obj#=90609 tim=1698802810327358
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000840 name|mode=1415053316 usn<<16 | slot=7929870 sequence=6 obj#=90609 tim=1698802812328346
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000871 name|mode=1415053316 usn<<16 | slot=393246 sequence=1961 obj#=90609 tim=1698802814329340
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000893 name|mode=1415053316 usn<<16 | slot=7798795 sequence=7 obj#=90609 tim=1698802816330325
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000870 name|mode=1415053316 usn<<16 | slot=7995413 sequence=6 obj#=90609 tim=1698802818331333
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000915 name|mode=1415053316 usn<<16 | slot=10223627 sequence=6 obj#=90609 tim=1698802820332338
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000866 name|mode=1415053316 usn<<16 | slot=720922 sequence=8 obj#=90609 tim=1698802822333335
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000880 name|mode=1415053316 usn<<16 | slot=1900561 sequence=6 obj#=90609 tim=1698802824334317
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000924 name|mode=1415053316 usn<<16 | slot=8650762 sequence=6 obj#=90609 tim=1698802826335354
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000916 name|mode=1415053316 usn<<16 | slot=9830430 sequence=6 obj#=90609 tim=1698802828336371
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000882 name|mode=1415053316 usn<<16 | slot=4587521 sequence=6 obj#=90609 tim=1698802830337350
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000849 name|mode=1415053316 usn<<16 | slot=8978450 sequence=6 obj#=90609 tim=1698802832338333
WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 2000932 name|mode=1415053316 usn<<16 | slot=9175053 sequence=7 obj#=90609 tim=1698802834339354
--//12槽為一組.
--//9175053 = /2^16  %2^16 (Type | Mode) = 140,13 = 0x8c000d

$ grep "^WAIT.*TX" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_25089.trc | awk '{print $10}'| paste -d" " $(seq 12 | xargs -IQ echo -n '- ')| nl
     1  1000407 1000918 1000900 1000901 1000927 1000873 1000887 1000928 1000887 1000929 1000891 1000886
     2  2000840 2000871 2000893 2000870 2000915 2000866 2000880 2000924 2000916 2000882 2000849 2000932
     3  4001884 4001875 4001872 4001900 4001865 4001919 4002212 4001491 4001936 4001829 4001924 4001915
     4  5001806 5001468 5001826 5001736 5001620 5001112 5001547 5002083 5001348 5002039 5001970 8002990
     5  5001867 5001801 5001269 5001847 5001460 5001975 5001386 5001465 5001977 5001714 5001539 16005303
     6  5001826 5001967 5001567 5001507 5001982 5001929 5001495 5001237 5001301 5002015 5001135 32010213
     7  5001894 5001902 5001864 5001975 5001976 5001123 5001649 5001535 5001341 5001872 5001274 64001768
     8  5001932 5001610 5002056 5001540 5001098 5001564 5001232 5001658 5002011 5001905 5001477 128002522
     9  5001835 5001984 5001898 5001394 5001308 5001787 5001488 5001185 5001334 5001643 5001776 256005557
    10  5001782 5002029 5001286 5001470 5001506 5001608 5001279 5001257 5001456 5001717 5001950 512010920
    11  5001683 5001591 5001846 5002061 5001197 5001463 5001404 5001496 5001972 5001636 5001700 1430211940

--//取出ela= NNNN數值。
--//最大12個ITL槽為1組,開始1秒,然後2秒,然後4秒,然後5秒,最後1個ITL等待秒數是 2^(迭代次數-1).再然後都是5秒,最後1個ITL等待秒數
--//總是 2^(迭代次數-1),在迭代10次以後,第11次迭代,其它ITL等待5秒,最後1個ITL槽無限等待下去.

$ grep "^WAIT.*TX" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_25089.trc | awk '{print $10}'|paste -sd'+' | bc | xargs -IQ echo Q/1000000 | bc -l
2970.43913200000000000000

--//最早出現:
--//WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000407 name|mode=1415053316 usn<<16 | slot=7929870 sequence=6 obj#=90609 tim=1698802799316318
--//tim=1698802799316318

$ xdate 1698802799316318/1000000 1
2023-11-01 09:39:59.316318000

--//trunc(sysdate)+10/24+29/1440+31/86400 == 2023/11/01 10:29:31 == timestamp'2023-11-01 10:29:31'
--//從出現enq: TX - allocate ITL entry到結束測試的時間間隔
--//(21+29)*60+31-59 = 2972,還給加上1秒. 實際上是2973秒.

--//換一個思路,在3000秒sleep裡面,扣除(169-39)/5,以及35-169/5 = 1.2秒。
--//3000-(169-39)/5 -(35-169/5) = 2972.8,有將近2.4秒的誤差,應該在其它方面的消耗,在正常範圍。

--//trunc(sysdate)+09/24+39/1440+23/86400 == 2023/11/01 09:39:23 == timestamp'2023-11-01 09:39:23'
--//trunc(sysdate)+10/24+29/1440+31/86400 == 2023/11/01 10:29:31 == timestamp'2023-11-01 10:29:31'

--//總共監測 (21+29)*60+31-23 = 3008秒。實際上等待ITL39回話的事務完成,釋放對應ITL槽。
--//3000+35-(169-39)/5 = 3009秒,非常接近。

--//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
*****************

SCOTT@book> @wcy trunc(sysdate)+09/24+39/1440+23/86400 trunc(sysdate)+10/24+29/1440+31/86400  "event='enq: TX - allocate ITL entry'"
-- Display ASH Wait Chain Signatures script v0.7 by Tanel Poder ( http://blog.tanelpoder.com )
%This     SECONDS        AAS WAIT_CHAIN                                                                      FIRST_SEEN          LAST_SEEN
------ ---------- ---------- ------------------------------------------------------------------------------- ------------------- -------------------
  83%        2450         .8 -> 302,53,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,302,53] 2023-11-01 09:40:10 2023-11-01 10:29:30
   2%          47          0 -> 141,53,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,141,53] 2023-11-01 09:40:02 2023-11-01 10:05:05
   2%          47          0 -> 57,75,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,57,75]   2023-11-01 09:40:05 2023-11-01 10:05:20
   2%          47          0 -> 364,69,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,364,69] 2023-11-01 09:40:09 2023-11-01 10:05:40
   2%          47          0 -> 246,49,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,246,49] 2023-11-01 09:40:01 2023-11-01 10:05:00
   2%          47          0 -> 85,177,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,85,177] 2023-11-01 09:40:00 2023-11-01 10:04:55
   2%          47          0 -> 199,75,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,199,75] 2023-11-01 09:40:04 2023-11-01 10:05:15
   2%          47          0 -> 117,49,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,117,49] 2023-11-01 09:39:59 2023-11-01 10:04:50
   2%          47          0 -> 160,39,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,160,39] 2023-11-01 09:40:07 2023-11-01 10:05:30
   2%          47          0 -> 178,55,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,178,55] 2023-11-01 09:40:03 2023-11-01 10:05:10
   2%          46          0 -> 282,59,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,282,59] 2023-11-01 09:40:08 2023-11-01 10:05:35
   2%          46          0 -> 230,61,@1=>91,55,@1=>enq: TX - allocate ITL entry -> [idle blocker 1,230,61] 2023-11-01 09:40:06 2023-11-01 10:05:25
12 rows selected.
--//前面11個槽47秒,很容易驗證 1+2+4+5*8 = 47.
--//阻塞會話的sid是 302 141 57 364 246 85 199 117 160 178 282 230 .

$ awk '/ITL/{print }' /tmp/itl.txt | head | nl
     1  ITL1         38         55 23731                    DEDICATED 23764
     2  ITL2        167         45 23733                    DEDICATED 23765
     3  ITL3        218         71 23734                    DEDICATED 23768
     4  ITL4         56         67 23737                    DEDICATED 23771
     5  ITL5        180         33 23739                    DEDICATED 23774
     6  ITL6         78         57 23740                    DEDICATED 23777
     7  ITL7        244         63 23743                    DEDICATED 23785
     8  ITL8        235         33 23744                    DEDICATED 23784
     9  ITL9        111         85 23747                    DEDICATED 23780
    10  ITL10        145         47 23749                    DEDICATED 23786
--//我按照順序執行的,ITL1的sid=38等於插入1的會話.

$ awk '/ITL/{print $2,$1}' /tmp/itl.txt | egrep  -n "^302 |^141 |^57 |^364 |^246 |^85 |^199 |^117 |^160 |^178 |^282 |^230 "
28:117 ITL28
29:85 ITL29
30:246 ITL30
31:141 ITL31
32:178 ITL32
33:199 ITL33
34:57 ITL34
35:230 ITL35
36:160 ITL36
37:282 ITL37
38:364 ITL38
39:302 ITL39
--//前面都能對上.如果你結合前面前面@wcy的輸出,可以推斷使用ITL槽從小到大看看那個槽沒有事務就是使用它.
--//將@wcy的輸出儲存為/tmp/itl3.txt
--//28 = 0x1c 7929870 = /2^16  %2^16 (Type | Mode) = 121,14 = 0x79000e
--//39 = 0x27

$ grep TX /tmp/itl3.txt | sort -k16 | awk '{print $5}' | sed 's/,.*$//'
117
85
246
141
178
199
57
230
160
282
364
302
--//前面說明sort -k16按照FIRST_SEEN的時分秒排序,然後awk '{print $5}'取出阻塞的會話部分,sed 's/,.*$//'刪除後面多餘的部分從,開始.
--//順序完全跟前面的對上.
--//我不知道出現阻塞時,隨機選取1段ITL槽嘗試還是別的,感覺是隨機選擇.最大選擇12個ITL槽,然後輪詢探查.

5.轉儲資料塊看看:

SCOTT@book> select rowid,x from t where rownum=1;
ROWID                         X
------------------ ------------
AAAWHxAAEAAAAIkAAA            1

SCOTT@book> @ rowid AAAWHxAAEAAAAIkAAA
    OBJECT       FILE      BLOCK        ROW ROWID_DBA            DBA                  TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
     90609          4        548          0  0x1000224           4,548                alter system dump datafile 4 block 548 ;

SCOTT@book> alter system dump datafile 4 block 548 ;
System altered.

Block header dump:  0x01000224
 Object id on Block? Y
 seg/obj: 0x161f1  csc: 0x03.1773e952  itc: 169  flg: E  typ: 1 - DATA
     brn: 0  bdba: 0x1000220 ver: 0x01 opc: 0
     inc: 0  exflg: 0
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0031.013.00000006  0x00c007d5.000a.06  C---    0  scn 0x0003.1773e2d5
0x02   0x002d.003.00000007  0x00c00a56.000c.08  C---    0  scn 0x0003.1773e0c7
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
0x03   0x0099.011.00000006  0x00c01114.0002.0b  ----    1  fsc 0x0000.00000000
0x04   0x0072.007.00000006  0x00c00eac.0001.09  C---    0  scn 0x0003.1773e02b.
...
0x1c   0x0087.01b.00000005  0x00c00ffd.0001.08  C---    0  scn 0x0003.1773e08d
------------
0x1d   0x0079.00e.00000006  0x00c00f1e.0001.06  C---    0  scn 0x0003.1773e091   --//slot=7929870 = /2^16  %2^16 = 121,14 = 0x79000e
0x1e   0x0006.01e.000007a9  0x00c005e6.036e.07  C---    0  scn 0x0003.1773e095   --//slot=393246  = /2^16  %2^16 = 6,30 = 0x6001e
0x1f   0x0077.00b.00000007  0x00c006c3.0009.03  C---    0  scn 0x0003.1773e099   --//slot=7798795 = /2^16  %2^16 = 119,11 = 0x77000b
0x20   0x007a.015.00000006  0x00c0066f.0003.04  C---    0  scn 0x0003.1773e09e   --//slot=7995413 = /2^16  %2^16 = 122,21 = 0x7a0015
0x21   0x009c.00b.00000006  0x00c01142.000b.02  C---    0  scn 0x0003.1773e0a2   --//slot=10223627= /2^16  %2^16 = 156,11 = 0x9c000b
0x22   0x000b.01a.00000008  0x00c00735.000e.04  C---    0  scn 0x0003.1773e0a6   --//slot=720922  = /2^16  %2^16 = 11,26 = 0xb001a
0x23   0x001d.011.00000006  0x00c00952.0002.09  C---    0  scn 0x0003.1773e0aa   --//slot=1900561 = /2^16  %2^16 = 29,17 = 0x1d0011
0x24   0x0084.00a.00000006  0x00c01099.0008.0b  C---    0  scn 0x0003.1773e0ae   --//slot=8650762 = /2^16  %2^16 = 132,10 = 0x84000a
0x25   0x0096.01e.00000006  0x00c010e6.0007.04  C---    0  scn 0x0003.1773e0b2   --//slot=9830430 = /2^16  %2^16 = 150,30 = 0x96001e
0x26   0x0046.001.00000006  0x00c00be1.0002.09  C---    0  scn 0x0003.1773e0b6   --//slot=4587521 = /2^16  %2^16 = 70,1 = 0x460001
0x27   0x0089.012.00000006  0x00c01012.0006.03  C---    0  scn 0x0003.1773e0ba   --//slot=8978450 = /2^16  %2^16 = 137,18 = 0x890012
0x28   0x008c.00d.00000007  0x00c0104c.000d.08  C---    0  scn 0x0003.1773e0bf   --//slot=9175053 = /2^16  %2^16 = 140,13 = 0x8c000d
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
----//使用以上12個ITL槽
0x29   0x00a0.01e.00000005  0x00c00478.0003.04  C---    0  scn 0x0003.1773e0c3
0x2a   0x0017.01d.00000006  0x00c006f1.0005.04  C---    0  scn 0x0003.1773e0cb
0x2b   0x000a.017.00005437  0x00c002a7.0f90.16  C---    0  scn 0x0003.1773e0cf
...
0xa8   0x002e.00e.00000006  0x00c004c2.0004.0e  C---    0  scn 0x0003.1773e2cd
0xa9   0x006f.00f.00000006  0x00c0043e.0002.0a  C---    0  scn 0x0003.1773e2d1
bdba: 0x01000224
data_block_dump,data header at 0x7f4ccac5ca0c
===============
tsiz: 0xff0
hsiz: 0x168
pbl: 0x7f4ccac5ca0c
     76543210
flag=--------
ntab=1
nrow=171
frre=-1
fsbo=0x168
fseo=0x44e
avsp=0x2e6
tosp=0x2e6
0xe:pti[0]    nrow=171    offs=0
0x12:pri[0]    offs=0x44e
0x14:pri[1]    offs=0x45f
...
0x166:pri[170]    offs=0xfde
block_row_dump:
tab 0, row 0, @0x44e
tl: 17 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 02
col  1: [10]  2a 2a 2a 2a 2a 2a 2a 2a 2a 2a
tab 0, row 1, @0x45f
tl: 17 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 03
col  1: [10]  2a 2a 2a 2a 2a 2a 2a 2a 2a 2a
tab 0, row 2, @0x470
tl: 17 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 04
col  1: [10]  2a 2a 2a 2a 2a 2a 2a 2a 2a 2a
tab 0, row 3, @0x481
...
tl: 18 fb: --H-FL-- lb: 0x3  cc: 2
col  0: [ 3]  c2 02 47
col  1: [10]  2a 2a 2a 2a 2a 2a 2a 2a 2a 2a
tab 0, row 170, @0xfde
tl: 18 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 3]  c2 02 48
col  1: [10]  2a 2a 2a 2a 2a 2a 2a 2a 2a 2a
end_of_block_dump
End dump data blocks tsn: 4 file#: 4 minblk 548 maxblk 548

--//注意看下劃線最後事務使用該ITL槽完成插入.
--//WAIT #140430939097200: nam='enq: TX - allocate ITL entry' ela= 1000886 name|mode=1415053316 usn<<16 | slot=9175053 sequence=7 obj#=90609 tim=1698802810327358
--//9175053 = /2^16  %2^16 (Type | Mode) = 140,13 = 0x8c000d
--//0x28 = 40,使用40 ITL槽,我前面ITL39,因為前面的insert已經使用itl 0x01槽(可以看前面Scn/Fsc列確定,當前是最大scn,說明已
--//經覆蓋)

--//還有一個細節,雖然是等待itl=0x28的事務結束釋放,但是實際上該事務使用的ITL槽是0x02。
0x02   0x002d.003.00000007  0x00c00a56.000c.08  C---    0  scn 0x0003.1773e0c7
--//你可以從前面@xid的輸出確定。
XIDUSN_XIDSLOT_XIDSQN
------------------------------
45.3.7
--//45 = 0x002d
--//也就是oracle在等待itl=0x28事務槽釋放後,還是選擇沒有使用的scn最小的事務槽,使用它。

$ awk '/ITL/{print $2,$1}' /tmp/itl.txt | egrep  -n "^302 |^141 |^57 |^364 |^246 |^85 |^199 |^117 |^160 |^178 |^282 |^230 "| tail -1
39:302 ITL39

--//透過bbed觀察:
BBED> set dba  4,548
        DBA             0x01000224 (16777764 4,548)

BBED> map
 File: /mnt/ramdisk/book/users01.dbf (4)
 Block: 548                                   Dba:0x01000224
------------------------------------------------------------
 KTB Data Block (Table/Cluster)
 struct kcbh, 20 bytes                      @0
 struct ktbbh, 4080 bytes                   @20
 struct kdbh, 14 bytes                      @4108
 struct kdbt[1], 4 bytes                    @4122
 sb2 kdbr[171]                              @4126
 ub1 freespace[742]                         @4468
 ub1 rowdata[2978]                          @5210
 ub4 tailchk                                @8188

6.總結:
--//我重複一年前的測試,主要遇到一些不理解問題,實際上它並沒有使用等待的itl槽,而是最後等待它釋放後,
--//選擇沒有使用的scn最小的事務槽.

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

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2992410/,如需轉載,請註明出處,否則將追究法律責任。

相關文章