January 24, 2011
It happened again, another blog article that forced me to stop, think, and … hey, why did Oracle Database 11.2.0.2 do something different than Oracle Database 10.2.0.5? What is different, even when the OPTIMIZER_FEATURES_ENABLE parameter is set to 10.2.0.4 (or 10.2.0.5)? The number of consistent gets for a SQL statement is significantly different – we did see a similar difference between release version before, but for a different reason. We need the help of Oracle Database trace event 10200 to determine why there is a difference. Once we have the trace file, we need an easy way to process the trace file.
Excel Macro that will work with a trace file produced by Oracle Database running on Windows (also works in Microsoft Visual Basic 6.0 and earlier; for an Oracle Database running on Unix/Linux, open the trace file with Wordpad first, and then save the trace file using Wordpad):
(Replace c:\or10s_ora_4256_watch_consistent.trc with the actual name of the generated trace file – the script as written seems to work with 10.2.0.x and 11.2.0.x)
Private Sub Read_10200_Trace1() Dim intFileNum As Integer '10200 trace file Dim intFileNum2 As Integer 'Output file Dim strInput As String 'Line read from the 10200 trace file Dim strOutput As String 'Line to be written to the output file Dim strBlock(2000) As String 'Block read from the trace file Dim strBlockCounter(2000) As Integer 'Number of times read Dim intBlocks As Integer 'Total number of blocks Dim i As Integer 'Loop counter Dim intFound As Integer 'Indicates whether or not the block was found intFileNum = FreeFile Open "c:\or10s_ora_4256_watch_consistent.trc" For Input As #intFileNum intFileNum2 = FreeFile Open "c:\watch_consistent.txt" For Output As #intFileNum2 Do While Not EOF(intFileNum) Line Input #intFileNum, strInput If InStr(strInput, "started for block") > 0 Then strOutput = Trim(Right(strInput, Len(strInput) - InStr(InStr(strInput, "started for block"), strInput, ":"))) 'Find the number of times the block was accessed intFound = 0 For i = 1 To intBlocks If strOutput = strBlock(i) Then intFound = i strBlockCounter(i) = strBlockCounter(i) + 1 Exit For End If Next i 'If the block was not found, record it If intFound = 0 Then intBlocks = intBlocks + 1 intFound = intBlocks strBlockCounter(intBlocks) = 1 strBlock(intBlocks) = strOutput End If Print #intFileNum2, strOutput; vbTab; strBlockCounter(intFound) End If Loop Print #intFileNum2, "" For i = 1 To intBlocks Print #intFileNum2, strBlock(i); vbTab; strBlockCounter(i) Next i Close #intFileNum Close #intFileNum2 End Sub
Excel Macro equivalent that will work with a trace file produced by Oracle Database running on Windows/Unix/Linux (also works in Microsoft Visual Basic 6.0 and earlier):
(Replace c:\or10s_ora_4256_watch_consistent.trc with the actual name of the generated trace file)
Private Sub Read_10200_Trace2() Dim strInput As String 'Line read from the 10200 trace file Dim strOutput As String 'Line to be written to the output file Dim strBlock(2000) As String 'Block read from the trace file Dim strBlockCounter(2000) As Integer 'Number of times read Dim intBlocks As Integer 'Total number of blocks Dim i As Integer 'Loop counter Dim intFound As Integer 'Indicates whether or not the block was found Dim objFSO As Object 'FileSystemObjects Dim objFile1 As Object 'The FileSystemObjects handle to the raw 10020 trace file Dim objFile2 As Object 'The FileSystemObjects handle to the output file Const ForReading = 1 Const ForWriting = 2 Set objFSO = CreateObject("Scripting.FileSystemObject") Set objFile1 = objFSO.OpenTextFile("c:\or10s_ora_4256_watch_consistent.trc", ForReading) Set objFile2 = objFSO.CreateTextFile("c:\watch_consistent.txt", True) Do While Not (objFile1.AtEndOfStream) strInput = objFile1.ReadLine If InStr(strInput, "started for block") > 0 Then strOutput = Trim(Right(strInput, Len(strInput) - InStr(InStr(strInput, "started for block"), strInput, ":"))) 'Find the number of times the block was accessed intFound = 0 For i = 1 To intBlocks If strOutput = strBlock(i) Then intFound = i strBlockCounter(i) = strBlockCounter(i) + 1 Exit For End If Next i 'If the block was not found, record it If intFound = 0 Then intBlocks = intBlocks + 1 intFound = intBlocks strBlockCounter(intBlocks) = 1 strBlock(intBlocks) = strOutput End If objFile2.Write strOutput & vbTab & strBlockCounter(intFound) & vbCrLf End If Loop objFile2.Write "" & vbCrLf For i = 1 To intBlocks objFile2.Write strBlock(i) & vbTab & strBlockCounter(i) & vbCrLf Next i objFile1.Close objFile2.Close End Sub
VBS Script Equivalent that will work with a trace file produced by Oracle Database running on Windows/Unix/Linux (also works in Excel and Microsoft Visual Basic 6.0 and earlier):
(Replace c:\or10s_ora_4256_watch_consistent.trc with the actual name of the generated trace file)
Dim strInput 'Line read from the 10200 trace file Dim strOutput 'Line to be written to the output file Dim strBlock(2000) 'Block read from the trace file Dim strBlockCounter(2000) 'Number of times read Dim intBlocks 'Total number of blocks Dim i 'Loop counter Dim intFound 'Indicates whether or not the block was found Dim objFSO 'FileSystemObjects Dim objFile1 'The FileSystemObjects handle to the raw 10020 trace file Dim objFile2 'The FileSystemObjects handle to the output file Const ForReading = 1 Set objFSO = CreateObject("Scripting.FileSystemObject") Set objFile1 = objFSO.OpenTextFile("c:\or10s_ora_4256_watch_consistent.trc", ForReading) Set objFile2 = objFSO.CreateTextFile("c:\watch_consistent.txt", True) Do While Not (objFile1.AtEndOfStream) strInput = objFile1.ReadLine If InStr(strInput, "started for block") > 0 Then strOutput = Trim(Right(strInput, Len(strInput) - InStr(InStr(strInput, "started for block"), strInput, ":"))) 'Find the number of times the block was accessed intFound = 0 For i = 1 To intBlocks If strOutput = strBlock(i) Then intFound = i strBlockCounter(i) = strBlockCounter(i) + 1 Exit For End If Next 'If the block was not found, record it If intFound = 0 Then intBlocks = intBlocks + 1 intFound = intBlocks strBlockCounter(intBlocks) = 1 strBlock(intBlocks) = strOutput End If objFile2.Write strOutput & vbTab & strBlockCounter(intFound) & vbCrLf End If Loop objFile2.Write "" & vbCrLf For i = 1 To intBlocks objFile2.Write strBlock(i) & vbTab & strBlockCounter(i) & vbCrLf Next objFile1.Close objFile2.Close
—-
OK, now that we have the solution, we need an appropriate problem that must be solved with our solution. The script below creates two test tables, each with a unique index on the ID column:
CREATE TABLE T1 AS SELECT ROWNUM ID, TRUNC(DBMS_RANDOM.VALUE(1,300000)) N1, LPAD(ROWNUM,10,'0') SMALL_VC, RPAD('X',100) PADDING FROM DUAL CONNECT BY LEVEL <= 300000; CREATE TABLE T2 AS SELECT ROWNUM ID, TRUNC(DBMS_RANDOM.VALUE(1,300000)) N1, LPAD(ROWNUM,10,'0') SMALL_VC, RPAD('X',100) PADDING FROM DUAL CONNECT BY LEVEL <= 300000; CREATE UNIQUE INDEX PAR_I1 ON T1(ID); CREATE UNIQUE INDEX CHI_I1 ON T2(ID); EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE) EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)
Now for the test SQL statement (hinted to help force a specific execution plan):
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='10.2.0.4'; SELECT /*+ GATHER_PLAN_STATISTICS LEADING(T1) USE_NL(T2) INDEX(T1) INDEX(T2) */ T1.ID, T1.N1, T2.ID, T2.N1 FROM T1, T2 WHERE T1.ID=T2.ID AND T1.ID BETWEEN 1 AND 200 AND T2.N1 = 0; SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST -ROWS -PREDICATE'));
The execution plan that is output looks like this:
SQL_ID 1afa5ym56cagh, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS LEADING(T1) USE_NL(T2) INDEX(T1) INDEX(T2) */ T1.ID, T1.N1, T2.ID, T2.N1 FROM T1, T2 WHERE T1.ID=T2.ID AND T1.ID BETWEEN 1 AND 200 AND T2.N1 = 0 Plan hash value: 3072046012 ---------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | ---------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 0 |00:00:00.03 | 408 | | 1 | NESTED LOOPS | | 1 | 0 |00:00:00.03 | 408 | | 2 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 200 |00:00:00.01 | 6 | | 3 | INDEX RANGE SCAN | PAR_I1 | 1 | 200 |00:00:00.01 | 2 | | 4 | TABLE ACCESS BY INDEX ROWID| T2 | 200 | 0 |00:00:00.02 | 402 | | 5 | INDEX UNIQUE SCAN | CHI_I1 | 200 | 200 |00:00:00.01 | 202 | ----------------------------------------------------------------------------------------
In the above, there were 2 consistent gets for the PAR_I1 index, 4 consistent gets for the T1 table, 202 consistent gets for the CHI_I1 index, and 200 consistent gets for the T2 table. While it might not be obvious from the above, the BLEVEL for both indexes is 1 (HEIGHT = 2 – see the quiz article linked to at the start of this article for an explanation). When I first saw the quiz that is linked to at the start of this article, I mentally assumed that there would be about 400 consistent gets for the CHI_I1 index – for every Start of the INDEX UNIQUE SCAN operation, I expected the index root block and the index leaf block to count as a consistent get, while the above showed that did not happen. Let’s trace the consistent gets to see why there were only 202 consistent gets and not roughly 400:
ALTER SESSION SET TRACEFILE_IDENTIFIER='WATCH_CONSISTENT'; ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1'; SELECT /*+ GATHER_PLAN_STATISTICS LEADING(T1) USE_NL(T2) INDEX(T1) INDEX(T2) */ T1.ID, T1.N1, T2.ID, T2.N1 FROM T1, T2 WHERE T1.ID=T2.ID AND T1.ID BETWEEN 1 AND 200 AND T2.N1 = 0;
If we then process the resulting 10200 trace file through one of the above trace file parsers, we might see output like what is listed below (the RDBA in hex is listed first, followed by the number of times that block had been accessed by a consistent get to that point in the trace file):
0206e214 1 0206e215 1 01c0000c 1 01c72e14 1 01c72e15 1 01c003ec 1 01c72e14 2 01c72e15 2 01c003ec 2 01c72e15 3 01c003ec 3 01c72e15 4 01c003ec 4 ... 01c72e15 56 01c003ec 56 01c72e15 57 01c003ec 57 01c0000d 1 01c72e15 58 01c003ed 1 01c72e15 59 01c003ed 2 01c72e15 60 01c003ed 3 01c72e15 61 ... 01c72e15 113 01c003ed 56 01c72e15 114 01c003ed 57 01c0000e 1 01c72e15 115 01c003ee 1 01c72e15 116 01c003ee 2 01c72e15 117 ... 01c72e15 170 01c003ee 56 01c72e15 171 01c003ee 57 01c0000f 1 01c72e15 172 01c003ef 1 01c72e15 173 01c003ef 2 01c72e15 174 01c003ef 3 ... 01c72d95 199 01c003ef 28 01c72d95 200 01c003ef 29 01c72e15 199 01c003ef 28 01c72e15 200 01c003ef 29 0206e214 1 0206e215 1 01c0000c 1 01c72e14 2 01c72e15 200 01c003ec 57 01c0000d 1 01c003ed 57 01c0000e 1 01c003ee 57 01c0000f 1 01c003ef 29
At the bottom of the output is a summary that shows (in order) RDBA 0206e214 was accessed a total of 1 time, RDBA 0206e215 was accessed 1 time, RDBA 01c0000c was accessed 1 time, RDBA 01c72e14 was accessed 2 times, RDBA 01c72e15 was accessed 200 times, etc. Nice, but what do those RDBA numbers represent? We will get to that later.
Inside the raw 10200 trace file we might see something like this (I am able to identifysome items that appear in the raw trace file, but I do not yet fully understand the file):
... *** SESSION ID:(146.18) 2011-01-23 14:36:18.700 Consistent read started for block 9 : 0206e214 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 9sch: scn: 0x0000.00000000) CR exa ret 2 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 206e214 Consistent read started for block 9 : 0206e215 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 9 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 206e215 Consistent read finished for block 9 : 206e215 Consistent read started for block 9 : 01c0000c env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 9 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c0000c Consistent read finished for block 9 : 1c0000c Consistent read started for block 9 : 01c72e14 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 2 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c72e14 Consistent read started for block 9 : 01c72e15 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 2 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c72e15 Consistent read started for block 9 : 01c003ec env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 2 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c003ec Consistent read started for block 9 : 01c72e14 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 9 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c72e14 Consistent read finished for block 9 : 1c72e14 Consistent read started for block 9 : 01c72e15 env: (scn: 0x0000.00135bfd xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: xid: 0x0000.000.00000000 scn: 0x0000.00000000 10sch: scn: 0x0000.00135bfd) CR exa ret 2 on: 0000000004B99F38 scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 scn: 0xffff.ffffffff sfl: 0 Consistent read finished for block 9 : 1c72e15 ...
Now that we see the RDBA numbers again, I suppose that it is time to try to determine the objects that are referenced by the RDBA numbers. We can try dumping the index structure to see which blocks are read, but first need to find the OBJECT_IDs for the two indexes:
SELECT OBJECT_NAME, OBJECT_ID FROM DBA_OBJECTS WHERE OBJECT_NAME IN ('PAR_I1','CHI_I1'); OBJECT_NAME OBJECT_ID ----------- ---------- CHI_I1 48143 PAR_I1 48142
With the OBJECT_IDs we are able to write the index structures to a trace file:
ALTER SESSION SET TRACEFILE_IDENTIFIER='TREE_DUMP_CHI_I1'; ALTER SESSION SET EVENTS 'IMMEDIATE TRACE NAME TREEDUMP LEVEL 48143'; ALTER SESSION SET TRACEFILE_IDENTIFIER='TREE_DUMP_PAR_I1'; ALTER SESSION SET EVENTS 'IMMEDIATE TRACE NAME TREEDUMP LEVEL 48142';
Partial output from the TREE_DUMP_PAR_I1 trace file might look like the section that follows (items appearing in bold were identified in the trace file summary):
----- begin tree dump branch: 0x206e214 34005524 (0: nrow: 625, level: 1) leaf: 0x206e215 34005525 (-1: nrow: 520 rrow: 520) leaf: 0x206e216 34005526 (0: nrow: 513 rrow: 513) leaf: 0x206e217 34005527 (1: nrow: 513 rrow: 513) leaf: 0x206e218 34005528 (2: nrow: 513 rrow: 513) ... leaf: 0x206ee0e 34008590 (623: nrow: 435 rrow: 435) ----- end tree dump
In the above 0x206e214 is a branch block (actually the root block) and 0x206e215 is the first leaf block.
Partial output from the TREE_DUMP_CHI_I1 trace file might look like the section that follows (items appearing in bold were identified in the trace file summary):
----- begin tree dump branch: 0x1c72e14 29830676 (0: nrow: 625, level: 1) leaf: 0x1c72e15 29830677 (-1: nrow: 520 rrow: 520) leaf: 0x1c72e16 29830678 (0: nrow: 513 rrow: 513) leaf: 0x1c72e17 29830679 (1: nrow: 513 rrow: 513) leaf: 0x1c72e18 29830680 (2: nrow: 513 rrow: 513) ... leaf: 0x1c7308e 29831310 (623: nrow: 435 rrow: 435) ----- end tree dump
In the above, 0x1c72e14 is a branch block (actually the root block) and 0x1c72e15 is the first leaf block.
If we take another look at the summary, we are now able to update the summary with the index block information:
0206e214 1 /* PAR_I1 Root block of index on T1 */ 0206e215 1 /* PAR_I1 Leaf block of index on T1 */ 01c0000c 1 01c72e14 2 /* CHI_I1 Root block of index on T2 */ 01c72e15 200 /* CHI_I1 Leaf block of index on T2 */ 01c003ec 57 01c0000d 1 01c003ed 57 01c0000e 1 01c003ee 57 01c0000f 1 01c003ef 29
Let’s try to find the source of the rest of the blocks that were found in the summary (I guess that this could be the hard way to get the job done):
SELECT SEGMENT_NAME, HEADER_FILE, HEADER_BLOCK, BLOCKS, HEADER_BLOCK+BLOCKS-1 MAX_BLOCKS FROM DBA_SEGMENTS WHERE SEGMENT_NAME IN ('T1','T2'); SEGMENT_NAME HEADER_FILE HEADER_BLOCK BLOCKS MAX_BLOCKS ------------ ----------- ------------ ---------- ---------- T1 7 11 5504 5514 T2 7 1003 5504 6506
Taking the above HEADER_FILE, HEADER_BLOCK, and MAX_BLOCKS numbers and dumping the block contents to a trace file (this will work in this test case script because all of the extents for the table blocks are probably close to each other – looking back, it probably would have been a better idea to use DBA_EXTENTS rather than DBA_SEGMENTS and just dump the first extent for each object):
ALTER SESSION SET TRACEFILE_IDENTIFIER='TABLE_DUMP_T1'; ALTER SYSTEM DUMP DATAFILE 7 BLOCK MIN 11 BLOCK MAX 5514; ALTER SESSION SET TRACEFILE_IDENTIFIER='TABLE_DUMP_T2'; ALTER SYSTEM DUMP DATAFILE 7 BLOCK MIN 1003 BLOCK MAX 6506;
Partial output from the TABLE_DUMP_T1 trace file might look like the following (items appearing in bold were identified in the trace file summary):
Second Level Bitmap block DBAs -------------------------------------------------------- DBA 1: 0x01c0000a buffer tsn: 9 rdba: 0x01c0000c (7/12) scn: 0x0000.00135a07 seq: 0x02 flg: 0x04 tail: 0x5a070602 frmt: 0x02 chkval: 0x541c type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c0000d (7/13) scn: 0x0000.00135a07 seq: 0x02 flg: 0x04 tail: 0x5a070602 frmt: 0x02 chkval: 0x42da type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c0000e (7/14) scn: 0x0000.00135a07 seq: 0x02 flg: 0x04 tail: 0x5a070602 frmt: 0x02 chkval: 0x840f type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c0000f (7/15) scn: 0x0000.00135a07 seq: 0x02 flg: 0x04 tail: 0x5a070602 frmt: 0x02 chkval: 0x74ce type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ...
Partial output from the TABLE_DUMP_T1 TABLE_DUMP_T2 trace file might look like the following (items appearing in bold were identified in the trace file summary):
Second Level Bitmap block DBAs -------------------------------------------------------- DBA 1: 0x01c003ea buffer tsn: 9 rdba: 0x01c003ec (7/1004) scn: 0x0000.00135ac4 seq: 0x02 flg: 0x04 tail: 0x5ac40602 frmt: 0x02 chkval: 0x50a8 type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c003ed (7/1005) scn: 0x0000.00135ac4 seq: 0x02 flg: 0x04 tail: 0x5ac40602 frmt: 0x02 chkval: 0x2ef2 type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c003ee (7/1006) scn: 0x0000.00135ac4 seq: 0x02 flg: 0x04 tail: 0x5ac40602 frmt: 0x02 chkval: 0xbc00 type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c003ef (7/1007) scn: 0x0000.00135ac4 seq: 0x02 flg: 0x04 tail: 0x5ac40602 frmt: 0x02 chkval: 0x6c98 type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ... buffer tsn: 9 rdba: 0x01c003f0 (7/1008) scn: 0x0000.00135ac4 seq: 0x02 flg: 0x04 tail: 0x5ac40602 frmt: 0x02 chkval: 0xf228 type: 0x06=trans data Hex dump of block: st=0, typ_found=1 Dump of memory from 0x00000000080F4400 to 0x00000000080F6400 ...
Taking another look at the summary, now updated with the table blocks:
0206e214 1 /* PAR_I1 Root block of index on T1 */ 0206e215 1 /* PAR_I1 Leaf block of index on T1 */ 01c0000c 1 /* T1 Table block */ 01c72e14 2 /* CHI_I1 Root block of index on T2 */ 01c72e15 200 /* CHI_I1 Leaf block of index on T2 */ 01c003ec 57 /* T2 Table block */ 01c0000d 1 /* T1 Table block */ 01c003ed 57 /* T2 Table block */ 01c0000e 1 /* T1 Table block */ 01c003ee 57 /* T2 Table block */ 01c0000f 1 /* T1 Table block */ 01c003ef 29 /* T2 Table block */
Those datafile dumps can be quite time consuming, is there anything else we can try?
We could try to find the RDBA for the ten blocks (note that there is a risk here if the first extent is only eight blocks in length) in the first extent of each segment using the DBMS_UTILITY.MAKE_DATA_BLOCK_ADDRESS function (items appearing in bold were identified in the trace file summary):
SELECT SEGMENT_NAME, DBMS_UTILITY.MAKE_DATA_BLOCK_ADDRESS(HEADER_FILE,HEADER_BLOCK+RN) RDBA, TO_CHAR(DBMS_UTILITY.MAKE_DATA_BLOCK_ADDRESS(HEADER_FILE,HEADER_BLOCK+RN),'XXXXXXXXXX') HEX_RDBA FROM DBA_SEGMENTS, (SELECT /*+ MATERIALIZE */ ROWNUM-1 RN FROM DUAL CONNECT BY LEVEL<=10) WHERE SEGMENT_NAME IN ('T1','T2') ORDER BY SEGMENT_NAME, RN; SEGMENT_NAME RDBA HEX_RDBA ------------ ---------- ----------- T1 29360139 1C0000B T1 29360140 1C0000C T1 29360141 1C0000D T1 29360142 1C0000E T1 29360143 1C0000F T1 29360144 1C00010 T1 29360145 1C00011 T1 29360146 1C00012 T1 29360147 1C00013 T1 29360148 1C00014 T2 29361131 1C003EB T2 29361132 1C003EC T2 29361133 1C003ED T2 29361134 1C003EE T2 29361135 1C003EF T2 29361136 1C003F0 T2 29361137 1C003F1 T2 29361138 1C003F2 T2 29361139 1C003F3 T2 29361140 1C003F4
—
Or, we could try working from the opposite direction. With the knowledge that the lower 22 bits of the RDBA is the block number and the upper ten bits of the RDBA is the relative file number, we can manually calculate the relative file number and the block number from the RDBA and then look up the object name associated with the file and block. First, we need the decimal equivalent of (binary) 1111111111111111111111:
(binary) 1111111111111111111111 = (decimal) 4194303
So, if we BITAND the RDBA with 4194303 we can obtain the block number, and if we divide the RDBA by 4194304 we can determine the relative file number for two of the RDBA numbers that were listed in the trace file summary, as shown below:
SELECT TO_CHAR(L.RDBA,'XXXXXXXX') HEX_RDBA, L.RDBA, TRUNC(L.RDBA/4194304) DATA_FILE, BITAND(L.RDBA,4194303) DATA_BLOCK FROM (SELECT TO_NUMBER('01c0000c', 'XXXXXXXX') RDBA FROM DUAL UNION ALL SELECT TO_NUMBER('01c003ec', 'XXXXXXXX') RDBA FROM DUAL) L; HEX_RDBA RDBA DATA_FILE DATA_BLOCK --------- ---------- ---------- ---------- 1C0000C 29360140 7 12 1C003EC 29361132 7 1004
Remembering the number 4194303 might be challenging, so we can just use the DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE and DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK functions instead. Looking up the associated object names can be slow, unless we are able to limit the object names to a list of specific objects (ideally, we would also specify the DE.OWNER column in the WHERE clause):
SELECT /*+ LEADING(L) */ TO_CHAR(L.RDBA, 'XXXXXXXX') RDBA_HEX, L.RDBA, DE.SEGMENT_NAME, DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE(L.RDBA) DATA_FILE, DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK(L.RDBA) DATA_BLOCK FROM (SELECT TO_NUMBER('01c0000c', 'XXXXXXXX') RDBA FROM DUAL UNION ALL SELECT TO_NUMBER('01c003ec', 'XXXXXXXX') RDBA FROM DUAL) L, DBA_EXTENTS DE WHERE DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE(L.RDBA)=DE.FILE_ID AND DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK(L.RDBA) BETWEEN DE.BLOCK_ID AND (DE.BLOCK_ID + DE.BLOCKS - 1) AND DE.SEGMENT_NAME IN ('T1','T2') ORDER BY DE.SEGMENT_NAME; RDBA_HEX RDBA SEGMENT_NAME DATA_FILE DATA_BLOCK --------- ---------- ------------ ---------- ---------- 1C0000C 29360140 T1 7 12 1C003EC 29361132 T2 7 1004
————————————————-
Now let’s take a look at Oracle Database 11.2.0.2 – what has changed? If we execute the test SQL statement, we see the following execution plan for the query:
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST -ROWS -PREDICATE')); SQL_ID 1afa5ym56cagh, child number 0 ------------------------------------- SELECT /*+ GATHER_PLAN_STATISTICS LEADING(T1) USE_NL(T2) INDEX(T1) INDEX(T2) */ T1.ID, T1.N1, T2.ID, T2.N1 FROM T1, T2 WHERE T1.ID=T2.ID AND T1.ID BETWEEN 1 AND 200 AND T2.N1 = 0 Plan hash value: 3072046012 ---------------------------------------------------------------------------------------- | Id | Operation | Name | Starts | A-Rows | A-Time | Buffers | ---------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 0 |00:00:00.01 | 215 | | 1 | NESTED LOOPS | | 1 | 0 |00:00:00.01 | 215 | | 2 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 200 |00:00:00.01 | 6 | | 3 | INDEX RANGE SCAN | PAR_I1 | 1 | 200 |00:00:00.01 | 2 | | 4 | TABLE ACCESS BY INDEX ROWID| T2 | 200 | 0 |00:00:00.01 | 209 | | 5 | INDEX UNIQUE SCAN | CHI_I1 | 200 | 200 |00:00:00.01 | 9 | ----------------------------------------------------------------------------------------
Notice in the above that the 202 consistent gets that we saw for the CHI_I1 index in Oracle Database 10.2.0.5 oddly only required 9 consistent gets in Oracle Database 11.2.0.2. But that is not the only change. If we process the 10200 trace file through one of the trace file parsers, we might see something like this:
0x0200439b> objd: 0x00011711 1 0x0200439c> objd: 0x00011711 1 0x02000083> objd: 0x00011705 1 0x01c04d9b> objd: 0x00011710 1 0x01c04d9c> objd: 0x00011710 1 0x01c0389b> objd: 0x00011706 1 0x01c04d9b> objd: 0x00011710 2 0x01c04d9c> objd: 0x00011710 2 0x01c0389b> objd: 0x00011706 2 0x01c04d9c> objd: 0x00011710 3 0x01c0389b> objd: 0x00011706 3 0x01c04d9c> objd: 0x00011710 4 0x01c0389b> objd: 0x00011706 4 0x01c04d9c> objd: 0x00011710 5 0x01c0389b> objd: 0x00011706 5 0x01c04d9c> objd: 0x00011710 6 0x01c0389b> objd: 0x00011706 6 0x01c04d9c> objd: 0x00011710 7 0x01c0389b> objd: 0x00011706 7 0x01c0389b> objd: 0x00011706 8 0x01c0389b> objd: 0x00011706 9 0x01c0389b> objd: 0x00011706 10 0x01c0389b> objd: 0x00011706 11 0x01c0389b> objd: 0x00011706 12 ... 0x01c0389b> objd: 0x00011706 54 0x01c0389b> objd: 0x00011706 55 0x01c0389b> objd: 0x00011706 56 0x01c0389b> objd: 0x00011706 57 0x02000084> objd: 0x00011705 1 0x01c0389c> objd: 0x00011706 1 0x01c0389c> objd: 0x00011706 2 0x01c0389c> objd: 0x00011706 3 0x01c0389c> objd: 0x00011706 4 ... 0x01c0389c> objd: 0x00011706 55 0x01c0389c> objd: 0x00011706 56 0x01c0389c> objd: 0x00011706 57 0x02000085> objd: 0x00011705 1 0x01c0389d> objd: 0x00011706 1 0x01c0389d> objd: 0x00011706 2 0x01c0389d> objd: 0x00011706 3 0x01c0389d> objd: 0x00011706 4 0x01c0389d> objd: 0x00011706 5 ... 0x01c0389d> objd: 0x00011706 55 0x01c0389d> objd: 0x00011706 56 0x01c0389d> objd: 0x00011706 57 0x02000086> objd: 0x00011705 1 0x01c0389e> objd: 0x00011706 1 0x01c0389e> objd: 0x00011706 2 0x01c0389e> objd: 0x00011706 3 ... 0x01c0389e> objd: 0x00011706 27 0x01c0389e> objd: 0x00011706 28 0x01c0389e> objd: 0x00011706 29 0x0200439b> objd: 0x00011711 1 0x0200439c> objd: 0x00011711 1 0x02000083> objd: 0x00011705 1 0x01c04d9b> objd: 0x00011710 2 0x01c04d9c> objd: 0x00011710 7 0x01c0389b> objd: 0x00011706 57 0x02000084> objd: 0x00011705 1 0x01c0389c> objd: 0x00011706 57 0x02000085> objd: 0x00011705 1 0x01c0389d> objd: 0x00011706 57 0x02000086> objd: 0x00011705 1 0x01c0389e> objd: 0x00011706 29
Interesting – it appears that Oracle Database 11.2.0.2 writes the DATA_OBJECT_ID that is related to the block, directly into the trace file so that we no longer need to execute several SQL statements to determine the object names related to the blocks.
Inside the raw 10200 trace file from 11.2.0.2 we might see something like the following:
ktrgtc2(): started for block <0x0009 : 0x0200439b> objd: 0x00011711 env [0x000000001870BF5C]: (scn: 0x0000.0014c547 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: 0x0000.000.00000000 st-scn: 0x0000.00000000 hi-scn: 0x0000.00000000 ma-scn: 0x0000.0014c527 flg: 0x00000661) ktrexc(): returning 2 on: 0000000013C3D598 cr-scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 cl-scn: 0xffff.ffffffff sfl: 0 ktrgtc2(): completed for block <0x0009 : 0x0200439b> objd: 0x00011711 ktrget2(): started for block <0x0009 : 0x0200439c> objd: 0x00011711 env [0x000000001870BF5C]: (scn: 0x0000.0014c547 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: 0x0000.000.00000000 st-scn: 0x0000.00000000 hi-scn: 0x0000.0014c547 ma-scn: 0x0000.0014c527 flg: 0x00000662) ktrexf(): returning 9 on: 0000000013C3D598 cr-scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 cl-scn: 0xffff.ffffffff sfl: 0 ktrgcm(): completed for block <0x0009 : 0x0200439c> objd: 0x00011711 ktrget2(): completed for block <0x0009 : 0x0200439c> objd: 0x00011711 ktrget2(): started for block <0x0009 : 0x02000083> objd: 0x00011705 env [0x000000001870BF5C]: (scn: 0x0000.0014c547 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: 0x0000.000.00000000 st-scn: 0x0000.00000000 hi-scn: 0x0000.0014c547 ma-scn: 0x0000.0014c527 flg: 0x00000662) ktrexf(): returning 9 on: 0000000013C3D598 cr-scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 cl-scn: 0xffff.ffffffff sfl: 0 ktrgcm(): completed for block <0x0009 : 0x02000083> objd: 0x00011705 ktrget2(): completed for block <0x0009 : 0x02000083> objd: 0x00011705 ktrgtc2(): started for block <0x0009 : 0x01c04d9b> objd: 0x00011710 env [0x000000001870BF5C]: (scn: 0x0000.0014c547 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: 0x0000.000.00000000 st-scn: 0x0000.00000000 hi-scn: 0x0000.0014c547 ma-scn: 0x0000.0014c527 flg: 0x00000662) ktrexc(): returning 2 on: 0000000013C3D598 cr-scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 cl-scn: 0xffff.ffffffff sfl: 0 ktrgtc2(): completed for block <0x0009 : 0x01c04d9b> objd: 0x00011710 ktrgtc2(): started for block <0x0009 : 0x01c04d9c> objd: 0x00011710 env [0x000000001870BF5C]: (scn: 0x0000.0014c547 xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 statement num=0 parent xid: 0x0000.000.00000000 st-scn: 0x0000.00000000 hi-scn: 0x0000.0014c547 ma-scn: 0x0000.0014c527 flg: 0x00000662) ktrexc(): returning 2 on: 0000000013C3D598 cr-scn: 0xffff.ffffffff xid: 0x0000.000.00000000 uba: 0x00000000.0000.00 cl-scn: 0xffff.ffffffff sfl: 0 ktrgtc2(): completed for block <0x0009 : 0x01c04d9c> objd: 0x00011710
The 10200 trace file in 11.2.0.2 provided the DATA_OBJECT_ID for the consistent reads, while the 10.2.0.5 trace file did not. We can use this information to determine which objects were accessed, and in which order by pulling in the unique OBJD values from the summary:
SELECT OBJECT_NAME, DATA_OBJECT_ID, TO_CHAR(DATA_OBJECT_ID, 'XXXXX') HEX_DATA_OBJECT_ID FROM DBA_OBJECTS WHERE DATA_OBJECT_ID IN( TO_NUMBER('11711', 'XXXXX'), TO_NUMBER('11705', 'XXXXX'), TO_NUMBER('11710', 'XXXXX'), TO_NUMBER('11706', 'XXXXX')); OBJECT_NAME DATA_OBJECT_ID HEX_DA ----------- -------------- ------ T1 71429 11705 T2 71430 11706 CHI_I1 71440 11710 PAR_I1 71441 11711
Taking another look at the summary, now updated with the table and index blocks:
0x0200439b> objd: 0x00011711 1 /* PAR_I1 Root block of index on T1 */ 0x0200439c> objd: 0x00011711 1 /* PAR_I1 Leaf block of index on T1 */ 0x02000083> objd: 0x00011705 1 /* T1 Table block */ 0x01c04d9b> objd: 0x00011710 2 /* CHI_I1 Root block of index on T2 */ 0x01c04d9c> objd: 0x00011710 7 /* CHI_I1 Leaf block of index on T2 */ 0x01c0389b> objd: 0x00011706 57 /* T2 Table block */ 0x02000084> objd: 0x00011705 1 /* T1 Table block */ 0x01c0389c> objd: 0x00011706 57 /* T2 Table block */ 0x02000085> objd: 0x00011705 1 /* T1 Table block */ 0x01c0389d> objd: 0x00011706 57 /* T2 Table block */ 0x02000086> objd: 0x00011705 1 /* T1 Table block */ 0x01c0389e> objd: 0x00011706 2 /* T2 Table block */
So, from the above, 2 of the consistent gets for the CHI_I1 index were for the root block of the index, and the remaining 7 were for the first leaf block.
—
Simple?
——————-
Anyone want to try creating a 10200 trace file parser in a different programming language and posting the source code here?
Interesting troubleshooting Charles, thanks.
But i still don’t know why the number of consistent gets for a SQL statement is significantly different between 10gR2 and 11gR2.
My guess is that Oracle is more “intelligent” and, perhaps he knows that he will touch the block again,again,again, so he decides to bring the block to the user private memory?
What do you think about it?
Thiago,
I think that you are right. There is a statistic with the name ‘buffer is pinned count’, and the amount by which this increased for the session on 10.2.0.5 and 11.2.0.2 was different – I ran out of time and was not able to spend much time comparing the differences, but I will check again later. Tanel Poder has an excellent write up on this statistic, part of which is quoted below:
http://blog.tanelpoder.com/2010/01/15/beyond-oracle-wait-interface-part-2/
It appears that 11.2.0.2 is much more intelligent with how index blocks are pinned, quickly pinning the index leaf blocks of the index belonging to the inner table in the nested looks join, while 10.2.0.5 did not pin these blocks. This increased willingness to pin observation of course is based on very limited testing, and might not apply to other situations. I welcome other people to test and report their findings – maybe it only happens in small index structures?
OK, I took another look at my results – I need to look at something other than the ‘buffer is pinned count’ statistic.
The results:
10.2.0.5:
11.2.0.2:
The above shows that the ‘buffer is pinned count’ increased by 593 on Oracle Database 10.2.0.5, and 498 (95 less) on Oracle Database 11.2.0.2. I would have expected that statistic would be about 190 higher on 11.2.0.2 than on 10.2.0.5.
Charles,
So, according to your results our guesses related to ‘buffer is pinned count’ might be not right. I was running the test in my desktop (Windows XP running 11.2.0.1) and i got some results:
1) even when the OPTIMIZER_FEATURES_ENABLE is set to ‘10.2.0.4’, the query returned 215 BG instead of 408 BG in my tests, still don’t know why.
2) reading http://blog.tanelpoder.com/2009/11/19/finding-the-reasons-for-excessive-logical-ios/, tanel says the quote below:
“These buffer get reason counters are not maintained properly in Oracle 11g, probably due an optimization effort and some changes for faster pinning of buffer cache buffers (there’s a parameter called _fastpin_enable which is set to 1 in 11g and it enables so called fastpath buffer gets. If you see v$sesstat statistics such “consistent gets from cache (fastpath) or “db block gets from cache (fastpath)” being inremented, then fastpath buffer gets/pins are used. Note that I do have a script which works also on 11g but I’ll write about that one some time in the future 🙂 ”
Said that, i changed the ‘_fastpin_enable’ to 0 and still got the same results.
So, Oracle is hiding something in version 11g 🙂
Cheers!
Hi Charles,
I think the text for your second table dump should read “Partial output from the TABLE_DUMP_T2…..’ instead of “…… TABLE_DUMP_T1….”
I’m truly amazed by your seemingly unlimited supply of write-ups 🙂
Cheers
Thank you for catching that error – I have now fixed it.
This write up took the better part of a day, and I was a bit tired as I went back through writing and then editing the comments that appear between the code blocks. I keep running out of ideas for blog articles, but seemingly like clockwork I see something written by someone else that triggers another idea for an article.
Question
How come you did not get the new extra nested loop when you run it on 11.2.0.2 (reference_link).
My tests on 11.2.0.1 generates the new extra nested loop
Were you still under optimizer_features_enable=10.2.0.4
Coskan,
Good that someone is actually trying the test. Sorry if it was not clear if you need to change the value of OPTIMIZER_FEATURES_ENABLE for the 11.2.0.2 execution. Yes, that setting is necessary to eliminate the second NESTED LOOPS join. So, the script to run the execution plan (somewhere near the top of this article is:
Of course, when you perform the 10200 trace, the changed value for OPTIMIZER_FEATURES_ENABLE should still be set.
last try, delete the previous …
– a small awk script, does the trick
– script working with gawk and trace file 11.1.0.7; example line: ktrget2(): started for block objd: 0x00189fa5
– to change, just change the $number references
$ awk -v trcfile=small.trc -f cons_get_trc.awk
now i lost the last part of the trace line …., and some typos
Stefan,
Please provide the missing sections in a comment and I will edit your comment above. Thanks for taking the time to post an awk script.
On this blog the <pre> and </pre> codes seem to work well when posting code, but < and > symbols may cause code to disappear.
Before posting code, please replace:
< symbols with < ; (without a space before the ; )
> symbols with > ; (without a space before the ; )
just decided, that I will no finally start blogging as well, until that’s up and running, here is my post (again):
My contribution a small awk script, that allows direct parsing of the trace file output on unix (although, I actually used it on cygwin …., so may be not 100% compatible)
The script is working with gawk and trace file 11.1.0.7; example trace line:
ktrget2(): started for block <0x0104 : 0x09e3d4cc> objd: 0x00189fa5.
In order to change to another trace file format, you just have to change $nr references in the script.
$ more cons_get_trc.awk
One third code, two thirds output. Usage demonstration, with just a head 50 of a trace file into small.trc:
$ awk -v trcfile=small.trc -f cons_get_trc.awk
[…] to my last post, this relates to another posting https://hoopercharles.wordpress.com/2011/01/24/watching-consistent-gets-10200-trace-file-parser. Tracing the event 10200 allows to see consistent reads. For details read linked blog entry. So now […]
OK, I know, that this post is over 3 years old, though since I stumbled upon it by chance only now, I thought I’d chime in with a perl “oneliner” version of the event 10200 trace file parser, as perl is installed these days pretty much everywhere, and I personally like it better than awk 🙂
(well, it was originally a one-liner, but then I wanted to make the formatting nicer, so it grow to a multi-liner)
1) version for 10g, no object IDs
Lists the following columns in the output, seperated by colons (:): rdba:hex:dec:count
Output sorted descending by count.
+ adds a line at the end of the listing, with the count(distinct(rdba))
2) Version for 11g (containing the object ID in the tracefile)
Contains 2 separate listings:
a) Lists the following columns in the output, seperated by colons (:): rdba:hex:dec:dec(obj#):count
Output sorted descending by count.
+ adds a line at the end of the listing, with the count(distinct(rdba))
b) Lists the following columns in the output, seperated by colons (:): obj:hex:dec:count
Output sorted descending by count.
+ adds a line at the end of the listing, with the count(distinct(obj))
Sample output of the 11g version (on an interesting IRS, which needed way too many BGs to obtain a small number of rows):
Cheers,
Josef K
Josef,
Yes, this is an old blog article. However, the invitation for readers to provide their translation of the 10020 trace using their tool of choice was still open. Thank you for providing the translation to Perl. The only code I wrote in Perl is an extension for Nagios to allow it to verify that a database instance is up, and willing to process simple SQL statements.
Also, thank you to sz for providing the awk translation.
I am in the process of reading the book Troubleshooting Oracle Performance, Second Edition”, and from what I have found so far, discussion of 10020 traces is the only performance related item not mentioned in that book (I did not realize that until I saw your comment on this blog article).