10200 Trace Shows Consistent Reads, but Not All Consistent Reads

4102011

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

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

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:

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

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:

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:

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

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

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

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:

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.

Actions

Information

2 responses

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.

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.

Hints for Posting Code Sections in Comments

********************
When the spacing of text in a comment section is important for readability (execution plans, PL/SQL blocks, SQL, SQL*Plus output, etc.) please use a <pre> tag before the code section and a </pre> tag after the code section:
<pre>

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;
TODAY
---------
01-MAR-12

</pre>
********************
When posting test case samples, it is much easier for people to reproduce the test case when the SQL*Plus line prefixes are not included - if possible, please remove those line prefixes. This:

SELECT
SYSDATE TODAY
FROM
DUAL;

Is easier to execute in a test case script than this:

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;

********************
Greater than and Less than signs in code sections are often interpretted as HTML formatting commands. Please replace these characters in the code sections with the HTML equivalents for these characters: