Continuing with the same table as in the previous example, but with the addition of
(a) Statistics on the table
(b) An Index on the CREATED column
Let's examine the tkprof output first.
The first query (the count(*) did a Full Table Scan and read 7.198million rows reading 97,793 blocks from disk and 97,798 consistent gets. The "pr" count is the count of Physical Reads and the "cr" is the count of Logical Reads (there are no "cur" -- current mode block gets -- in this example). The Logical Reads count includes the Physical Reads count, do not attempt to add them.
During a Full Table Scan, Oracle may have to read the Segment Header and/or additional blocks to read the Extent Map. Thus, some blocks may be read multiple times, the first reading may have been from Disk, subsequent readings from the Buffer Cache.
In this case, the Segment Header is identified as :
and identified from the trace file as the 'db file sequential read' (single block read) as the first disk read before the 'direct path reads':
Note the underlined 'db file sequential read' of block#=330 from file number=4.
The third query also does a Full Table Scan but doesn't show a 'db file sequential read' wait for this block. This Segment Header block was persisted in the Buffer Cache. All the other blocks of the table read via 'direct path read' in the first Full Table Scan query were not persisted in the Buffer Cache.
The raw trace file in this case will NOT show the individual Logical Reads, only the Physical Reads when there are Waits. However, the Logical Reads are visible in the STAT lines in the raw trace file. These STAT lines for the first Full Table Scan query are visible as :
These STAT lines show
(a) The Object ID for the Table being 35014
(b) The estimated COST for the Execution Plan was 26,777 (shown as "cost=").
(c) The estimated CARDINALITY (Number of Rows from the step in the Execution Plan was 7,197,952 (shown as "card=")
(d) The elapsed time for the Full Table Scan was 48.481million microseconds.
Note : Particularly on short-running steps in an Execution Plan and rounding of time, there may be some mismatch between the time reported individually in the raw trace and tkprof and the actual time.
If we look at the STAT line for the third query doing a Full Table Scan
we note that the second Full Table Scan took 17.475million microseconds. This is much less time than the first Full Table Scan (48.481million). Thus, we can see that there was some impact of caching either in the Storage Cache or Server / FileSystem Cache which enabled these Disk Reads to be faster.
Note the difference in the "cost=" and "size=" values between the first Full Table Scan and the second Full Table Scan. The first Full Table Scan had cost=26,777 and size=0. The second Full Table Scan had cost=26,854 and size=57,583,616. The additional "size" and "cost" in the second Full Table Scan is for reading the actual values in the "CREATED" column. The first Full Table Scan only had to count the number of rows and did not have to return any column values. The second query had to interpret the rows and return the "CREATED" values. This is evident if we see the difference in the Explain Plans and note the "BYTES"
Note how the query on MIN(CREATED), MAX(CREATED) shows that it returns 54million bytes (reading the CREATED column values for all the rows) and, therefore, has a higher Cost.
The Full Table Scans are executed as 'direct path read' operations and *not* reads from the database instance Buffer Cache in the SGA. These Direct Reads are a result of the "serial direct read" behaviour of 11g used for large tables --as noted in my previous blog post, this table is larger than the Buffer Cache. Had it been a small table (or pre-11g), the reads would have been executed with 'db file scattered read' waits and loaded into the Buffer Cache and it is possible that some of the blocks may have been present in the Buffer Cache for the third query.
The second query, using an Index on the CREATED column did 3 block reads as 'db file sequential read'.
The three single block reads (Root, Branch, Leaf) for object 35037 (the Index) are from file=1 which happens to be the SYSTEM tablespace.
tkprof does not show this information about the index being in the different (actually wrong !) Tablespace. Only a reading of the trace file identifies this. There are 3 blocks (Root, Branch, Leaf) to be read and the BLEVEL indicates this. Block 61217 is the block immediately after the Segment Head Block (61216). Block 63109 is a Branch Block and Block 61218 is a Leaf Block. This query was fully satisfied from the Index alone and didn't have to read any Table blocks.
.
.
.
(a) Statistics on the table
(b) An Index on the CREATED column
SQL> select count(*) from all_objects_many_list; COUNT(*) ---------- 7197952 SQL> SQL> select min(created) from all_objects_many_list; MIN(CREAT --------- 28-AUG-11 SQL> SQL> select min(created), max(created) from all_objects_many_list; MIN(CREAT MAX(CREAT --------- --------- 28-AUG-11 15-NOV-15 SQL> SQL>
Let's examine the tkprof output first.
[oracle@ora11204 Hemant]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2982.trc QRYS_22NOV.PRF aggregate=NO
TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 22 17:44:13 2015
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
[oracle@ora11204 Hemant]$
SQL ID: cwdmaym4gk0y2 Plan Hash: 2662061148
select count(*)
from
all_objects_many_list
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1.79 34.67 97793 97798 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.79 34.70 97793 97798 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=97798 pr=97793 pw=0 time=34677183 us)
7197952 7197952 7197952 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97793 pw=0 time=48480880 us cost=26777 size=0 card=7197952)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
Disk file operations I/O 1 0.00 0.00
db file sequential read 1 0.00 0.00
direct path read 1542 0.20 33.81
SQL*Net message from client 2 0.00 0.00
********************************************************************************
SQL ID: 72fjkwbds0wxf Plan Hash: 3190284407
select min(created)
from
all_objects_many_list
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 3 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.02 3 3 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=3 pr=3 pw=0 time=17972 us)
1 1 1 INDEX FULL SCAN (MIN/MAX) ALL_OBJ_M_L_CRTD_NDX (cr=3 pr=3 pw=0 time=17950 us cost=3 size=8 card=1)(object id 35037)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file sequential read 3 0.00 0.01
SQL*Net message from client 2 0.00 0.00
********************************************************************************
SQL ID: dcrcwkktu08mv Plan Hash: 2662061148
select min(created), max(created)
from
all_objects_many_list
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1.31 1.27 97792 97797 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.31 1.28 97792 97797 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=97797 pr=97792 pw=0 time=1278898 us)
7197952 7197952 7197952 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=17474658 us cost=26854 size=57583616 card=7197952)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
direct path read 1542 0.00 0.16
SQL*Net message from client 3 14.02 14.02
SQL*Net break/reset to client 2 0.00 0.00
********************************************************************************
The first query (the count(*) did a Full Table Scan and read 7.198million rows reading 97,793 blocks from disk and 97,798 consistent gets. The "pr" count is the count of Physical Reads and the "cr" is the count of Logical Reads (there are no "cur" -- current mode block gets -- in this example). The Logical Reads count includes the Physical Reads count, do not attempt to add them.
During a Full Table Scan, Oracle may have to read the Segment Header and/or additional blocks to read the Extent Map. Thus, some blocks may be read multiple times, the first reading may have been from Disk, subsequent readings from the Buffer Cache.
In this case, the Segment Header is identified as :
SQL> select header_file, header_block from dba_segments where owner = 'HEMANT' and segment_name = 'ALL_OBJECTS_MANY_LIST'; HEADER_FILE HEADER_BLOCK ----------- ------------ 4 330 SQL>
and identified from the trace file as the 'db file sequential read' (single block read) as the first disk read before the 'direct path reads':
PARSING IN CURSOR #140647645766312 len=42 dep=0 uid=87 oct=3 lid=87 tim=1448185243704201 hv=3371762626 ad='6bd59a08' sqlid='cwdmaym4gk0y2' select count(*) from all_objects_many_list END OF STMT PARSE #140647645766312:c=5999,e=33833,p=3,cr=39,cu=0,mis=1,r=0,dep=0,og=1,plh=2662061148,tim=1448185243704195 EXEC #140647645766312:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2662061148,tim=1448185243704326 WAIT #140647645766312: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1448185243704401 WAIT #140647645766312: nam='Disk file operations I/O' ela= 39 FileOperation=2 fileno=4 filetype=2 obj#=35014 tim=1448185243704787 WAIT #140647645766312: nam='db file sequential read' ela= 6291 file#=4 block#=330 blocks=1 obj#=35014 tim=1448185243711101 -------------------------------------------------------------------------------------------------------------------------- WAIT #140647645766312: nam='direct path read' ela= 3626 file number=4 first dba=331 block cnt=13 obj#=35014 tim=1448185243714977 WAIT #140647645766312: nam='direct path read' ela= 5029 file number=4 first dba=345 block cnt=15 obj#=35014 tim=1448185243720084
Note the underlined 'db file sequential read' of block#=330 from file number=4.
The third query also does a Full Table Scan but doesn't show a 'db file sequential read' wait for this block. This Segment Header block was persisted in the Buffer Cache. All the other blocks of the table read via 'direct path read' in the first Full Table Scan query were not persisted in the Buffer Cache.
The raw trace file in this case will NOT show the individual Logical Reads, only the Physical Reads when there are Waits. However, the Logical Reads are visible in the STAT lines in the raw trace file. These STAT lines for the first Full Table Scan query are visible as :
STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=97798 pr=97793 pw=0 time=34677183 us)' STAT #140647645766312 id=2 cnt=7197952 pid=1 pos=1 obj=35014 op='TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97793 pw=0 time=48480880 us cost=26777 size=0 card=7197952)'
These STAT lines show
(a) The Object ID for the Table being 35014
(b) The estimated COST for the Execution Plan was 26,777 (shown as "cost=").
(c) The estimated CARDINALITY (Number of Rows from the step in the Execution Plan was 7,197,952 (shown as "card=")
(d) The elapsed time for the Full Table Scan was 48.481million microseconds.
Note : Particularly on short-running steps in an Execution Plan and rounding of time, there may be some mismatch between the time reported individually in the raw trace and tkprof and the actual time.
If we look at the STAT line for the third query doing a Full Table Scan
STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=97797 pr=97792 pw=0 time=1278898 us)' STAT #140647645766312 id=2 cnt=7197952 pid=1 pos=1 obj=35014 op='TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=17474658 us cost=26854 size=57583616 card=7197952)'
we note that the second Full Table Scan took 17.475million microseconds. This is much less time than the first Full Table Scan (48.481million). Thus, we can see that there was some impact of caching either in the Storage Cache or Server / FileSystem Cache which enabled these Disk Reads to be faster.
Note the difference in the "cost=" and "size=" values between the first Full Table Scan and the second Full Table Scan. The first Full Table Scan had cost=26,777 and size=0. The second Full Table Scan had cost=26,854 and size=57,583,616. The additional "size" and "cost" in the second Full Table Scan is for reading the actual values in the "CREATED" column. The first Full Table Scan only had to count the number of rows and did not have to return any column values. The second query had to interpret the rows and return the "CREATED" values. This is evident if we see the difference in the Explain Plans and note the "BYTES"
SQL> explain plan for select count(*) from all_objects_many_list; Explained. SQL> select * from table(dbms_xplan.display); PLAN_TABLE_OUTPUT ------------------------------------------------------------------------------------------------------------------------------------ Plan hash value: 2662061148 ------------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Cost (%CPU)| Time | ------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 1 | 26777 (1)| 00:05:22 | | 1 | SORT AGGREGATE | | 1 | | | | 2 | TABLE ACCESS FULL| ALL_OBJECTS_MANY_LIST | 7197K| 26777 (1)| 00:05:22 | ------------------------------------------------------------------------------------ 9 rows selected. SQL> explain plan for select min(created), max(created) from all_objects_many_list; Explained. SQL> select * from table(dbms_xplan.display); PLAN_TABLE_OUTPUT ------------------------------------------------------------------------------------------------------------------------------------ Plan hash value: 2662061148 -------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 8 | 26854 (1)| 00:05:23 | | 1 | SORT AGGREGATE | | 1 | 8 | | | | 2 | TABLE ACCESS FULL| ALL_OBJECTS_MANY_LIST | 7197K| 54M| 26854 (1)| 00:05:23 | -------------------------------------------------------------------------------------------- 9 rows selected. SQL>
Note how the query on MIN(CREATED), MAX(CREATED) shows that it returns 54million bytes (reading the CREATED column values for all the rows) and, therefore, has a higher Cost.
The Full Table Scans are executed as 'direct path read' operations and *not* reads from the database instance Buffer Cache in the SGA. These Direct Reads are a result of the "serial direct read" behaviour of 11g used for large tables --as noted in my previous blog post, this table is larger than the Buffer Cache. Had it been a small table (or pre-11g), the reads would have been executed with 'db file scattered read' waits and loaded into the Buffer Cache and it is possible that some of the blocks may have been present in the Buffer Cache for the third query.
The second query, using an Index on the CREATED column did 3 block reads as 'db file sequential read'.
PARSING IN CURSOR #140647645766312 len=46 dep=0 uid=87 oct=3 lid=87 tim=1448185278404154 hv=3682628526 ad='7f931480' sqlid='72fjkwbds0wxf' select min(created) from all_objects_many_list END OF STMT PARSE #140647645766312:c=4999,e=4087,p=1,cr=30,cu=0,mis=1,r=0,dep=0,og=1,plh=3190284407,tim=1448185278404148 EXEC #140647645766312:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3190284407,tim=1448185278404230 WAIT #140647645766312: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=35014 tim=1448185278404299 WAIT #140647645766312: nam='db file sequential read' ela= 5021 file#=1 block#=61217 blocks=1 obj#=35037 tim=1448185278409390 WAIT #140647645766312: nam='db file sequential read' ela= 6886 file#=1 block#=63109 blocks=1 obj#=35037 tim=1448185278416360 WAIT #140647645766312: nam='db file sequential read' ela= 5782 file#=1 block#=61218 blocks=1 obj#=35037 tim=1448185278422228 FETCH #140647645766312:c=0,e=17979,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3190284407,tim=1448185278422304 STAT #140647645766312 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=3 pw=0 time=17972 us)' STAT #140647645766312 id=2 cnt=1 pid=1 pos=1 obj=35037 op='INDEX FULL SCAN (MIN/MAX) ALL_OBJ_M_L_CRTD_NDX (cr=3 pr=3 pw=0 time=17950 us cost=3 size=8 card=1)'
The three single block reads (Root, Branch, Leaf) for object 35037 (the Index) are from file=1 which happens to be the SYSTEM tablespace.
SQL> l 1* select tablespace_name , blevel from dba_indexes where owner = 'HEMANT' and table_name = 'ALL_OBJECTS_MANY_LIST' SQL> / TABLESPACE_NAME BLEVEL ------------------------------ ---------- SYSTEM 2 SQL>
tkprof does not show this information about the index being in the different (actually wrong !) Tablespace. Only a reading of the trace file identifies this. There are 3 blocks (Root, Branch, Leaf) to be read and the BLEVEL indicates this. Block 61217 is the block immediately after the Segment Head Block (61216). Block 63109 is a Branch Block and Block 61218 is a Leaf Block. This query was fully satisfied from the Index alone and didn't have to read any Table blocks.
.
.
.
2 comments:
Hi Hemant, nice blog and informative articles. What are the kind of DB performance problems for which use of DB tracing is essential. What information do we get from traces that we cannot get otherwise?
Deven,
See https://hemantoracledba.blogspot.com/2015/12/trace-files-9-advantages.html
Hemant K Chitale
Post a Comment