This blog post was originally released on Pythian blog

This post relates to my previous writing on mining the AWR. I noticed that it’s very easy to misinterpret the DISK_READS_TOTAL and DISK_READS_DELTA columns in DBA_HIST_SQLSTAT. Let’s see what the documentation says:

  • DISK_READS_TOTAL - Cumulative number of disk reads for this child cursor
  • DISK_READS_DELTA - Delta number of disk reads for this child cursor

You might think it’s clear enough and that’s exactly what I thought too. The number of disk reads is the number of IO requests to the storage. But is it really true?

I started suspecting something was not right after using my own awr_sqlid_perf_trend.sql script (see more details on this script here. I noticed the DISK_READS_DELTA values were too close to BUFFER_GETS_DELTA values for queries that use full table scans, which are normally executed using multi-block IO requests to the storage. I was expecting disk reads to be at least two times lower than the buffer gets, but it was something closer to 90% in a few cases. So was I looking at the number of IO requests or the number of blocks read from disks? The best way to find it out was a test case.

The following testing was done in an 11.2.0.3 database:

  1. I created a new AWR snapshot and enabled tracing for my session. I made sure the db_file_multiblock_read_count parameter was set to a high value and then executed a SQL that was forced to use a full table scan (FTS) to read the data from disks. Another AWR snapshot was taken after that.

    SQL> alter session set tracefile_identifier='TEST1';
Session altered.

SQL> show parameter multiblock
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count        integer     26

SQL> alter system set db_file_multiblock_read_count=128;
System altered.

SQL> show parameter multiblock
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count        integer     128

SQL> exec dbms_workload_repository.create_snapshot();
PL/SQL procedure successfully completed.

SQL> alter session set max_dump_file_size=unlimited;
Session altered.

SQL> alter system set events '10046 trace name context forever, level 12';
System altered.

SQL> select /*+ full(a) */ count(I_DATA) from tpcc.item;
COUNT(I_DATA)
-------------
       100000

SQL> exec dbms_workload_repository.create_snapshot();
PL/SQL procedure successfully completed.

  2. I found the sql_id in the trace file (it was 036c3dmx2u3x9) and executed the awr_sqlid_perf_trend.sql to find out how many disk reads were made (I removed a few columns that are not important here).

    SQL> @awr_sqlid_perf_trend.sql 036c3dmx2u3x9 20 0.001

 INST TIME                BUFFER_GETS_1EXEC  DISK_READS_1EXEC DIRECT_WRITES_1EXEC  EXECUTIONS ROWS_PROCESSED_1EXEC
----- ------------------- ----------------- ----------------- ------------------- ----------- --------------------
    1 24.10.2013 03:53:06          1092.000          1073.000                .000           1                1.000

    It was a single execution and look at the numbers! 1073 disk reads and 1092 buffer gets. Could it be the DISK_READS_DELTA is actually the number of blocks read from disks? I need to check the raw trace file to find out.

  3. I found the following lines in the trace file. I’ve highlighted all lines that report waits on physical IO. Notice the first query (sqlid=’96g93hntrzjtr’) is a recursive SQL (dep=1) for the query I executed (sqlid=’036c3dmx2u3x9’, and it was executed during the PARSE phase “PARSE #7904600” for my query. There were few other recursive statements, but they didn’t do any disk IOs (you’ll have to trust me here). It’s good to know the lines are written to the trace file after the corresponding event completes, this is why the recursive statements of the parse phase are reported before the line describing the whole parse operation.

    PARSING IN CURSOR #25733316 len=210 dep=1 uid=0 oct=3 lid=0 tim=1382576068532471 hv=864012087 ad='3ecd4b88' sqlid='96g93hntrzjtr'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
PARSE #25733316:c=0,e=240,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=3,plh=0,tim=1382576068532470
EXEC #25733316:c=0,e=404,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=3,plh=2239883476,tim=1382576068532919
WAIT #25733316: nam='db file sequential read' ela= 885 file#=1 block#=64857 blocks=1 obj#=427 tim=1382576068533833
WAIT #25733316: nam='db file sequential read' ela= 996 file#=1 block#=58629 blocks=1 obj#=425 tim=1382576068534935
FETCH #25733316:c=0,e=2092,p=2,cr=3,cu=0,mis=0,r=1,dep=1,og=3,plh=2239883476,tim=1382576068535022
STAT #25733316 id=1 cnt=1 pid=0 pos=1 obj=425 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=2 pw=0 time=2079 us)'
STAT #25733316 id=2 cnt=1 pid=1 pos=1 obj=427 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=1 pw=0 time=989 us)'
CLOSE #25733316:c=0,e=58,dep=1,type=3,tim=1382576068535146
=====================
PARSING IN CURSOR #7904600 len=50 dep=0 uid=0 oct=3 lid=0 tim=1382576068535413 hv=4197257129 ad='3618a2a4' sqlid='036c3dmx2u3x9'
select /*+ full(a) */ count(I_DATA) from tpcc.item
END OF STMT
PARSE #7904600:c=8001,e=12985,p=2,cr=19,cu=0,mis=1,r=0,dep=0,og=1,plh=1537583476,tim=1382576068535411
EXEC #7904600:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1537583476,tim=1382576068535500
WAIT #7904600: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1382576068535530
WAIT #7904600: nam='db file sequential read' ela= 1960 file#=4 block#=113050 blocks=1 obj#=65019 tim=1382576068537566
WAIT #7904600: nam='direct path read' ela= 1203 file number=4 first dba=113051 block cnt=5 obj#=65019 tim=1382576068539309
WAIT #7904600: nam='direct path read' ela= 1531 file number=4 first dba=123392 block cnt=8 obj#=65019 tim=1382576068541567
WAIT #7904600: nam='direct path read' ela= 1047 file number=4 first dba=123401 block cnt=15 obj#=65019 tim=1382576068542719
WAIT #7904600: nam='direct path read' ela= 1081 file number=4 first dba=123417 block cnt=15 obj#=65019 tim=1382576068543895
WAIT #7904600: nam='direct path read' ela= 956 file number=4 first dba=123433 block cnt=15 obj#=65019 tim=1382576068544997
WAIT #7904600: nam='direct path read' ela= 950 file number=4 first dba=123449 block cnt=15 obj#=65019 tim=1382576068546096
WAIT #7904600: nam='direct path read' ela= 1168 file number=4 first dba=123465 block cnt=15 obj#=65019 tim=1382576068547425
WAIT #7904600: nam='direct path read' ela= 1151 file number=4 first dba=123481 block cnt=15 obj#=65019 tim=1382576068548784
WAIT #7904600: nam='direct path read' ela= 1279 file number=4 first dba=123497 block cnt=15 obj#=65019 tim=1382576068550229
WAIT #7904600: nam='direct path read' ela= 9481 file number=4 first dba=123522 block cnt=126 obj#=65019 tim=1382576068559912
WAIT #7904600: nam='direct path read' ela= 6872 file number=4 first dba=123650 block cnt=126 obj#=65019 tim=1382576068566997
WAIT #7904600: nam='direct path read' ela= 5562 file number=4 first dba=123778 block cnt=126 obj#=65019 tim=1382576068573516
WAIT #7904600: nam='direct path read' ela= 7524 file number=4 first dba=123906 block cnt=126 obj#=65019 tim=1382576068582195
WAIT #7904600: nam='direct path read' ela= 5858 file number=4 first dba=124034 block cnt=126 obj#=65019 tim=1382576068589263
WAIT #7904600: nam='direct path read' ela= 5326 file number=4 first dba=124162 block cnt=126 obj#=65019 tim=1382576068595750
WAIT #7904600: nam='direct path read' ela= 5788 file number=4 first dba=124290 block cnt=126 obj#=65019 tim=1382576068602627
WAIT #7904600: nam='direct path read' ela= 2446 file number=4 first dba=124418 block cnt=70 obj#=65019 tim=1382576068607337
FETCH #7904600:c=4000,e=73444,p=1071,cr=1073,cu=0,mis=0,r=1,dep=0,og=1,plh=1537583476,tim=1382576068608996
STAT #7904600 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1073 pr=1071 pw=0 time=73444 us)'
STAT #7904600 id=2 cnt=100000 pid=1 pos=1 obj=65019 op='TABLE ACCESS FULL ITEM (cr=1073 pr=1071 pw=0 time=49672 us cost=198 size=3900000 card=100000)'
WAIT #7904600: nam='SQL*Net message from client' ela= 148 driver id=1650815232 #bytes=1 p3=0 obj#=65019 tim=1382576068609235
FETCH #7904600:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1537583476,tim=1382576068609261
WAIT #7904600: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=65019 tim=1382576068609276
WAIT #7904600: nam='SQL*Net message from client' ela= 940 driver id=1650815232 #bytes=1 p3=0 obj#=65019 tim=1382576068610226
CLOSE #7904600:c=0,e=17,dep=0,type=0,tim=1382576087713173

  4. The next task was to count the “blocks” for db file sequential reads and “block cnt” for direct path reads. The recursive SQL (96g93hntrzjtr) read 2 data blocks from disks and the main SQL (036c3dmx2u3x9) read 1071 data blocks from disks. The total number is 1073! Hey, this is exactly what DISK_READS_DELTA (DISK_READS_1EXEC in the script outputs above) reported - so it’s the number of data blocks, and not the number of IO requests!

The investigation resulted in two obvious conclusions:

  • DISK_READS_TOTAL and DISK_READS_DELTA in DBA_HIST_SQLSTAT report the number of blocks read from disks.
  • The query statistics in DBA_HIST_SQLSTAT also include the data from execution of the recursive statements.

P.S. Later I found another column - DBA_HIST_SQLSTAT.PHYSICAL_READ_REQUESTS_DELTA - that was introduced in 11.2 along with a large number of additional columns. PHYSICAL_READ_REQUESTS_DELTA and PHYSICAL_READ_REQUESTS_TOTAL represent the number of IO requests that were executed. You can compare the numbers by counting the highlighted rows above to the value I found in DBA_HIST_SQLSTAT below.

SQL> select DISK_READS_DELTA, PHYSICAL_READ_REQUESTS_DELTA from dba_hist_sqlstat where sql_id='036c3dmx2u3x9';

DISK_READS_DELTA PHYSICAL_READ_REQUESTS_DELTA
---------------- ----------------------------
            1073                           20