Watching Consistent Gets – 10200 Trace File Parser

24 01 2011

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?


Actions

Information

15 responses

24 01 2011
Thiago Maciel

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?

24 01 2011
Charles Hooper

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/

“However, check the value for buffer is pinned count statistic! This counter is updated every time we go to a buffer to get some data from it AND it already happens to be open by my session! Oracle keeps buffers pinned and relevant buffer handles cached during a database call in some cases (like nested loop joins and index scans) to avoid reopening the buffer again (getting a buffer again if its closed would mean another logical IO).”

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?

24 01 2011
Charles Hooper

OK, I took another look at my results – I need to look at something other than the ‘buffer is pinned count’ statistic.

ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE='10.2.0.4';
 
COLUMN NAME FORMAT A38
 
SELECT
  NAME,
  VALUE
FROM
  V$MYSTAT M,
  V$STATNAME S
WHERE
  (NAME LIKE 'consistent%'
    OR NAME LIKE 'buffer%')
  AND M.STATISTIC#=S.STATISTIC#;
 
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
  NAME,
  VALUE
FROM
  V$MYSTAT M,
  V$STATNAME S
WHERE
  (NAME LIKE 'consistent%'
    OR NAME LIKE 'buffer%')
  AND M.STATISTIC#=S.STATISTIC#;

The results:
10.2.0.5:

NAME                                        VALUE
-------------------------------------- ----------
consistent gets                                44
consistent gets from cache                     44
consistent gets - examination                   3
consistent gets direct                          0
consistent changes                              0
buffer is pinned count                         37
buffer is not pinned count                      7
 
NAME                                        VALUE
-------------------------------------- ----------
consistent gets                               452  /* +408 */
consistent gets from cache                    452  /* +408 */
consistent gets - examination                 405  /* +402 */
consistent gets direct                          0
consistent changes                              0
buffer is pinned count                        630  /* +593 */
buffer is not pinned count                    413  /* +406 */

11.2.0.2:

NAME                                        VALUE
-------------------------------------- ----------
consistent gets                                37
consistent gets from cache                     37
consistent gets from cache (fastpath)          32
consistent gets - examination                   4
consistent gets direct                          0
consistent changes                              0
buffer is pinned count                         12
buffer is not pinned count                      8
 
NAME                                        VALUE
-------------------------------------- ----------
consistent gets                               252  /* +215 */
consistent gets from cache                    252  /* +215 */
consistent gets from cache (fastpath)          39  /* +  7 */
consistent gets - examination                 212  /* +208 */
consistent gets direct                          0
consistent changes                              0
buffer is pinned count                        410  /* +498 */
buffer is not pinned count                    416  /* +408 */

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.

24 01 2011
Thiago Maciel

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!

24 01 2011
Andy

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

24 01 2011
Charles Hooper

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.

24 01 2011
coskan

Question

How come you did not get the new extra nested loop when you run it on 11.2.0.2 (reference_link).

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  3v5y2pjq60zzd, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS LEADING(T1) USE_NL(T2) INDEX(T1)
INDEX(T2) */ /*test_11201*/   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: 2303960507

----------------------------------------------------------------------------------------
| Id  | Operation                     | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |        |       |       |   206 (100)|          |
|   1 |  NESTED LOOPS                 |        |       |       |            |          |
|   2 |   NESTED LOOPS                |        |     1 |    20 |   206   (0)| 00:00:02 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1     |   200 |  2000 |     6   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | PAR_I1 |   200 |       |     2   (0)| 00:00:01 |
|*  5 |    INDEX UNIQUE SCAN          | CHI_I1 |     1 |       |     0   (0)|          |
|*  6 |   TABLE ACCESS BY INDEX ROWID | T2     |     1 |    10 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------

My tests on 11.2.0.1 generates the new extra nested loop

Were you still under optimizer_features_enable=10.2.0.4

24 01 2011
Charles Hooper

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:

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')); 

Of course, when you perform the 10200 trace, the changed value for OPTIMIZER_FEATURES_ENABLE should still be set.

16 04 2011
stefan

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

BEGIN {
   FS ="[ \t<>:]+"
   print "Details for file: " trcfile
   print "---------------------------------"
   while( getline < trcfile != EOF ){
      if ( $0 ~ /started for block/ ) {
           rba[$6]+=1
           obj[$8]+=1
           both[$6","$8]+=1
           print $6 " " rba[$6] ", " $8 " " obj[$8]
       }
   }
   close (trcfile)
   print ""

   print "Summary rba for file: " trcfile
   print "---------------------------------"
   for ( var in rba ) {
      print var " " rba[var]
   }

   print ""
   print "Summary obj for file: " trcfile
   print "---------------------------------"
   for ( var in obj ) {
     print var " " obj[var]
   }

   print ""
   print "Summary rdba and obj for file: " trcfile
   print "---------------------------------"
   for ( var in both) {
     print var " " both[var]
   }

}

$ awk -v trcfile=small.trc -f cons_get_trc.awk

Details for file: small.trc
---------------------------------
0x09e3d4cc 1, 0x00189fa5 1
0x09fa4692 1, 0x00189fa5 2
0x0a0ac450 1, 0x00189fa5 3
0x009d94fc 1, 0x00189fa5 4
0x09fa4698 1, 0x00189fa5 5
0x009d94ff 1, 0x00189fa5 6

Summary rba for file: small.trc
---------------------------------
0x09fa4692 1
0x009d94ff 1
0x09fa4698 1
0x0a0ac450 1
0x09e3d4cc 1
0x009d94fc 1

Summary obj for file: small.trc
---------------------------------
0x00189fa5 6

