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.

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 :

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

  1. 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.
  2. 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
  3. 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)
  4. You can repeatedly review the tracefile and spend more time on it which you can’t do in real-time monitoring
  5. 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 :

[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

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>

.
.
.

29 November, 2015

Trace Files -- 8c : Still More Performance Evaluation from Trace File

In previous blog posts here and here, I have demonstrated Full Table Scans of a table called ALL_OBJECTS_MANY_LIST being executed via Direct Path Reads (shown as 'direct path read') in the Wait Events.

This sort of read does NOT use the Buffer Cache and the read from disk directly goes to the user's server process PGA.  Thus, the blocks read are not shareable with other users.  Multiple users reading the same table(s) via Direct Path Read are not able to share the Buffer Cache, resulting in Disk Reads being repeated for every Full Table Scan request.  (Note : The OS may be using a File System Buffer Cache or the Storage may be using a Storage Cache to service the Disk Reads, but Oracle will always see every re-read of the table as a Disk Read).

Pre-11g, this behaviour could only be possible for Parallel Query.
However, 11g introduced the feature of "serial_direct_read" which allows non-PQ FullTableScans  to bypass the Buffer Cache.  This behaviour is predicated by the size of the table (segment) vis-a-vis the Buffer Cache, in relation to what is called "small_table_threshold".  A table exceeding a certain multiple of the "small_table_threshold" (which, by default, is a certain ratio of the Buffer Cache) is read via Direct Path Reads.

The Pre-11g and the 11g behaviour for smaller tables is to use Disk Reads that feed into the Buffer Cache, making the buffers shareable for repeated reads by either the same session or other sessions.  This obviates the need to make Disk Read calls for subsequent requests (as long as the blocks are still in the Buffer Cache).  The Wait Event we'd see for such Disk Reads is the (well known) "db file scattered read".

Here's a demo with a smaller table ALL_OBJECTS_SHORT_LIST.

SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> select count(*) from all_objects_short_list;

  COUNT(*)
----------
     28117

SQL> exec dbms_session.session_trace_disable();

PL/SQL procedure successfully completed.

SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3029.trc

SQL> exit
[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3029.trc \
> SHORT_LIST.PRF aggregate=NO sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 29 23:13:43 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 ~]$ 

SQL ID: 69hzxtrb3dv1b Plan Hash: 1680768796

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
  NVL(SUM(C2),:"SYS_B_1")
FROM
 (SELECT /*+ NO_PARALLEL("ALL_OBJECTS_SHORT_LIST")
  FULL("ALL_OBJECTS_SHORT_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_SHORT_LIST")
  */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM
  "HEMANT"."ALL_OBJECTS_SHORT_LIST" SAMPLE BLOCK (:"SYS_B_4" , :"SYS_B_5")
  SEED (:"SYS_B_6") "ALL_OBJECTS_SHORT_LIST") SAMPLESUB


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        1      0.00       0.11        437         72          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.11        437         72          0           1

Misses in library cache during parse: 1
isses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=72 pr=437 pw=0 time=110985 us)
      3289       3289       3289   TABLE ACCESS SAMPLE ALL_OBJECTS_SHORT_LIST (cr=72 pr=437 pw=0 time=173325 us cost=19 size=61752 card=5146)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         7        0.04          0.05
  db file scattered read                          9        0.02          0.05
--------------------------------------------------------------------------------



SQL ID: 5ayuqj4djbjxh Plan Hash: 3180576180

select count(*)
from
 all_objects_short_list


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02          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.11        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=90644 us)
     28117      28117      28117   TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=140 pw=0 time=110678 us cost=158 size=0 card=30071)


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.02          0.07
  db file sequential read                         3        0.00          0.00
  SQL*Net message from client                     2        9.76          9.76
********************************************************************************

