V$FILESTAT is Wrong?

February 13, 2010

While describing file monitoring in chapter 8 of the Expert Oracle Practices book, one of the interesting items that Randolf and I mentioned was an apparent inconsistency in V$FILESTAT, but we then went on to explain why the inconsistency is present.  To see this inconsistency, I will bounce an 11.1.0.7 database, execute a couple of SQL statements to force physical reads (the SQL statements are not important to this experiment), and then check the current values in V$FILESTAT.  The following script will be executed to show the V$FILESTAT statistics and also the statistics from V$FILE_HISTOGRAM:

spool fileactivity.txt
set linesize 160
set pagesize 2000

SELECT
  FILE#,
  PHYRDS,
  PHYWRTS,
  PHYBLKRD,
  PHYBLKWRT,
  SINGLEBLKRDS,
  READTIM,
  WRITETIM,
  SINGLEBLKRDTIM,
  AVGIOTIM,
  LSTIOTIM,
  MINIOTIM,
  MAXIORTM,
  MAXIOWTM
FROM
  V$FILESTAT
WHERE
  FILE# IN (6,7);

SELECT
  FILE#,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1,SINGLEBLKRDS,0)) MILLI1,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2,SINGLEBLKRDS,0)) MILLI2,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4,SINGLEBLKRDS,0)) MILLI4,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,8,SINGLEBLKRDS,0)) MILLI8,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,16,SINGLEBLKRDS,0)) MILLI16,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,32,SINGLEBLKRDS,0)) MILLI32,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,64,SINGLEBLKRDS,0)) MILLI64,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,128,SINGLEBLKRDS,0)) MILLI128,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,256,SINGLEBLKRDS,0)) MILLI256,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,512,SINGLEBLKRDS,0)) MILLI512,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1024,SINGLEBLKRDS,0)) MILLI1024,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2048,SINGLEBLKRDS,0)) MILLI2048,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4096,SINGLEBLKRDS,0)) MILLI4096
FROM
  V$FILE_HISTOGRAM
WHERE
  FILE# IN (6,7)
GROUP BY
  FILE#
ORDER BY
  FILE#;

spool off

So, what is the inconsistency?  Here is the output of the above SQL statements:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6     13       9       13         9            2      25        0              8        0        0        0        9        0
    7  27983   39608   138431    107305        13693    6073  3702202           1719        0        0        0       36      447 

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      0      0      0       0       0       2        0        0        0         0         0         0
    7  12816    222     68     79     108     304      80       12        3        1         0         0         0

So, what is the inconsistency?  Let’s ignore file #7 for a moment and take a look at file #6.  In the above output, the SINGLEBLKRDS column indicates that there were 2 single block reads of file #6, and the SINGLEBLKRDTIM column indicates that the two single block reads required 8 centiseconds (0.08 seconds).  The V$FILE_HISTOGRAM output shows that there were two block reads of file #6 that completed in the range of 32ms (0.032 seconds) and 63.99999ms (0.06399999 seconds).  Those two sets of statistics are consistent, so where is the inconsistency?

Let’s check a couple of the statistics from the output of V$FILESTAT and check the definitions from the documentation:

 2 SINGLEBLKRDS - Number of single block reads
13 PHYBLKRD - Number of physical blocks read
13 PHYRDS - Number of physical reads done

Is the inconsistency clear now?  If 2 of the 13 blocks that were read from the tablespace were read by single block reads, that means that 11 of the blocks were read by something other than single block reads.  Single block reads, by definition, read one block during each read request, so 2 of the 13 physical reads were read by single block reads and that means 11 of the read request were something other than single block reads.  That means 11 blocks were read in 11 read calls by something other than single block reads – were they read by multi-block reads?  Think about that for a moment.

Do those columns really mean something other than what the documentation states?  Is this another bug in the V$FILESTAT view?  Bugs?  From Metalink:

• V$FILESTAT WRITETIM Shows Very High Values [ID 168930.1]
• Bug 4942939 – Very high values for ODM/ASM readtim/writetim in V$FILESTAT [ID 4942939.8]
• Bug 2481002 – V$FILESTAT.AVGIOTIM is incorrect [ID 2481002.8]

All of the above bugs were fixed prior to Oracle 11.1.0.7.  Maybe the next step is to look for more information about V$FILESTAT:

• Metalink: How to Check Oracle Datafile I/O With V$FILESTAT [ID 1050735.6]
• Discussion on David Aldridge’s site
• Oracle Wait Event Tuning: High Performance with Wait Event Interface Analysis book
• Oracle Performance Tuning for 10gR2
• Oracle Wait Interface: a Practical Guide to Performance Diagnostics & Tuning
• Secrets of the Oracle Database
• Troubleshooting Oracle Performance
• Expert Oracle Database 11g Administration
• Expert Oracle Practices: Oracle Database Administration from the Oak Table

OK, now that you are back from reading the above links, how is it possible to read 11 blocks in a total of 11 read requests when none of the 11 reads are single block reads?  Maybe another script will help answer that question:

CONNECT SYS/SYSPASSWORD AS SYSDBA

CREATE OR REPLACE TRIGGER STARTUP_10046_TRACE AFTER STARTUP ON DATABASE
BEGIN
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET MAX_DUMP_FILE_SIZE=UNLIMITED';
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET TIMED_STATISTICS=TRUE';
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
END;
/

