10200 Trace Shows Consistent Reads, but Not All Consistent Reads

October 4, 2011

An interesting, but poorly worded, problem appeared in an OTN thread recently where the OP claimed that a 10200 trace was not showing a consistent get, even though a concurrent 10046 trace’s EXEC and STAT lines indicated one consistent get.  The provided test case and sample 10200/10046 trace left a couple of details unspecified, such as the table and index definitions, the tablespace definition, the Oracle Database release version, and exactly what the OP was trying to understand: does a 10200 trace never work, or is it just not producing output in this specific case.

Let’s try a couple of experiments to try to reproduce the output provided by the OP.  Frst let’s make certain that we know what the OP wanted to see.  A 10200 trace is supposed to write out additional lines in a trace file every time a consistent block read is performed – we have previously experimented a bit with 10200 trace file entries.  Let’s connect to the database using two SQL*Plus sessions, session 1 will connect as a standard database user, and session 2 will connect as the SYS user.  We will create a locally managed, non-ASSM, tablespace with uniform 1MB extent sizes to help improve the consistency of the results.  A sample CREATE TABLESPACE command follows (created in session 2):

CREATE SMALLFILE TABLESPACE "LOCAL_UNIFORM1M" DATAFILE 'C:\Oracle\OraData\OR1122D\locun1MOR1122.dbf' SIZE 100M AUTOEXTEND ON NEXT 10M
  MAXSIZE UNLIMITED LOGGING EXTENT MANAGEMENT LOCAL UNIFORM SIZE 1M SEGMENT SPACE MANAGEMENT MANUAL; 

In session 1, we will create a table in the recently created tablespace, populate the table with 100,001 rows, and then execute a couple of throw-away SQL statements that will be used later (this is done to eliminate the hard parse during the later re-execution of the SQL statements):

DROP TABLE T4 PURGE;

CREATE TABLE T4(
  C1 NUMBER,
  C2 VARCHAR2(10),
  C3 VARCHAR2(10))
  TABLESPACE LOCAL_UNIFORM1M;

INSERT INTO
  T4
SELECT
  ROWNUM+10,
  TO_CHAR(ROWNUM),
  TO_CHAR(ROWNUM+10)
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>NULL,TABNAME=>'T4',CASCADE=>TRUE)

INSERT INTO T4 VALUES(1,NULL,NULL);
COMMIT;

SET AUTOTRACE TRACEONLY STATISTICS

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'T4_IGNORE_ME';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT
  *
FROM
  T4;

SELECT
  SYSDATE
FROM
  DUAL;

INSERT INTO T4 VALUES(2,NULL,NULL);
ROLLBACK;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT OFF';

In session 2 (the SYS session), we will execute a SQL statement that examines X$BH where the STATE column is not equal to 0, after flushing the buffer cache.  This query will indicate the blocks that remain in the buffer cache as well as the STATE of the block in the buffer cache.  From http://www.ixora.com.au/q+a/0103/22151356.htm, the meaning of the STATE column (we could have just queried V$BH instead to see the meaning of that column):

0, FREE, no valid block image
1, XCUR, a current mode block, exclusive to this instance
2, SCUR, a current mode block, shared with other instances
3, CR,   a consistent read (stale) block image
4, READ, buffer is reserved for a block being read from disk
5, MREC, a block in media recovery mode
6, IREC, a block in instance (crash) recovery mode

We will need to re-execute the SQL statement a couple of times (waiting a few seconds between executions) until the query results stabilize:

SELECT
  TS#,
  FILE#,
  DBARFIL,
  DBABLK,
  STATE
FROM
  X$BH
WHERE
  STATE<>0
ORDER BY
  TS#,
  FILE#,
  DBABLK;

/

/ 

Once stabilized, the query output appeared as follows for my test case:

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1 

The above shows two blocks from the SYSTEM tablespace, with a STATE of 1 (current version of the block).

Quickly switching back to session 1, we execute a SQL statement for which we are interested in examining, followed by a second SQL statement that is simply intended to make certain that the STAT lines were written to the trace file (will will need to quickly switch back to session 2 after executing this script):

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'T4_SELECT';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

SELECT
  *
FROM
  T4;

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT OFF'; 

In session 2 (the SYS session), execute the following:

/ 

Session 2 produced the following output (slightly modified due to length, with each added block found in the buffer cache numbered):

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1
   5      5          5        128      1  *   1
   5      5          5        129      1  *   2
   5      5          5        130      1  *   3
   5      5          5        131      1  *   4
   5      5          5        132      1  *   5
   5      5          5        133      1  *   6
   5      5          5        134      1  *   7
   5      5          5        135      1  *   8
   5      5          5        136      1  *   9
   5      5          5        137      1  *  10
...
   5      5          5        423      1  * 296
   5      5          5        424      1  * 297
   5      5          5        425      1  * 298
   5      5          5        426      1  * 299
   5      5          5        427      1  * 300
   5      5          5        428      1  * 301

303 rows selected. 

The query executed in session 1 added 301 blocks to the buffer cache (XCUR – the current versions of the block).  Let’s take a look at the statistics displayed in session 1 for the execution of the select from T4:

SQL> SELECT
  2    *
  3  FROM
  4    T4;

100001 rows selected.

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
       6967  consistent gets
        301  physical reads
          0  redo size
    2353883  bytes sent via SQL*Net to client
      73685  bytes received via SQL*Net from client
       6668  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     100001  rows processed 

The above shows 301 blocks read from disk (physical reads), with 6,967 blocks read by consistent read (consistent gets), and 0 current mode reads (db block gets).

Taking a look at a portion of the generated 10200/10046 trace file (some of the rows are numbered to match the comments added to the query of X$BH):

PARSE #391723720:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2560505625,tim=90982737037
EXEC #391723720:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2560505625,tim=90982737090
WAIT #391723720: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13759 tim=90982737111
WAIT #391723720: nam='Disk file operations I/O' ela= 133 FileOperation=2 fileno=5 filetype=2 obj#=13759 tim=90982737271
WAIT #391723720: nam='db file sequential read' ela= 163 file#=5 block#=128 blocks=1 obj#=71123 tim=90982737471               * 1
ktrget2(): started for block  <0x0005 : 0x01400081> objd: 0x000115d3 env [0x000000001759AF24]: (scn: 0x0000.0048429e  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.00484274  flg: 0x00000661) 
WAIT #391723720: nam='db file scattered read' ela= 2876 file#=5 block#=129 blocks=127 obj#=71123 tim=90982740602             * 2 through 128
ktrgcm(): completed for block  <0x0005 : 0x01400081> objd: 0x000115d3 
ktrget2(): completed for  block <0x0005 : 0x01400081> objd: 0x000115d3 
FETCH #391723720:c=0,e=3865,p=128,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2560505625,tim=90982740990
WAIT #391723720: nam='SQL*Net message from client' ela= 93 driver id=1413697536 #bytes=1 p3=0 obj#=71123 tim=90982741103
ktrget2(): started for block  <0x0005 : 0x01400081> objd: 0x000115d3 env [0x000000001759AF24]: (scn: 0x0000.0048429e  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.00484274  flg: 0x00000660) 
ktrexf(): returning 9 on:  0000000012658C48  cr-scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  cl-scn: 0xffff.ffffffff  sfl: 0 
ktrgcm(): completed for block  <0x0005 : 0x01400081> objd: 0x000115d3 ktrget2(): completed for  block <0x0005 : 0x01400081> objd: 0x000115d3
WAIT #391723720: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=71123 tim=90982741172
FETCH #391723720:c=0,e=55,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=2560505625,tim=90982741183
...
WAIT #391723720: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=71123 tim=90983507550
ktrget2(): started for block  <0x0005 : 0x014001ac> objd: 0x000115d3 env [0x000000001759AF24]: (scn: 0x0000.0048429e  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.00484274  flg: 0x00000660) 
ktrexf(): returning 9 on:  0000000012658C48  cr-scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  cl-scn: 0xffff.ffffffff  sfl: 0 
ktrgcm(): completed for block  <0x0005 : 0x014001ac> objd: 0x000115d3 ktrget2(): completed for  block <0x0005 : 0x014001ac> objd: 0x000115d3
FETCH #391723720:c=0,e=88,p=0,cr=2,cu=0,mis=0,r=10,dep=0,og=1,plh=2560505625,tim=90983507599
STAT #391723720 id=1 cnt=100001 pid=0 pos=1 obj=71123 op='TABLE ACCESS FULL T4 (cr=6967 pr=301 pw=0 time=303617 us cost=84 size=1700000 card=100000)'
WAIT #391723720: nam='SQL*Net message from client' ela= 530 driver id=1413697536 #bytes=1 p3=0 obj#=71123 tim=90983508174

In the above, we see various entries that begin with ktrget2(), ktrgcm(), ktrexf(),  and ktrgcm().  Those entries do not normally appear in a 10046 trace file, so we know that Oracle Database will write 10200 trace information for consistent gets to a trace file, when that event is enabled.  The information conveyed by the additional lines found in the trace file is partially explained here.

Let’s try a second test that reproduces what the OP was attempting to investigate.  In session 2 (the SYS session), let’s flush the buffer cache, and query X$BH until the query results stabilize:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT
  TS#,
  FILE#,
  DBARFIL,
  DBABLK,
  STATE
FROM
  X$BH
WHERE
  STATE<>0
ORDER BY
  TS#,
  FILE#,
  DBABLK;

/

/ 

Once stabilized, the query output for my test appeared as follows (the same blocks as were seen at the start of the previous test above):

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1 

Quickly switching to session 1, execute the following (then quickly jump to session 2 again):

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'T4_INSERT';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

INSERT INTO T4 VALUES(2,NULL,NULL);

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT OFF'; 

We will later switch back to session 1 to issue a ROLLBACK.  Switch to session 2 (the SYS session) and determine which blocks are in the buffer cache, and the state of those blocks:

/ 

The output that I received in session 2 follows (with a comment that counts the blocks that were added to the buffer cache):

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1
   2      3          3        224      1   * 1
   2      3          3        230      1   * 2
   5      5          5        128      1   * 3
   5      5          5        427      1   * 4
   5      5          5        428      1   * 5 

7 rows selected.

In the above, notice that 5 blocks were added to the buffer cache, all with a STATE of XCUR (the current version of the blocks).

The statistics that were output in session 1 follow:

SQL> INSERT INTO T4 VALUES(2,NULL,NULL);

1 row created.

Statistics
---------------------------------------------------
          0  recursive calls
          3  db block gets
          1  consistent gets
         35  physical reads
          0  redo size
        557  bytes sent via SQL*Net to client
        501  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed 

Notice in the above that the statistics show 35 blocks read from disk (physical reads), with 1 block read by consistent read (consistent gets), and 3 current mode reads (db block gets).  The OP mentioned finding similar output.  Let’s take a look at a portion of the 10200/10046 trace file (with comments that tie back to the output from X$BH):

PARSING IN CURSOR #392100208 len=34 dep=0 uid=62 oct=2 lid=62 tim=91041503275 hv=544833741 ad='7ffb77546b8' sqlid='96mny1hh7m06d'
INSERT INTO T4 VALUES(2,NULL,NULL)
END OF STMT
PARSE #392100208:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=91041503275
WAIT #392100208: nam='db file sequential read' ela= 175 file#=5 block#=128 blocks=1 obj#=71123 tim=91041503526     * 3
WAIT #392100208: nam='db file scattered read' ela= 971 file#=5 block#=427 blocks=32 obj#=71123 tim=91041504601     * 4 and 5
WAIT #392100208: nam='db file sequential read' ela= 144 file#=3 block#=224 blocks=1 obj#=0 tim=91041504795         * 1
WAIT #392100208: nam='db file sequential read' ela= 142 file#=3 block#=230 blocks=1 obj#=0 tim=91041504992         * 2
EXEC #392100208:c=0,e=1749,p=35,cr=1,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=91041505052                               * One Consistent Read, 3 Current Mode Reads
STAT #392100208 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=35 pw=0 time=1729 us)'          * One Consistent Read
...
CLOSE #392100208:c=0,e=3,dep=0,type=1,tim=91041508828 

Note in the above that there is no 10200 trace information that indicates which block was read by consistent read – the problem posed by the OP.  What happened, which block was read by consistent read?

Before we forget, roll back the INSERT in session 1:

ROLLBACK; 

A search found this Oracle-L post that lead to another blog article that suggested making the following change and bouncing the database (note: do not change hidden Oracle parameters in a production environment without the consent of Oracle Support):

ALTER SYSTEM SET "_TRACE_PIN_TIME"=1 SCOPE=SPFILE;