Summary rdba and obj for file: small.trc
---------------------------------
0x0a0ac450,0x00189fa5 1
0x09fa4698,0x00189fa5 1
0x09fa4692,0x00189fa5 1
0x009d94ff,0x00189fa5 1
0x009d94fc,0x00189fa5 1
0x09e3d4cc,0x00189fa5 1
16 04 2011
stefan

now i lost the last part of the trace line …., and some typos

16 04 2011
Charles Hooper

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 &lt ; (without a space before the ; )
> symbols with &gt ; (without a space before the ; )

16 04 2011
sz

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

BEGIN { 
   FS ="[ \t<>:]+"
    print "Details for file: " trcfile
   print "---------------------------------"
   while( getline < trcfile != EOF ){
      if ( $0 ~ /started for block/ ) {
      rdba[$6]+=1
      obj[$8]+=1
      both[$6","$8]+=1
      print $6 " " rdba[$6] ", " $8 " " obj[$8]
      }
   }
   close (trcfile)
   print ""

   print ""
   print "Summary rdba and obj for file: " trcfile
   print "---------------------------------"
   for ( var in both) {
      print var " " both[var]
   }

   print ""
   print "Summary obj for file: " trcfile
   print "---------------------------------"
   for ( var in obj ) {
      print var " " obj[var]
   }
}

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

Details for file: small.trc
---------------------------------
0x09e3d4cc 1, 0x00189fa5 1
0x09fa4692 1, 0x00189fa5 2
0x0a0ac450 1, 0x00189fa5 3
0x009d94fc 1, 0x00189fa5 4
0x09fa4698 1, 0x00189fa5 5
0x009d94ff 1, 0x00189fa5 6

Summary rdba and obj for file: small.trc
---------------------------------
0x0a0ac450,0x00189fa5 1
0x09fa4698,0x00189fa5 1
0x09fa4692,0x00189fa5 1
0x009d94ff,0x00189fa5 1
0x009d94fc,0x00189fa5 1
0x09e3d4cc,0x00189fa5 1

Summary obj for file: small.trc
---------------------------------
0x00189fa5 6

16 04 2011
Consistent get trace file parser « perfexpert2

[...] to my last post, this relates to another posting  http://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 [...]

11 07 2014
Josef K

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))

perl -e '
 use warnings;use strict;my %hrdba=();
 while(<STDIN>){if(/started for block[^:]+:\s*0x([^>]+)/){$hrdba{$1}++}};
 for my $i (sort{$hrdba{$b}<=>$hrdba{$a}} keys %hrdba){printf("$i:%d:$hrdba{$i}\n",hex($i))}
 printf("-- count(distinct(rdba))=%d\n",scalar keys %hrdba);
' <event_10200_tracefilename.trc

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))

perl -e '
 use warnings;use strict;my %hrdba=();my %hobj=();
 while(<STDIN>){if(/started for block[^:]+:\s*0x([^>]+)>\s*objd:\s*0x([0-9a-f]+)/){if(1==++$hrdba{$1}{"c"}){$hrdba{$1}{"o"}=hex($2)};$hobj{$2}++}};
 print "-- rdba:hex:dec:dec(obj):count\n";
 for my $i (sort{$hrdba{$b}{'c'}<=>$hrdba{$a}{'c'}} keys %hrdba){printf("rdba:$i:%d:%d:%d\n",hex($i),$hrdba{$i}{"o"},$hrdba{$i}{"c"})}
 printf("-- count(distinct(rdba))=%d\n\n-- obj#:hex:dec:count\n",scalar keys %hrdba);
 for my $i (sort{$hobj{$b}<=>$hobj{$a}} keys %hobj){printf("obj:$i:%d:$hobj{$i}\n",hex($i))}
 printf("-- count(distinct(obj))=%d\n",scalar keys %hobj);
' <event_10200_tracefilename.trc

Sample output of the 11g version (on an interesting IRS, which needed way too many BGs to obtain a small number of rows):

[oracle@somehost 20140711]$ perl -e '
>  use warnings;use strict;my %hrdba=();my %hobj=();
>  while(<STDIN>){if(/started for block[^:]+:\s*0x([^>]+)>\s*objd:\s*0x([0-9a-f]+)/){if(1==++$hrdba{$1}{"c"}){$hrdba{$1}{"o"}=hex($2)};$hobj{$2}++}};
>  print "-- rdba:hex:dec:dec(obj):count\n";
>  for my $i (sort{$hrdba{$b}{'c'}<=>$hrdba{$a}{'c'}} keys %hrdba){printf("rdba:$i:%d:%d:%d\n",hex($i),$hrdba{$i}{"o"},$hrdba{$i}{"c"})}
>  printf("-- count(distinct(rdba))=%d\n\n-- obj#:hex:dec:count\n",scalar keys %hrdba);
>  for my $i (sort{$hobj{$b}<=>$hobj{$a}} keys %hobj){printf("obj:$i:%d:$hobj{$i}\n",hex($i))}
>  printf("-- count(distinct(obj))=%d\n",scalar keys %hobj);
> ' <ORASID_ora_8303_JK_20140711_124801.trc
-- rdba:hex:dec:dec(obj):count
rdba:0041137b:4264827:2:4
rdba:0c2b0866:204146790:75267:2
rdba:0af5ef58:183889752:75267:1
rdba:0cb12ca6:212937894:75267:1
[...]
rdba:0c746c0d:208956429:75267:1
rdba:0aa81b1b:178789147:75267:1
rdba:09e46c8c:165964940:75267:1
-- count(distinct(rdba))=8845

-- obj#:hex:dec:count
obj:00012603:75267:8840
obj:00012604:75268:5
obj:00000002:2:4
-- count(distinct(obj))=3
[oracle@somehost 20140711]$ 

Cheers,
Josef K

11 07 2014
Charles Hooper

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).

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 142 other followers

%d bloggers like this: