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.
.
.
.
09 December, 2015
Trace Files -- 9 : Advantages
I received a question about why Trace Files are useful.
I jotted down a few quick points. I may expand on them or add to them later
I jotted down a few quick points. I may expand on them or add to them later
- You don’t have to monitor a user screen , batch job in real time – e.g. if the user or batch is running at 2am, you’d have to login at 2am to monitor it.
- If you are doing real time monitoring, once the particular event of interest has gone off your screen, you don’t have time to think about it because something else is happening on the screen you are using to monitor the user / batch
- ASH doesn’t capture every wait event --- you’ll have many single block reads and multi block reads and even locks that may have occurred between two 1second AWR snapshots. So it is an approximation but not an aggregation. (Historical AWR is even worse as it maintains only 1 in 10 samples)
- You can repeatedly review the tracefile and spend more time on it which you can’t do in real-time monitoring
- I’d use a trace file for a batch job.
06 December, 2015
Trace Files -- 8d : Full Table Scans
In the previous two posts, I have demonstrated direct path read and db file scattered read being used for Full Table Scans. Since 11g, Oracle uses an internal formula to determine the manner of reading the table segment for a Full Table Scan.
Here I use an SQL trace to compare the two behaviours.
In session 1, I run these queries :
(I had another session running other queries between 18:03 and 18:11)
The Full Table Scan on "ALL_OBJECTS_MANY_LIST" would have been executed as 'direct path read's. The Full Table Scan on "ALL_OBJECTS_SHORT_LIST" (being a much smaller table) would have been executed as 'db file scattered read's.
Let's compare the queries in terms of the number of blocks read and how they were read. First, the three executions on the larger table.
All three executions of the Full Table Scan (inspite of one query on another table being executed between the two) were done with 'direct path read' reading all the blocks from disk. Note the 'disk ' column and "Times Waited" column. For all three executions, CPU time is only about a second in each execution and the disk reads took more than 40seconds in the first two executions and more than 100seconds in the third execution..
Next, the three executions on the smaller table.
For these queries against the smaller (SHORT_LIST) table, it is only the first execution that shows Disk I/O from the 'db file scattered read' waits and the "disk" column (140 blocks reported in the "disk" column and shown as physical reads indicated by the "pr=140" in the statistics). The subsequent two executions were against the blocks in the Buffer Cache (as shown by 0 "disk" and "pr" statistics). This is also evident in the third execution which occurred almost eleven minutes after the second execution. Evidently, the buffers for the table were still evident in the Buffer Cache. The session did not have to go back to disk to read the blocks. This would be the behaviour for any other session also, as the Buffer Cache would be shared by multiple sessions.
Thus, we can see that for a table (the MANY_LIST table) that is large enough for Oracle to decide on direct path reads, there is no buffering of the blocks in the buffer cache. Every Full Table Scan execution, whether by the same session or another session, has to re-read the table from disk (or filesystem buffers maintained by the OS) afresh. This must be a consideration when you have a database application that frequently needs to do Full Table Scans. Do you want every session to have to read from disk afresh ? You would not take advantage of the buffer cache in the SGA. You could choose to create a larger SGA and Buffer Cache. There is another method -- the undocumented "_serial_direct_read" parameter but that makes sense to use only if the table is smaller than the Buffer Cache.
Note : The 496.19 "SQL*Net message from client" wait event after the second query against the SHORT_LIST table is the elapsed time till the next query. The clock time showed at the SQLPlus prompt may not have been the time a query started because I might have waited some time before actually submitting the query (by hitting the ENTER query after the ";")
.
.
.
Here I use an SQL trace to compare the two behaviours.
In session 1, I run these queries :
[oracle@ora11204 ~]$ sqlplus hemant/hemant
SQL*Plus: Release 11.2.0.4.0 Production on Sun Dec 6 17:59:12 2015
Copyright (c) 1982, 2013, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> set time on
17:59:18 SQL> set timing on
17:59:20 SQL> alter session set tracefile_identifier='SESSION_1';
Session altered.
Elapsed: 00:00:00.00
17:59:31 SQL> exec dbms_session.session_trace_enable(waits=>TRUE);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
17:59:41 SQL>
18:00:25 SQL> select count(*) from all_objects_many_list where owner = 'HEMANT';
COUNT(*)
----------
256
Elapsed: 00:00:45.67
18:01:28 SQL> select count(*) from all_objects_short_list where owner = 'HEMANT';
COUNT(*)
----------
3
Elapsed: 00:00:00.40
18:01:46 SQL> select /* second_run */ count(*) from all_objects_many_list where owner = 'HEMANT';
COUNT(*)
----------
256
Elapsed: 00:00:42.35
18:02:48 SQL> select /* second_run */ count(*) from all_objects_short_list where owner = 'HEMANT';
COUNT(*)
----------
3
Elapsed: 00:00:00.01
18:03:05 SQL>
18:10:57 SQL>
18:11:06 SQL> select /* third_run */ count(*) from all_objects_many_list where owner = 'HEMANT';
COUNT(*)
----------
256
Elapsed: 00:01:41.50
18:13:03 SQL> select /* third_run */ count(*) from all_objects_short_list where owner = 'HEMANT';
COUNT(*)
----------
3
Elapsed: 00:00:00.07
18:13:20 SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@ora11204 ~]$
(I had another session running other queries between 18:03 and 18:11)
The Full Table Scan on "ALL_OBJECTS_MANY_LIST" would have been executed as 'direct path read's. The Full Table Scan on "ALL_OBJECTS_SHORT_LIST" (being a much smaller table) would have been executed as 'db file scattered read's.
Let's compare the queries in terms of the number of blocks read and how they were read. First, the three executions on the larger table.
SQL ID: bpgst4ajh1wb2 Plan Hash: 2662061148
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
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=44340391 us)
256 256 256 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97793 pw=0 time=30091048 us cost=26809 size=5256 card=657)
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 3 0.67 0.76
direct path read 1542 1.81 43.21
SQL*Net message from client 2 16.96 16.96
********************************************************************************
SQL ID: bqhqn8rvr5139 Plan Hash: 2662061148
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
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=42353099 us)
256 256 256 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=15066276 us cost=26809 size=5256 card=657)
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
direct path read 1542 1.66 41.95
SQL*Net message from client 2 17.06 17.06
********************************************************************************
SQL ID: 2pwy1jv1uu23x Plan Hash: 2662061148
select /* third_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 1.05 101.44 97792 97797 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.05 101.44 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=101440638 us)
256 256 256 TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97797 pr=97792 pw=0 time=109050948 us cost=26809 size=5256 card=657)
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
direct path read 1542 1.06 101.01
SQL*Net message from client 2 17.00 17.00
********************************************************************************
All three executions of the Full Table Scan (inspite of one query on another table being executed between the two) were done with 'direct path read' reading all the blocks from disk. Note the 'disk ' column and "Times Waited" column. For all three executions, CPU time is only about a second in each execution and the disk reads took more than 40seconds in the first two executions and more than 100seconds in the third execution..
Next, the three executions on the smaller table.
SQL ID: 9k7ff0kmd0nbw Plan Hash: 3180576180
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
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=580 pr=140 pw=0 time=95405 us)
3 3 3 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=140 pw=0 time=95379 us cost=158 size=102 card=6)
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 scattered read 21 0.03 0.08
db file sequential read 3 0.00 0.00
SQL*Net message from client 2 19.89 19.89
********************************************************************************
SQL ID: dgu2sxavbv996 Plan Hash: 3180576180
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
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=580 pr=0 pw=0 time=1173 us)
3 3 3 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=0 pw=0 time=1146 us cost=158 size=102 card=6)
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
SQL*Net message from client 2 496.19 496.19
********************************************************************************
SQL ID: 2xuyj80zj1xnt Plan Hash: 3180576180
select /* third_run */ count(*)
from
all_objects_short_list where owner = 'HEMANT'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 2 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.02 0 582 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=580 pr=0 pw=0 time=1019 us)
3 3 3 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=0 pw=0 time=991 us cost=158 size=102 card=6)
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
SQL*Net message from client 2 3.57 3.57
********************************************************************************
For these queries against the smaller (SHORT_LIST) table, it is only the first execution that shows Disk I/O from the 'db file scattered read' waits and the "disk" column (140 blocks reported in the "disk" column and shown as physical reads indicated by the "pr=140" in the statistics). The subsequent two executions were against the blocks in the Buffer Cache (as shown by 0 "disk" and "pr" statistics). This is also evident in the third execution which occurred almost eleven minutes after the second execution. Evidently, the buffers for the table were still evident in the Buffer Cache. The session did not have to go back to disk to read the blocks. This would be the behaviour for any other session also, as the Buffer Cache would be shared by multiple sessions.
Thus, we can see that for a table (the MANY_LIST table) that is large enough for Oracle to decide on direct path reads, there is no buffering of the blocks in the buffer cache. Every Full Table Scan execution, whether by the same session or another session, has to re-read the table from disk (or filesystem buffers maintained by the OS) afresh. This must be a consideration when you have a database application that frequently needs to do Full Table Scans. Do you want every session to have to read from disk afresh ? You would not take advantage of the buffer cache in the SGA. You could choose to create a larger SGA and Buffer Cache. There is another method -- the undocumented "_serial_direct_read" parameter but that makes sense to use only if the table is smaller than the Buffer Cache.
Note : The 496.19 "SQL*Net message from client" wait event after the second query against the SHORT_LIST table is the elapsed time till the next query. The clock time showed at the SQLPlus prompt may not have been the time a query started because I might have waited some time before actually submitting the query (by hitting the ENTER query after the ";")
.
.
.
03 December, 2015
Auditing DBMS_STATS usage
(I will be returning to the Tracing series .... but a quick diversion because I had received a request for assistance on auditing DBMS_STATS usage)
First, I setup auditing
Next, I run a DBMS_STATS call and check the audit trail for it.
Now, I check the Audit Trail.
Note : Execution of DBMS_STATS by SYS would not be audited in the database audit trail table. As you can see below :
I would need AUDIT_SYS_OPERATIONS and AUDIT_FILE_DEST to capture audit of actions by SYS.
.
.
.
First, I setup auditing
SQL> alter system set audit_trail='DB_EXTENDED' scope=SPFILE; System altered. SQL> shutdown immediate; Database closed. Database dismounted. ORACLE instance shut down. SQL> startup; ORACLE instance started. Total System Global Area 1068937216 bytes Fixed Size 2260088 bytes Variable Size 750781320 bytes Database Buffers 310378496 bytes Redo Buffers 5517312 bytes Database mounted. Database opened. SQL> audit execute on sys.dbms_stats; Audit succeeded. SQL>
Next, I run a DBMS_STATS call and check the audit trail for it.
SQL> connect hemant/hemant
Connected.
SQL> create table obj_all_list as select * from all_objects;
Table created.
SQL> execute dbms_stats.gather_table_stats('','OBJ_ALL_LIST',method_opt=>'FOR ALL COLUMNS SIZE 1');
PL/SQL procedure successfully completed.
SQL> execute dbms_stats.lock_table_stats('','OBJ_ALL_LIST');
PL/SQL procedure successfully completed.
SQL>
Now, I check the Audit Trail.
SQL> connect / as sysdba
Connected.
SQL> set pages600
SQL> select to_char(timestamp,'DD-MON HH24:MI:SS'), username, userhost, sql_text
2 from dba_audit_object
3 where obj_name = 'DBMS_STATS'
4 and timestamp > trunc(sysdate)
5 order by timestamp;
TO_CHAR(TIMESTAMP,'DD-MO USERNAME
------------------------ ------------------------------
USERHOST
--------------------------------------------------------------------------------
SQL_TEXT
--------------------------------------------------------------------------------
03-DEC 22:58:35 HEMANT
ora11204
BEGIN dbms_stats.gather_table_stats('','OBJ_ALL_LIST',method_opt=>'FOR ALL COLUM
NS SIZE 1'); END;
03-DEC 22:58:50 HEMANT
ora11204
BEGIN dbms_stats.lock_table_stats('','OBJ_ALL_LIST'); END;
SQL>
Note : Execution of DBMS_STATS by SYS would not be audited in the database audit trail table. As you can see below :
SQL> execute dbms_stats.unlock_table_stats('HEMANT','OBJ_ALL_LIST');
PL/SQL procedure successfully completed.
SQL> select to_char(timestamp,'DD-MON HH24:MI:SS'), username, userhost, sql_text
2 from dba_audit_object
3 where obj_name = 'DBMS_STATS'
4 and timestamp > trunc(sysdate)
5 order by timestamp;
TO_CHAR(TIMESTAMP,'DD-MO USERNAME
------------------------ ------------------------------
USERHOST
--------------------------------------------------------------------------------
SQL_TEXT
--------------------------------------------------------------------------------
03-DEC 22:58:35 HEMANT
ora11204
BEGIN dbms_stats.gather_table_stats('','OBJ_ALL_LIST',method_opt=>'FOR ALL COLUM
NS SIZE 1'); END;
03-DEC 22:58:50 HEMANT
ora11204
BEGIN dbms_stats.lock_table_stats('','OBJ_ALL_LIST'); END;
SQL>
I would need AUDIT_SYS_OPERATIONS and AUDIT_FILE_DEST to capture audit of actions by SYS.
SQL> show parameter audit
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
audit_file_dest string /u01/app/oracle/admin/orcl/adu
mp
audit_sys_operations boolean FALSE
audit_syslog_level string
audit_trail string DB_EXTENDED
SQL>
.
.
.
Subscribe to:
Posts (Atom)