So far, all the examples of SQL Tracing that I have provided in this series are for SELECT statements. (By "DML" I mean INSERT / UPDATE / DELETE statements other than SELECT statements)
Examples of the tkprof outputs are :
In all these cases the statistics (disk reads and query {i.e. consistent} gets) are reported against the FETCH call, not the EXECUTE call. ("rows" is 1 in all the above cases because we are always retrieving a single value, a count or a min value).
Let's see what happens when we execute an UPDATE (which does not update an index entries).
Here, the UPDATE required a Full Table Scan as we can see in the Row Source Operations. This required 579 consistent gets ("cr" in Row Source Operations and "query" in the Statistics). However, the difference we now see is that the Statistics are reported against the *EXECUTE* Phase, not the FETCH phase.
The actual retrieval of blocks for the UPDATE (all the blocks since no index was used) is not reported as FETCH call statistics but EXECUTE call statistics. Thereafter, we see 4 blocks retrieved in "current" mode for the 3 rows that were updated. Does the trace file show which 4 blocks were retrieved in "current" mode ? Unfortunately, no it does not. The SQL Trace file only shows wait events if blocks were retrieved from disk but it doesn't identify and differentiate "consistent" and "current" gets. That is why even the Row Source Operations reports "cr" being "consistent reads".
Another thing to note is that Oracle doesn't report any physical writes ("pw=0") because disk writes for normal DML (other than Direct Path INSERTs) is deferred to be executed by DBWR later. So, the process doing the UPDATE does not necessarily have to do writes.
(What are "current" gets ? "Current" gets are when Oracle needs to retrieve the most current version of a block because it needs to update the block).
Let my try another UPDATE. This time of a single row and where the UPDATE has to update an Indexed column.
(Note : Let's put aside the high COST of 26777 and expected Row Cardinality of 7197952 for the Full Table Scan in the Row Source Operations --- that is the subject of another discussion, which you could see here).
Here we see that the query does not have to do Full Table Scan. There are 4 blocks fetched in "consistent get" mode (reported in "query") and 8 blocks in "current get" mode.
So, here we have a single row being updated, so we'd have a table block updated and two updates to index leaf block(s) (an UPDATE to an index is actual executed as a "soft-delete" of the previous entry and an insert of the new entry). Yet, there are 8 blocks in "current" mode. When updating an Index, Oracle fetches the Root, Branch and Leaf Blocks in "current" mode because it doesn't know in advance if the UPDATE will result in Leaf Block Splits (search my blog for posts on 90-10 and 50-50 splits for an explanation).
Note also that the Row Source Operations or the Trace File will *not* show which Index(es) needed to be updated.
Remember also that when we execute DML, Oracle also has to update one or more Undo Blocks besides the Table and Index blocks.
Let me try a DELETE.
Here, again we see the statistics being reported against the EXECUTE call.
Takeaway : Simple SELECT reports statistics under FETCH calls. INSERT / UPDATE / DELETE operations report statistics under EXECUTE calls.
.
.
.
Examples of the tkprof outputs are :
select count(*) from all_objects_many_list where owner = 'HEMANT' 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.05 44.33 97793 97798 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 1.06 44.34 97793 97798 0 1 select /* second_run */ count(*) from all_objects_many_list where owner = 'HEMANT' 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.96 42.35 97792 97797 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.96 42.35 97792 97797 0 1 select count(*) from all_objects_short_list where owner = 'HEMANT' call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.10 2 2 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.09 140 580 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.01 0.20 142 582 0 1 select /* second_run */ count(*) from all_objects_short_list where owner = 'HEMANT' call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 1 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.00 0.00 0 580 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 0 581 0 1 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
In all these cases the statistics (disk reads and query {i.e. consistent} gets) are reported against the FETCH call, not the EXECUTE call. ("rows" is 1 in all the above cases because we are always retrieving a single value, a count or a min value).
Let's see what happens when we execute an UPDATE (which does not update an index entries).
update all_objects_short_list
set owner = 'HKC'
where owner = 'HEMANT'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.01 0.13 577 579 4 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 0.15 577 579 4 3
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
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE ALL_OBJECTS_SHORT_LIST (cr=579 pr=577 pw=0 time=136182 us)
3 3 3 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=579 pr=577 pw=0 time=135859 us cost=158 size=24 card=3)
Here, the UPDATE required a Full Table Scan as we can see in the Row Source Operations. This required 579 consistent gets ("cr" in Row Source Operations and "query" in the Statistics). However, the difference we now see is that the Statistics are reported against the *EXECUTE* Phase, not the FETCH phase.
The actual retrieval of blocks for the UPDATE (all the blocks since no index was used) is not reported as FETCH call statistics but EXECUTE call statistics. Thereafter, we see 4 blocks retrieved in "current" mode for the 3 rows that were updated. Does the trace file show which 4 blocks were retrieved in "current" mode ? Unfortunately, no it does not. The SQL Trace file only shows wait events if blocks were retrieved from disk but it doesn't identify and differentiate "consistent" and "current" gets. That is why even the Row Source Operations reports "cr" being "consistent reads".
Another thing to note is that Oracle doesn't report any physical writes ("pw=0") because disk writes for normal DML (other than Direct Path INSERTs) is deferred to be executed by DBWR later. So, the process doing the UPDATE does not necessarily have to do writes.
(What are "current" gets ? "Current" gets are when Oracle needs to retrieve the most current version of a block because it needs to update the block).
Let my try another UPDATE. This time of a single row and where the UPDATE has to update an Indexed column.
update all_objects_many_list
set created=sysdate
where rowid =
(select rowid from all_objects_many_list where rownum < 2)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 0 0 0
Execute 1 0.00 0.01 0 4 8 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.03 0 4 8 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
---------- ---------- ---------- ---------------------------------------------------
0 0 0 UPDATE ALL_OBJECTS_MANY_LIST (cr=4 pr=0 pw=0 time=434 us)
1 1 1 TABLE ACCESS BY USER ROWID ALL_OBJECTS_MANY_LIST (cr=4 pr=0 pw=0 time=100 us cost=1 size=20 card=1)
1 1 1 COUNT STOPKEY (cr=3 pr=0 pw=0 time=77 us)
1 1 1 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=3 pr=0 pw=0 time=60 us cost=26777 size=86375424 card=7197952)
(Note : Let's put aside the high COST of 26777 and expected Row Cardinality of 7197952 for the Full Table Scan in the Row Source Operations --- that is the subject of another discussion, which you could see here).
Here we see that the query does not have to do Full Table Scan. There are 4 blocks fetched in "consistent get" mode (reported in "query") and 8 blocks in "current get" mode.
So, here we have a single row being updated, so we'd have a table block updated and two updates to index leaf block(s) (an UPDATE to an index is actual executed as a "soft-delete" of the previous entry and an insert of the new entry). Yet, there are 8 blocks in "current" mode. When updating an Index, Oracle fetches the Root, Branch and Leaf Blocks in "current" mode because it doesn't know in advance if the UPDATE will result in Leaf Block Splits (search my blog for posts on 90-10 and 50-50 splits for an explanation).
Note also that the Row Source Operations or the Trace File will *not* show which Index(es) needed to be updated.
Remember also that when we execute DML, Oracle also has to update one or more Undo Blocks besides the Table and Index blocks.
Let me try a DELETE.
delete all_objects_short_list
where owner = 'HKC'
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 579 4 3
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 579 4 3
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
---------- ---------- ---------- ---------------------------------------------------
0 0 0 DELETE ALL_OBJECTS_SHORT_LIST (cr=579 pr=0 pw=0 time=2448 us)
3 3 3 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=579 pr=0 pw=0 time=2195 us cost=158 size=24 card=3)
Here, again we see the statistics being reported against the EXECUTE call.
Takeaway : Simple SELECT reports statistics under FETCH calls. INSERT / UPDATE / DELETE operations report statistics under EXECUTE calls.
.
.
.
No comments:
Post a Comment