The first query is the Dynamic Sampling query (because no statistics exist on the target table).  As in example 8a, this is done with a mix of single block ("db file sequential read") and multiblock ("db file scattered read") waits.  Here is a sampling of the waits for the Dynamic Sampling query :
WAIT #139712598070504: nam='db file sequential read' ela= 16 file#=1 block#=61344 blocks=1 obj#=35064 tim=1448809955554822
WAIT #139712598070504: nam='db file sequential read' ela= 951 file#=1 block#=61350 blocks=1 obj#=35064 tim=1448809955555840
WAIT #139712598070504: nam='db file scattered read' ela= 956 file#=1 block#=61362 blocks=6 obj#=35064 tim=1448809955556893
WAIT #139712598070504: nam='db file sequential read' ela= 720 file#=1 block#=61370 blocks=1 obj#=35064 tim=1448809955557710
WAIT #139712598070504: nam='db file sequential read' ela= 837 file#=1 block#=61378 blocks=1 obj#=35064 tim=1448809955558589
WAIT #139712598070504: nam='db file scattered read' ela= 1020 file#=1 block#=61385 blocks=7 obj#=35064 tim=1448809955559711
WAIT #139712598070504: nam='db file sequential read' ela= 804 file#=1 block#=61392 blocks=1 obj#=35064 tim=1448809955560643
WAIT #139712598070504: nam='db file scattered read' ela= 1270 file#=1 block#=61400 blocks=8 obj#=35064 tim=1448809955562000


This is the execution of the actual FullTableScan (the count(*) query submitted by me) :
EXEC #139712598962024:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3180576180,tim=1448809955666350
WAIT #139712598962024: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=35064 tim=1448809955666420
WAIT #139712598962024: nam='db file scattered read' ela= 28044 file#=1 block#=61345 blocks=5 obj#=35064 tim=1448809955695578
WAIT #139712598962024: nam='db file sequential read' ela= 1691 file#=1 block#=61351 blocks=1 obj#=35064 tim=1448809955697475
WAIT #139712598962024: nam='db file scattered read' ela= 11 file#=1 block#=61352 blocks=8 obj#=35064 tim=1448809955697539
WAIT #139712598962024: nam='db file scattered read' ela= 64 file#=1 block#=61360 blocks=2 obj#=35064 tim=1448809955697790
WAIT #139712598962024: nam='db file scattered read' ela= 468 file#=1 block#=61368 blocks=2 obj#=35064 tim=1448809955698673
WAIT #139712598962024: nam='db file scattered read' ela= 1493 file#=1 block#=61371 blocks=5 obj#=35064 tim=1448809955700255
WAIT #139712598962024: nam='db file scattered read' ela= 64 file#=1 block#=61376 blocks=2 obj#=35064 tim=1448809955700510
WAIT #139712598962024: nam='db file scattered read' ela= 1856 file#=1 block#=61379 blocks=5 obj#=35064 tim=1448809955702457
WAIT #139712598962024: nam='db file sequential read' ela= 11 file#=1 block#=61384 blocks=1 obj#=35064 tim=1448809955702568
WAIT #139712598962024: nam='db file scattered read' ela= 1184 file#=1 block#=61393 blocks=7 obj#=35064 tim=1448809955703916
WAIT #139712598962024: nam='db file scattered read' ela= 5970 file#=1 block#=61408 blocks=8 obj#=35064 tim=1448809955710042
WAIT #139712598962024: nam='db file scattered read' ela= 263 file#=1 block#=61424 blocks=7 obj#=35064 tim=1448809955710475
WAIT #139712598962024: nam='db file scattered read' ela= 2461 file#=1 block#=82176 blocks=8 obj#=35064 tim=1448809955713060
WAIT #139712598962024: nam='db file scattered read' ela= 2585 file#=1 block#=82184 blocks=8 obj#=35064 tim=1448809955715814
WAIT #139712598962024: nam='db file scattered read' ela= 70 file#=1 block#=82192 blocks=8 obj#=35064 tim=1448809955716030
WAIT #139712598962024: nam='db file scattered read' ela= 687 file#=1 block#=82200 blocks=3 obj#=35064 tim=1448809955716832
WAIT #139712598962024: nam='db file scattered read' ela= 28205 file#=1 block#=82204 blocks=4 obj#=35064 tim=1448809955745140
WAIT #139712598962024: nam='db file scattered read' ela= 13 file#=1 block#=82208 blocks=8 obj#=35064 tim=1448809955745285
WAIT #139712598962024: nam='db file scattered read' ela= 1070 file#=1 block#=82216 blocks=8 obj#=35064 tim=1448809955746453
WAIT #139712598962024: nam='db file sequential read' ela= 5960 file#=1 block#=82304 blocks=1 obj#=35064 tim=1448809955752560
WAIT #139712598962024: nam='db file scattered read' ela= 15 file#=1 block#=82538 blocks=5 obj#=35064 tim=1448809955754269
WAIT #139712598962024: nam='db file scattered read' ela= 15 file#=1 block#=82560 blocks=8 obj#=35064 tim=1448809955754481
WAIT #139712598962024: nam='db file scattered read' ela= 22 file#=1 block#=82674 blocks=14 obj#=35064 tim=1448809955755267
WAIT #139712598962024: nam='db file scattered read' ela= 18 file#=1 block#=82688 blocks=12 obj#=35064 tim=1448809955755460
FETCH #139712598962024:c=9997,e=90650,p=140,cr=580,cu=0,mis=0,r=1,dep=0,og=1,plh=3180576180,tim=1448809955757097
STAT #139712598962024 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=580 pr=140 pw=0 time=90644 us)'
STAT #139712598962024 id=2 cnt=28117 pid=1 pos=1 obj=35064 op='TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=580 pr=140 pw=0 time=110678 us cost=158 size=0 card=30071)'


The Segment Header is in Block#61344 which has already been read into the Buffer Cache by the Dynamic Sampling query. So, we don't see a Wait Event for it in the count(*) query.  The Disk Reads start from Block#61345. From 61345 onwards, 5 blocks are read from disk (61345 to 61349). Block#61350 has already been read into the Buffer Cache by the Dynamic Sampling query.  Block#61351 is the last block of the Extents (8 blocks beginning at #61344) so it is a singe block read ("db file sequential read").  Even when Extents are contigous, Oracle will not make a read call that spans Extents.  The next Extent starts at Block#61352 and Oracle does a proper 8 block read.
At Block#61360, Oracle does a 2 block read because Block#61362 has already been read by the Dynamic Sampling query and is in the Buffer Cache.
All the Extents for this table are very small

Thus, you can see that multiblock reads using the "db file scattered read" wait event are reads that also rely on knowing which blocks are already present in the Buffer Cache.  Oracle does not do a "db file scattered read" read for a block that is already present in the Buffer Cache.

(What about Blocks 61363 to 61367 ?    Unfortunately, not every read call does get reported into the trace file, sometimes there may be "holes".  Not every Read Call is reported as being read to the last block in the Extent.
If you look at the Block# IDs being reported above and compare them with the Extents allocated, you will see that Oracle may not have reported every block as a Read Wait Event.
SQL> l
  1  select extent_id, file_id, block_id, blocks
  2  from dba_extents
  3  where
  4  owner = 'HEMANT'
  5  and segment_name = 'ALL_OBJECTS_SHORT_LIST'
  6* order by 1, 2, 3
SQL> /

 EXTENT_ID    FILE_ID BLOCK_ID     BLOCKS
---------- ---------- ---------- ----------
  0     1    61344   8
  1     1    61352   8
  2     1    61360   8
  3     1    61368   8
  4     1    61376   8
  5     1    61384   8
  6     1    61392   8
  7     1    61400   8
  8     1    61408   8
  9     1    61424   8
 10     1    82176   8
 11     1    82184   8
 12     1    82192   8
 13     1    82200   8
 14     1    82208   8
 15     1    82216   8
 16     1    82304 128
 17     1    82432 128
 18     1    82560 128
 19     1    82688 128

20 rows selected.

SQL> 

Also, once again note that file#1 indicates that these are in the SYSTEM Tablespace. .
.
.

22 November, 2015

Trace Files -- 8b : More Performance Evaluation from Trace File

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

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.

.
.
.


15 November, 2015

Trace Files -- 8a : Using SQL Trace for Performance Evaluations

All previous examples of tracing are only to demonstrate enabling tracing and viewing the results.

Now, I present a case where we can use tracing to evaluate performance of queries.  There may be a follow-up post(s) to expand on or add example(s).

I start with a table with 7million rows and more than 750MB in size (larger than the database buffer cache).  This is a multiplied copy of DBA_OBJECTS.  Statistics have not been gathered on the Table.  The Table has no Indexes.

[oracle@ora11204 ~]$ sqlplus hemant/hemant

SQL*Plus: Release 11.2.0.4.0 Production on Sun Nov 15 22:51:15 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> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> select count(*) from all_objects_many_list where owner = 'HEMANT';

  COUNT(*)
----------
       256

SQL> exec dbms_session.session_trace_disable;

PL/SQL procedure successfully completed.

SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8944.trc

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 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8944.trc MY_ALL_OBJ_M_L_QRY.PRF sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 15 22:53:12 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 ~]$ 

We expect a Full Table Scan against the Table.  But the tkprof output shows something else as well.

SQL ID: 9s5xc0z5khvq7 Plan Hash: 3546461632

SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
  NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
  NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
  NVL(SUM(C2),:"SYS_B_1")
FROM
 (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("ALL_OBJECTS_MANY_LIST")
  FULL("ALL_OBJECTS_MANY_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_MANY_LIST") */
  :"SYS_B_2" AS C1, CASE WHEN "ALL_OBJECTS_MANY_LIST"."OWNER"=:"SYS_B_3" THEN
  :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "HEMANT"."ALL_OBJECTS_MANY_LIST"
  SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8")
  "ALL_OBJECTS_MANY_LIST") SAMPLESUB


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        1      0.00       0.88        123         65          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.88        123         65          0           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Optimizer mode: ALL_ROWS
Parsing user id: 87     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=65 pr=123 pw=0 time=887883 us)
      3289       3289       3289   TABLE ACCESS SAMPLE ALL_OBJECTS_MANY_LIST (cr=65 pr=123 pw=0 time=20429 us cost=19 size=149234 card=5146)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                        35        0.08          0.70
  db file scattered read                         11        0.07          0.17
********************************************************************************

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.03          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.68      12.88      97792      97798          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.68      12.91      97794      97800          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=97792 pw=0 time=12886862 us)
       256        256        256   TABLE ACCESS FULL ALL_OBJECTS_MANY_LIST (cr=97798 pr=97792 pw=0 time=37649164 us cost=26772 size=26520 card=1560)

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
  reliable message                                1        0.03          0.03
  enq: KO - fast object checkpoint                1        0.00          0.00
  direct path read                             1542        0.18         12.54
  SQL*Net message from client                     2       18.06         18.06
********************************************************************************

Note the additional SQL that was executed before my query. That is the Dynamic Sampling query identified by the OPT_DYN_SAMP comment.  This query, although being recursive (indicated by "dep=1" in the raw trace file) is not excluded by the SYS=NO, because it is actually executed by the user "HEMANT" (indicated by "uid=87", "lid=87", where 87 is the userid of  database user 'HEMANT').

Let's see a portion of the raw trace file relating to this Dynamic Sampling query.

PARSING IN CURSOR #140417579320304 len=616 dep=1 uid=87 oct=3 lid=87 tim=1447599117299160 hv=3408424647 ad='7f8bb8f0' sqlid='9s5xc0z5khvq7'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("ALL_OBJECTS_MANY_LIST") FULL("ALL_OBJECTS_MANY_LIST") NO_PARALLEL_INDEX("ALL_OBJECTS_MANY_LIST") */ :"SYS_B_2" AS C1, CASE WHEN "ALL_OBJECTS_MANY_LIST"."OWNER"=:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "HEMANT"."ALL_OBJECTS_MANY_LIST" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "ALL_OBJECTS_MANY_LIST") SAMPLESUB
END OF STMT
PARSE #140417579320304:c=1000,e=670,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1447599117299155
EXEC #140417579918768:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1447599117300059
FETCH #140417579918768:c=1000,e=20,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=3,plh=2239883476,tim=1447599117300113
CLOSE #140417579918768:c=0,e=7,dep=2,type=3,tim=1447599117300148
EXEC #140417579320304:c=1000,e=1319,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=1,plh=3546461632,tim=1447599117300542
WAIT #140417579320304: nam='db file sequential read' ela= 17 file#=4 block#=330 blocks=1 obj#=35014 tim=1447599117300633
WAIT #140417579320304: nam='db file sequential read' ela= 12384 file#=4 block#=1044 blocks=1 obj#=35014 tim=1447599117313168
WAIT #140417579320304: nam='db file sequential read' ela= 30217 file#=4 block#=1839 blocks=1 obj#=35014 tim=1447599117343572
WAIT #140417579320304: nam='db file sequential read' ela= 14367 file#=4 block#=4273 blocks=1 obj#=35014 tim=1447599117358103
WAIT #140417579320304: nam='db file sequential read' ela= 26739 file#=4 block#=4666 blocks=1 obj#=35014 tim=1447599117384964
WAIT #140417579320304: nam='db file sequential read' ela= 15278 file#=4 block#=8352 blocks=1 obj#=35014 tim=1447599117400429
WAIT #140417579320304: nam='db file scattered read' ela= 55038 file#=4 block#=14030 blocks=8 obj#=35014 tim=1447599117455816

*** 2015-11-15 22:51:57.527
WAIT #140417579320304: nam='db file sequential read' ela= 71363 file#=4 block#=14417 blocks=1 obj#=35014 tim=1447599117527415
WAIT #140417579320304: nam='db file sequential read' ela= 81866 file#=4 block#=18668 blocks=1 obj#=35014 tim=1447599117609519
WAIT #140417579320304: nam='db file sequential read' ela= 65981 file#=4 block#=23052 blocks=1 obj#=35014 tim=1447599117675718
WAIT #140417579320304: nam='db file sequential read' ela= 14640 file#=4 block#=25282 blocks=1 obj#=35014 tim=1447599117690503
WAIT #140417579320304: nam='db file sequential read' ela= 65302 file#=4 block#=26230 blocks=1 obj#=35014 tim=1447599117755921
WAIT #140417579320304: nam='db file scattered read' ela= 51919 file#=4 block#=27340 blocks=8 obj#=35014 tim=1447599117808090
WAIT #140417579320304: nam='db file scattered read' ela= 70379 file#=4 block#=27479 blocks=8 obj#=35014 tim=1447599117878651

Note the mix of single-block 'db file sequential read' waits and multi-block 'db file scattered read' waits.  Also, note from the block numbers (indicated by "block#") that the reads are not really sequential blocks from disk.  The first block read is block 330 of file 4.  That is the header block of the Table (i.e. Segment) (we could query DBA_SEGMENTS to confirm this).  After that, Oracle has randomly identified blocks to scan.  The multi-block reads can be identified by "blocks=8"  (in this extract we see only 3 multi-block reads, as I haven't presented the entire raw trace file here.  The Dynamic Sampling had 35 'db file sequential read' waits and 11 'db file scattered read waits' -- which we see in the tkprof output.  The tkprof shows that although there were physical block read requests for 123 blocks, only 65 were actually sampled.  Dynamic Sampling took 0.88seconds (i.e. added 0.88seconds to the time to execute my query0.

Dynamic Sampling is done using Buffered reads.  However, the Full Table Scan of the large table is executed using Direct Path reads.  That is why the wait event for the count(*) query is different -- it is a 'direct path read' wait that occurs many times.

ARSING IN CURSOR #140417579185064 len=65 dep=0 uid=87 oct=3 lid=87 tim=1447599118188941 hv=2734748002 ad='7f956058' sqlid='bpgst4ajh1wb2'
select count(*) from all_objects_many_list where owner = 'HEMANT'
END OF STMT
PARSE #140417579185064:c=24996,e=1098676,p=127,cr=184,cu=0,mis=1,r=0,dep=0,og=1,plh=2662061148,tim=1447599118188936
EXEC #140417579185064:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2662061148,tim=1447599118189025
WAIT #140417579185064: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=35014 tim=1447599118189093
WAIT #140417579185064: nam='reliable message' ela= 33598 channel context=2123970008 channel handle=2123913464 broadcast message=2125033832 obj#=35014 tim=1447599118223060
WAIT #140417579185064: nam='enq: KO - fast object checkpoint' ela= 3905 name|mode=1263468550 2=65560 0=1 obj#=35014 tim=1447599118227031
WAIT #140417579185064: nam='direct path read' ela= 32287 file number=4 first dba=331 block cnt=13 obj#=35014 tim=1447599118259487
WAIT #140417579185064: nam='direct path read' ela= 97 file number=4 first dba=345 block cnt=15 obj#=35014 tim=1447599118259681
WAIT #140417579185064: nam='direct path read' ela= 9530 file number=4 first dba=361 block cnt=15 obj#=35014 tim=1447599118269284
WAIT #140417579185064: nam='direct path read' ela= 81 file number=4 first dba=377 block cnt=15 obj#=35014 tim=1447599118269448
WAIT #140417579185064: nam='direct path read' ela= 4879 file number=4 first dba=393 block cnt=15 obj#=35014 tim=1447599118274418
WAIT #140417579185064: nam='direct path read' ela= 18847 file number=4 first dba=409 block cnt=15 obj#=35014 tim=1447599118293388
WAIT #140417579185064: nam='direct path read' ela= 3692 file number=4 first dba=425 block cnt=15 obj#=35014 tim=1447599118297175
WAIT #140417579185064: nam='direct path read' ela= 2612 file number=4 first dba=441 block cnt=15 obj#=35014 tim=1447599118299862
WAIT #140417579185064: nam='direct path read' ela= 42872 file number=4 first dba=514 block cnt=62 obj#=35014 tim=1447599118342814
WAIT #140417579185064: nam='direct path read' ela= 12735 file number=4 first dba=576 block cnt=64 obj#=35014 tim=1447599118355614
WAIT #140417579185064: nam='direct path read' ela= 41997 file number=4 first dba=642 block cnt=62 obj#=35014 tim=1447599118397975
WAIT #140417579185064: nam='direct path read' ela= 11584 file number=4 first dba=704 block cnt=64 obj#=35014 tim=1447599118409765
WAIT #140417579185064: nam='direct path read' ela= 10909 file number=4 first dba=770 block cnt=62 obj#=35014 tim=1447599118420916
WAIT #140417579185064: nam='direct path read' ela= 10969 file number=4 first dba=832 block cnt=64 obj#=35014 tim=1447599118432086

Before we look at the 'direct path read' waits, please see the 'reliable message' and 'enq: KO - fast object checkpoint' waits.  Oracle will always cause a segment checkpoint before it starts doing Direct Path reads.  This is to ensure that any dirty buffers for that segment (the table "all_objects_many_list") are flushed to disk before Oracle starts using Direct Path reads to bypass the Buffer Cache. 

Next, if we look at the 'direct path read' waits, we see that they are reported differently from the 'db file sequential || scattered read' waits.  Instead of reporting "block#" and "blocks", this wait event reports "dba" ("data block address") and "block cnt".  Note the first read is of 13 blocks starting at block number 331 (after the Segment Header).  The next read starts at block number 345 (which is 331+13+1).  This is a 15 block read.  The third read starts at block 361 (which is 345+15+1).  Thus, we can see that the Table is laid out contiguous extents in the same datafile (file=4).

The "ela=" time is the time in micrseconds for each read.  The obj# is the Object ID of the table.
During the Full Table Scan, there were 1,542 occurrences of the 'direct path read' wait event.  The average read time for 'direct path read' waits can be computed by dividing the 12.54seconds over the 1,542 occurrences.  But we must note that some of these reads were 16 or fewer blocks and others were 64 or so blocks. The first read was 32,287microseconds,  the next was 97microseconds.  It is possible that either the OS or the Storage Cache did some pre-fetching of blocks.  But note the fluctuations in read wait times.  Averages can be misleading.  It is a good idea to sometimes walk through the trace file (preferably using a tool) to determine a Histogram of these waits.

If we look at the small extract of the trace file that I've pasted here, we can see that the reads were growing.  There were 64 blocks read in the last wait event that I've pasted.  Reviewing the entire trace file, I see that "64" is the highest  reported "block cnt" figure.  However, the distribution of extent size goes upto 8MB (1024 blocks), yet the largest read was 64 blocks because of how Oracle has auto-configured 'db_file_multiblock_read_count'.  Remember, tkprof does NOT show you the sizes of the multi-block reads either as 'db file scattered read' or 'direct path read'.  You have to read or parse the raw trace file to identify this.


SQL> select blocks, count(*) 
  2  from dba_extents
  3  where owner = 'HEMANT'
  4  and segment_name = 'ALL_OBJECTS_MANY_LIST'
  5  group by blocks
  6  order by 1;

    BLOCKS   COUNT(*)
---------- ----------
  8    16
       128    63
      1024    88

SQL>      
SQL> show parameter db_file_multi

NAME         TYPE  VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count      integer  106
SQL> 

The DBA here had not specifically configured db_file_multiblock_read_count to 128 (I would certainly have done so, and would have got better performance on the Full Table Scan).
,
,
,

08 November, 2015

Trace Files -- 7 : SQL in PL/SQL

So far, all my examples of Tracing have been 'pure' SQL.  What does a Trace File show for SQL that is executed from within PL/SQL ?

I run this code  where I trace only the execution of the stored procedure :

SQL> drop table departmental_salary purge;

Table dropped.

SQL> drop procedure my_dept_salary_proc ;

Procedure dropped.

SQL> 
SQL> create table departmental_salary (department_id number, total_salary number);

Table created.

SQL> 
SQL> create or replace procedure my_dept_salary_proc as
  2  l_dept_id number(4);
  3  l_tot_salary number(10,2);
  4  cursor get_dept_id is select distinct department_id from employees;
  5  
  6  begin
  7  open get_dept_id;
  8  loop
  9  fetch get_dept_id into l_dept_id;
 10  exit when get_dept_id%notfound;
 11  
 12  -- get the sum(salary)
 13  select sum(salary) into l_tot_salary from employees where department_id = l_dept_id ;
 14  -- the developer mistakenly entered the same query twice in the procedure
 15  -- the second SELECT is textually different
 16  SELECT  SUM(SALARY) into l_tot_salary FROM    employees WHERE DEPARTMENT_ID = l_dept_id ;
 17  
 18  insert into departmental_salary values (l_dept_id, l_tot_salary);
 19  -- again, the developer mistakenly entered the same INSERT twice
 20  -- not exactly the same text
 21  INSERT into   DEPARTMENTAL_SALARY values (L_DEPT_ID, L_TOT_SALARY);
 22  
 23  end loop;
 24  
 25  commit;
 26  
 27  end;
 28  /

Procedure created.

SQL> 
SQL> exec dbms_session.session_trace_enable(waits=>TRUE);

PL/SQL procedure successfully completed.

SQL> 
SQL> execute my_dept_salary_proc;

PL/SQL procedure successfully completed.

SQL> 
SQL> exec dbms_session.session_trace_disable;

PL/SQL procedure successfully completed.

SQL> 
SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3927.trc

SQL> 


Note the repetition of the SELECT and INSERT statements.  In "normal" SQL, the two SELECTs for SUM(SALARY) would have two different SQL_IDs because any SQL that differs by Case or blank characters is a different SQL_ID.  As also, the two INSERTs should have different SQL_IDs.

What does a tkprof show ?

[oracle@ora11204 ~]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3927.trc \
> EXEC_MY_DEPT_SALARY_PROC.PRF sys=NO aggregate=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 8 23:23:42 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 ~]$ 



Note that I've set SYS=NO to exclude Parse Recursive SQLs.

Selectively reporting from the tkprof, I see :

SQL ID: 0wan8zwsb8000 Plan Hash: 0

BEGIN dbms_session.session_trace_enable(waits=>TRUE); END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43


SQL ID: a8p49fngpats5 Plan Hash: 0

BEGIN my_dept_salary_proc; END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43


SQL ID: 4xts9z878v4yb Plan Hash: 3042654289

SELECT DISTINCT DEPARTMENT_ID
FROM
 EMPLOYEES


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       13      0.00       0.00          0          6          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.00       0.00          0          6          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        12         12         12  HASH UNIQUE (cr=6 pr=0 pw=0 time=743 us cost=4 size=33 card=11)
       214        214        214   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=917 us cost=3 size=642 card=214)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=73 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=64 us cost=3 size=133 card=19)


SQL ID: bnr7u92kg18ak Plan Hash: 1756381138

SELECT SUM(SALARY)
FROM
 EMPLOYEES WHERE DEPARTMENT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12      0.00       0.00          0         66          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25      0.00       0.00          0         66          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=6 pr=0 pw=0 time=50 us)
        12         12         12   TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=40 us cost=3 size=133 card=19)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          4         55          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          4         55          12

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
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=479 us)


SQL ID: b6yyghrcpvy4y Plan Hash: 0

INSERT INTO DEPARTMENTAL_SALARY
VALUES
 (:B2 , :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          1         14          12
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0          1         14          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43     (recursive depth: 1)
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=63 us)


SQL ID: 8ggw94h7mvxd7 Plan Hash: 0

COMMIT


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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Parsing user id: 43     (recursive depth: 1)


SQL ID: 4pzfk82288xrc Plan Hash: 0

BEGIN dbms_session.session_trace_disable; END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 43


********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.01          0          0          0           3

Misses in library cache during parse: 1



OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       15      0.00       0.00          0          0          0           0
Execute     59      0.00       0.00          0         17         77          28
Fetch       40      0.00       0.00          0        148          0          37
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      114      0.01       0.01          0        165         77          65

Misses in library cache during parse: 1
Misses in library cache during execute: 1





Note 1 : The first query for DISTINCT DEPARTMENT_IDs returned 12 rows (12 distinct Department_IDs).  Therefore, each of the SELECT and INSERT statements was executed 12 times.
There are some very interesting observations to be made.

Note 2 : The Rows (1st), (avg), (max) statistics for the SELECT SUM(SALARY) are not accurate as the trace file has not captured Row Source Statistics individually for each execution of the query.  Different DEPARTMENT_IDs actually have different Row Counts.  You have to be careful when interpreting these statistics.  Check the trace file to see if Row Source Statistics (indicated by "STAT" lines) are captured.


Firstly : The SQLs called from the PLSQL procedure are not accounted under "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS". This can be surmised by looking at the "Execute" and "Fetch" count statistics. The SQLs called from the PLSQL procedure are reported under "OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS".  That is why it can sometimes be very important to *not* ignore the "Recursive Statements" statistics.  Here, all the effort is in what are identified by tkprof as "Recursive Statements".  Some of the 59 Executions under "Recursive Statements" are NOT Parse overheads but actual User SQLs (called from the PLSQL procedure) !
I can also see from the raw trace file that my SELECT and INSERT statements appear with "dep=1" (and not "dep=0").  So, they are tracked as Recursive Depth SQLs, not Parent level SQLs.

PARSING IN CURSOR #139685522349264 len=44 dep=1 uid=43 oct=3 lid=43 tim=1446996115239966 hv=244159435 ad='70eaa1c0' sqlid='4xts9z878v4yb'
SELECT DISTINCT DEPARTMENT_ID FROM EMPLOYEES
END OF STMT

PARSING IN CURSOR #139685521574368 len=60 dep=1 uid=43 oct=3 lid=43 tim=1446996115241015 hv=2767233362 ad='70f496b0' sqlid='bnr7u92kg18ak'
SELECT SUM(SALARY) FROM EMPLOYEES WHERE DEPARTMENT_ID = :B1
END OF STMT

PARSING IN CURSOR #139685521624960 len=51 dep=1 uid=43 oct=2 lid=43 tim=1446996115241988 hv=3646814366 ad='6e08dea0' sqlid='b6yyghrcpvy4y'
INSERT INTO DEPARTMENTAL_SALARY VALUES (:B2 , :B1 )
END OF STMT


Secondly : those CASE-Sensitive SQL statements that I had in the procedure which should have generated different SQL_IDs are all transformed to ALL-UPPERCASE SQL statements with the additional blank spaces stripped out.  Thus, although we have two different sets of SELECT statements for the SUM(SALARY), they appear exactly the same (transformed to ALL-UPPERCASE) with the *same* SQL_ID in the raw trace.  Similarly, the two different INSERT statements appear exactly the same ALL-UPPERCASE statements.
This is in optimization that Oracle applies to SQL statements inside PLSQL.  They effectively become case-insensitive and similar.  Also, you can see that Oracle automatically assigns Bind Variables (:B1, :B2) in place of the placeholders I used (l_dept_id, l_tot_salary).


Note  :  SELECT statement statistics (consistent gets, disk reads,  rows etc are accounted under FETCH, while DML (e.g. INSERT) statement statistics are accounted under EXECUTE.


I can verify that the INSERTs were executed twice for each DEPARTMENT_ID :

SQL> select department_id, total_salary from departmental_salary order by 1;

DEPARTMENT_ID TOTAL_SALARY
------------- ------------
    10       8800
    10       8800
    20      38000
    20      38000
    30      49800
    30      49800
    40      13000
    40      13000
    50     312800
    50     312800
    60      57600
    60      57600
    70      20000
    70      20000
    80     609000
    80     609000
    90     116000
    90     116000
   100     103216
   100     103216
   110      40616
   110      40616



24 rows selected.

SQL> 


.
.
.