SHUTDOWN IMMEDIATE;

STARTUP

spool fileactivitystartup.txt
set linesize 160
set pagesize 2000

SELECT
  FILE#,
  PHYRDS,
  PHYWRTS,
  PHYBLKRD,
  PHYBLKWRT,
  SINGLEBLKRDS,
  READTIM,
  WRITETIM,
  SINGLEBLKRDTIM,
  AVGIOTIM,
  LSTIOTIM,
  MINIOTIM,
  MAXIORTM,
  MAXIOWTM
FROM
  V$FILESTAT
WHERE
  FILE# IN (6,7);

SELECT
  FILE#,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1,SINGLEBLKRDS,0)) MILLI1,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2,SINGLEBLKRDS,0)) MILLI2,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4,SINGLEBLKRDS,0)) MILLI4,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,8,SINGLEBLKRDS,0)) MILLI8,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,16,SINGLEBLKRDS,0)) MILLI16,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,32,SINGLEBLKRDS,0)) MILLI32,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,64,SINGLEBLKRDS,0)) MILLI64,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,128,SINGLEBLKRDS,0)) MILLI128,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,256,SINGLEBLKRDS,0)) MILLI256,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,512,SINGLEBLKRDS,0)) MILLI512,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1024,SINGLEBLKRDS,0)) MILLI1024,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2048,SINGLEBLKRDS,0)) MILLI2048,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4096,SINGLEBLKRDS,0)) MILLI4096
FROM
  V$FILE_HISTOGRAM
WHERE
  FILE# IN (6,7)
GROUP BY
  FILE#
ORDER BY
  FILE#;

spool off

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

DROP TRIGGER STARTUP_10046_TRACE;

The output of the above script follows:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6      4       1        4         1            1       2        0              2        0        2        0        2        0
    7      4       1        4         1            1       2        0              2        0        2        0        2        0

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      0      0      0       0       1       0        0        0        0         0         0         0
    7      0      0      0      0       0       1       0        0        0        0         0         0         0

Again we see the inconsistency SINGLEBLKRDS = 1, PHYBLKRD = 4, PHYRDS = 4 – therefore there were 3 blocks read in 3 physical reads that were not single block reads.  How is this possible?  Maybe we should check the trace files?  The trace file for the session performing the STARTUP command contains the following:

...
WAIT #5: nam='direct path read' ela= 17 file number=1 first dba=1 block cnt=1 obj#=369 tim=7842773692
WAIT #5: nam='direct path read' ela= 11153 file number=2 first dba=1 block cnt=1 obj#=369 tim=7842784875
WAIT #5: nam='direct path read' ela= 19974 file number=3 first dba=1 block cnt=1 obj#=369 tim=7842804886
WAIT #5: nam='direct path read' ela= 1 file number=4 first dba=1 block cnt=1 obj#=369 tim=7842804932
WAIT #5: nam='direct path read' ela= 1 file number=5 first dba=1 block cnt=1 obj#=369 tim=7842804959
WAIT #5: nam='direct path read' ela= 1 file number=6 first dba=1 block cnt=1 obj#=369 tim=7842804981
...

The trace file for LGWR contains the following:

...
WAIT #0: nam='direct path read' ela= 5 file number=1 first dba=1 block cnt=1 obj#=-1 tim=7842890656
WAIT #0: nam='direct path read' ela= 1 file number=2 first dba=1 block cnt=1 obj#=-1 tim=7842890694
WAIT #0: nam='direct path read' ela= 1 file number=3 first dba=1 block cnt=1 obj#=-1 tim=7842890726
WAIT #0: nam='direct path read' ela= 1 file number=4 first dba=1 block cnt=1 obj#=-1 tim=7842890756
WAIT #0: nam='direct path read' ela= 0 file number=5 first dba=1 block cnt=1 obj#=-1 tim=7842890801
WAIT #0: nam='direct path read' ela= 1 file number=6 first dba=1 block cnt=1 obj#=-1 tim=7842890832
...

Let’s see: 1 single block read in the SYS session, 1 single block read in the LGWR trace file, therefore 1=2?  That makes complete sense.  What you probably will not find in the documentation is a statement that the SINGLEBLKRDS column of V$FILESTAT and the statistics in V$FILE_HISTOGRAM correspond to the “db file sequential read” wait event, and do not include statistics for single block reads associated with the “direct path read” wait event.  (At least in this case.)

What about Oracle 11.2.0.1?  Here is the output of the two SQL statements after executing a couple of queries following a database bounce:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6     18      14       18        14           18       2        0              2        0        0        0        1        0
    7  57047  223616   535618    495511        42430   11588  5689141           4838        0        0        0      218      279

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      1      0      0       1       0       0        0        0        0         0         0         0
    7  39775    186    342    991     684     235     107       79        7        3         1         2         2

From the above:

18 SINGLEBLKRDS - Number of single block reads
18 PHYBLKRD - Number of physical blocks read
18 PHYRDS - Number of physical reads done

Don’t you hate it when Oracle is self-consistent, and yet at the same time not self-consistent?  One has to wonder if a bug was corrected regarding the counting of single block reads, or if direct path reads are no longer performed when the database is opened.  But, we have another problem – look closely at the output from V$FILE_HISTOGRAM.