Go through the same process as outlined above of connecting the sessions, creating the table, and making certain that hard parses do not confuse the output.

In session 2 (the SYS session), flush the buffer cache, determine which blocks are in the buffer cache (execute a couple of times until the output stabilizes):

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT
  TS#,
  FILE#,
  DBARFIL,
  DBABLK,
  STATE
FROM
  X$BH
WHERE
  STATE<>0
ORDER BY
  TS#,
  FILE#,
  DBABLK;

/

/

Just as shown earlier in this article, I again received the following output:

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1 

Quickly switch to session 1 and execute the following (prepare to switch back to session 2):

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'T4_NO_INDEX2';
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

INSERT INTO T4 VALUES(2,NULL,NULL);

In session 2 (the SYS session) check the contents of the buffer cache:

/ 

The output that I received follows (note that the numbers to the right of the lines correspond to the order in which the physical block reads were unpinned, as it appeared in the trace file that follows):

 TS#  FILE#    DBARFIL     DBABLK  STATE
---- ------ ---------- ---------- ------
   0      1          1       2016      1
   0      1          1       2017      1
   2      3          3        192      1  *  3
   2      3          3      16029      1  *  1
   5      5          5        128      1  *  X
   5      5          5        427      1  *  2
   5      5          5        428      1  *  2 

A portion of the 10200/10046 trace file follows (with the unpinning order numbered):

PARSING IN CURSOR #367514528 len=34 dep=0 uid=62 oct=2 lid=62 tim=21584856863 hv=544833741 ad='7ffb77d8140' sqlid='96mny1hh7m06d'
INSERT INTO T4 VALUES(2,NULL,NULL)
END OF STMT
PARSE #367514528:c=0,e=489,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=21584856863
WAIT #367514528: nam='db file sequential read' ela= 156 file#=5 block#=128 blocks=1 obj#=71114 tim=21584857108  X ****
pin ktswh28: ktsgsp dba 0x1400080:4 time 110020667                                                              X Pin
WAIT #367514528: nam='db file scattered read' ela= 935 file#=5 block#=427 blocks=32 obj#=71114 tim=21584858155  2 ****
pin ktswh72: ktsbget dba 0x14001ab:1 time 110021704                                                             2 Pin
WAIT #367514528: nam='db file sequential read' ela= 132 file#=3 block#=192 blocks=1 obj#=0 tim=21584858344      3 ****
pin ktuwh59: ktugus:ktubnd dba 0xc000c0:25 time 110021892                                                       3 Pin
WAIT #367514528: nam='db file sequential read' ela= 130 file#=3 block#=16029 blocks=1 obj#=0 tim=21584858538    1 ****
pin ktuwh09: ktugfb dba 0xc03e9d:26 time 110022085                                                              1 Pin
pin release        18 ktuwh09: ktugfb dba 0xc03e9d:26                                                           1 Unpin
pin release       428 ktswh72: ktsbget dba 0x14001ab:1                                                          2 Unpin
pin release       246 ktuwh59: ktugus:ktubnd dba 0xc000c0:25                                                    3 Unpin
EXEC #367514528:c=0,e=1731,p=35,cr=1,cu=3,mis=0,r=1,dep=0,og=1,plh=0,tim=21584858629
STAT #367514528 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=35 pw=0 time=1703 us)'
WAIT #367514528: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=21584858681 

In the above, it appears that block 128 was read from file #5, was pinned, and then was still pinned when the EXEC and STAT lines were written to the trace file.  I do not claim to fully understand what appears above – maybe someone can confirm that in fact block 128 was still pinned.  Let’s determine the header block for table T4:

SELECT
  HEADER_FILE,
  HEADER_BLOCK
FROM
  DBA_SEGMENTS
WHERE
  SEGMENT_NAME='T4';

HEADER_FILE HEADER_BLOCK
----------- ------------
          5          128 

Block 128 in file #5 is the segment header block for the T4 test table. I suspect that it is the segment header block that is accounting for the one consistent read in the EXEC and STAT lines. My best guess is that the session is re-reading that block while it is still pinned, and is thus considering that read as a consistent get, even though the session already has the block pinned. That re-read after being pinned could also explain why a 10200 trace would not show that consistent read.

Opinions – or a better explanation?