I am an Oracle Database Specialist in Singapore.
Please note that this site uses cookies.
21 December, 2015
15 December, 2015
Trace Files -- 10b : More DML Tracing
In the previous post, I demonstrated what a trace of UPDATE or DELETE would show (or not show). For example, although Index blocks need to be updated, we cannot identify how many Index blocks were updated.
Let's now look at an INSERT on an empty table and then gradually populate it with single row inserts.
I started with a table with a precreated segment (else the first row INSERT would have had to create the segment). That count of 30 blocks in current mode is a suprise, isn't it ? Row Source Operations statistics do not tell us why 30 blocks or which 30 blocks (actually buffers in the buffer cache).
This is from the trace file (not the "cu=30" for the EXEC) :
Could the 30 blocks be some maintenance operations ? I leave it to you to conduct your own experiments. Maybe you could post your findings and observations.
Remember : I have used aggregate=NO and sys=NO in my tkprof calls.
Note that there was no disk read. The initial table creation with a segment seems to have created the first extent with blocks in the buffer cache (when I do a block dump later, I can confirm that 5 blocks after the segment header are formatted).
Let me do another INSERT.
I still see 3 blocks in current get mode. It is quite likely that this second row went into the same block as the first row yet the same block has to be 're-got' in current mode. Also, an Undo segment block has to be updated. Note, however, the consistent get also that had to be done. If we could enable more detailed tracing (can we ?) we might be able to identify which block (buffer in the buffer cache) was in consistent get and which were in current get.
What if I have an index on the table ?
Now we have 6 blocks in current mode.
So, with an index present, the current get overhead is greater. Obviously, Oracle has to expend more effort to retrieve and update the index block.
Here, this table with 4 rows has only 1 table block and 1 index (root) block being used. The same block is updated for each fresh INSERT, and each call requires a fresh current get. This means that there will be CPU overhead in repeatedly reading the (same !) block for each fresh INSERT.
Caveat : All 4 rows inserted are inserted by the same session, so they went into the same block. Had I used different sessions for the 4 rows they may have gone into 2 or more blocks because of the way in which ASSM splits INSERT calls across different blocks.
(Note : A GATHER_TABLE_STATS would show a block count of 5 (not 1, not 8) because the first 5 blocks are formatted, as I can confirm with a block dump).
.
.
.
Let's now look at an INSERT on an empty table and then gradually populate it with single row inserts.
SQL> alter session set deferred_segment_creation=FALSE;
Session altered.
SQL> create table small_insert (id_column number, data_column varchar2(25)) tablespace users;
Table created.
SQL> select blocks from user_segments where segment_name = 'SMALL_INSERT';
BLOCKS
----------
8
SQL> exec dbms_session.session_trace_enable(waits=>TRUE);
PL/SQL procedure successfully completed.
SQL> insert into small_insert select 1, 'Row ONE' from dual;
1 row created.
SQL>
SQL ID: fphypk50c6rtw Plan Hash: 1388734953
insert into small_insert select 1, 'Row ONE' from dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.15 0 1 0 0
Execute 1 0.00 0.00 0 2 30 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.15 0 3 30 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 LOAD TABLE CONVENTIONAL (cr=2 pr=0 pw=0 time=592 us)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)
I started with a table with a precreated segment (else the first row INSERT would have had to create the segment). That count of 30 blocks in current mode is a suprise, isn't it ? Row Source Operations statistics do not tell us why 30 blocks or which 30 blocks (actually buffers in the buffer cache).
This is from the trace file (not the "cu=30" for the EXEC) :
PARSING IN CURSOR #139944607436728 len=54 dep=0 uid=87 oct=2 lid=87 tim=1450187439148096 hv=1086545724 ad='7f927750' sqlid='fphypk50c6rtw' insert into small_insert select 1, 'Row ONE' from dual END OF STMT PARSE #139944607436728:c=27996,e=331306,p=0,cr=427,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1450187439148091 EXEC #139944607436728:c=1000,e=628,p=0,cr=2,cu=30,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1450187439148770 STAT #139944607436728 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=2 pr=0 pw=0 time=592 us)' STAT #139944607436728 id=2 cnt=1 pid=1 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)' WAIT #139944607436728: nam='log file sync' ela= 1652 buffer#=1260 sync scn=4725627 p3=0 obj#=-1 tim=1450187439150552 WAIT #139944607436728: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1450187439150617
Could the 30 blocks be some maintenance operations ? I leave it to you to conduct your own experiments. Maybe you could post your findings and observations.
Remember : I have used aggregate=NO and sys=NO in my tkprof calls.
Note that there was no disk read. The initial table creation with a segment seems to have created the first extent with blocks in the buffer cache (when I do a block dump later, I can confirm that 5 blocks after the segment header are formatted).
Let me do another INSERT.
SQL> insert into small_insert select 2, 'Row TWO' from dual;
1 row created.
SQL>
SQL ID: 9r6zkjh90yvfy Plan Hash: 1388734953
insert into small_insert select 2, 'Row TWO' from dual
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 1 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 1 3 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 LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=118 us)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)
I still see 3 blocks in current get mode. It is quite likely that this second row went into the same block as the first row yet the same block has to be 're-got' in current mode. Also, an Undo segment block has to be updated. Note, however, the consistent get also that had to be done. If we could enable more detailed tracing (can we ?) we might be able to identify which block (buffer in the buffer cache) was in consistent get and which were in current get.
What if I have an index on the table ?
SQL> create index small_insert_ndx on small_insert(id_column);
Index created.
SQL> exec dbms_session.session_trace_enable(waits=>TRUE);
PL/SQL procedure successfully completed.
SQL> insert into small_insert select 3, 'Row THREE' from dual;
1 row created.
SQL>
SQL ID: cx3ubh9c2r80m Plan Hash: 1388734953
insert into small_insert select 3, 'Row THREE' from dual
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 1 6 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 1 6 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 LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=223 us)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=7 us cost=2 size=0 card=1)
Now we have 6 blocks in current mode.
SQL> insert into small_insert select 4, 'Row FOUR' from dual;
1 row created.
SQL>
insert into small_insert select 4, 'Row FOUR' from dual
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 1 5 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 1 5 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 LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=206 us)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=9 us cost=2 size=0 card=1)
So, with an index present, the current get overhead is greater. Obviously, Oracle has to expend more effort to retrieve and update the index block.
Here, this table with 4 rows has only 1 table block and 1 index (root) block being used. The same block is updated for each fresh INSERT, and each call requires a fresh current get. This means that there will be CPU overhead in repeatedly reading the (same !) block for each fresh INSERT.
Caveat : All 4 rows inserted are inserted by the same session, so they went into the same block. Had I used different sessions for the 4 rows they may have gone into 2 or more blocks because of the way in which ASSM splits INSERT calls across different blocks.
(Note : A GATHER_TABLE_STATS would show a block count of 5 (not 1, not 8) because the first 5 blocks are formatted, as I can confirm with a block dump).
.
.
.
13 December, 2015
Trace Files -- 10 : Tracing DML
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.
.
.
.
Subscribe to:
Posts (Atom)