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?
Hi Charles,
a bit late to the party – but here’s some additional info:
1. Your guess that the session is re-reading the block while it is still pinned: Doesn’t sound very plausible, because that is exactly the point of a buffer being pinned: You don’t need a logical I/O to access that buffer again, so I would be surprised if Oracle accounted such a buffer re-visit as “consistent get”
2. It looks like that access to the undo segment header (where the transaction slot for the transaction is located) is recorded as “consistent get” but not shown in the 10200 trace. So my best guess 🙂 is that the consistent get in question for that particular case is the access to the undo segment header
3. Another good additional source for information in such cases is to delta the session statistics – it will give additional clues about what type of activity that is covered by the session statistics has been performed.
Randolf
Hi Randolf,
Thank you for the additional information. The day before I posted this article I was curious to know if the consistent get was undo related, but I did not make any progress confirming that it was an undo block that was responsible for the consistent get. As an experiment I set the undo related events 10201, 10220, 10221 as mentioned here: http://www.juliandyke.com/Diagnostics/Events/EventReference.html#10201
I did not obtain any additional information from the enabled additional events. I might experiment a bit with the session statistics – thank you for the idea.