Pythian Blog: Technical Track

Meaning of "Disk Reads" Values in DBA_HIST_SQLSTAT

by Maris Elsins on Nov 6, 2013 12:00:00 AM

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. [code language="sql"] 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. [/code]
  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). [code language="sql"] 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 [/code] 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. [code language="text" highlight="6-7,19-36"] 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 [/code]
  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. [code language="sql"] 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 [/code]
Topics: MySQL Technical Track

No Comments Yet

Let us know what you think

See all

See all

Subscribe by email
Follow us
Love Your Data
Pythian Logo

© 2024 All rights reserved.