Skip navigation.

Hemant K Chitale

Syndicate content
I am an Oracle Database Specialist in Singapore.
get an rss feed of this blog at http://hemantoracledba.blogspot.com/feeds/posts/default?alt=rss
follow me on twitter : @HemantKChitale
Updated: 44 min 54 sec ago

Trace Files -- 11b : Using DBMS_SQLDIAG to trace the Optimization of an SQL Statement

Sun, 2016-02-07 07:46
My previous blogpost covered using ALTER SYSTEM/SESSION to set tracing for a specific SQL_ID that has been determined in advance.   The SQL may be executed in the future after the ALTER SYSTEM/SESSION.

Here is a method for an SQL that has already been executed.

SQL> select count(*) from all_objects_many_list
2 where created > sysdate-365;

COUNT(*)
----------
25548

SQL> begin
2 dbms_sqldiag.dump_trace(p_sql_id=>'b086mzzp82x7w',
3 p_component=>'Optimizer',
4 p_file_id=>'OPT_TRACE_b086mzzp82x7w');
5 end;
6 /

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_2987_OPT_TRACE_b086mzzp82x7w.trc

SQL>


Let's review the trace file.

Registered qb: SEL$1 0x99b9000 (PARSER)
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=4 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"

SPM: statement not found in SMB
SPM: statement not a candidate for auto-capture

**************************
Automatic degree of parallelism (ADOP)
**************************
Automatic degree of parallelism is disabled: Parameter.

PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
OPTIMIZER INFORMATION

******************************************
----- Current SQL Statement for this session (sql_id=0b1t991khf449) -----
/* SQL Analyze(148,0) */ select count(*) from all_objects_many_list
where created > sysdate-365
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x6be0d530 145 package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be0d530 12098 package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be6b738 1229 package body SYS.DBMS_SQLDIAG
0x6becaea8 2 anonymous block
*******************************************
Legend
The following abbreviations are used by optimizer trace.
CBQT - cost-based query transformation
JPPD - join predicate push-down
OJPPD - old-style (non-cost-based) JPPD
FPD - filter push-down
PM - predicate move-around
CVM - complex view merging
SPJ - select-project-join
SJC - set join conversion
SU - subquery unnesting
OBYE - order by elimination
OST - old style star transformation
ST - new (cbqt) star transformation
CNT - count(col) to count(*) transformation
JE - Join Elimination
JF - join factorization
CBY - connect by
SLP - select list pruning
DP - distinct placement
qb - query block
LB - leaf blocks
DK - distinct keys
LB/K - average number of leaf blocks per key
DB/K - average number of data blocks per key
CLUF - clustering factor
NDV - number of distinct values
Resp - response cost
Card - cardinality
Resc - resource cost
NL - nested loops (join)
SM - sort merge (join)
HA - hash (join)
CPUSPEED - CPU Speed
IOTFRSPEED - I/O transfer speed
IOSEEKTIM - I/O seek time
SREADTIM - average single block read time
MREADTIM - average multiblock read time
MBRC - average multiblock read count
MAXTHR - maximum I/O system throughput
SLAVETHR - average slave I/O throughput
dmeth - distribution method
1: no partitioning required
2: value partitioned
4: right is random (round-robin)
128: left is random (round-robin)
8: broadcast right and partition left
16: broadcast left and partition right
32: partition left using partitioning of right
64: partition right using partitioning of left
256: run the join in serial
0: invalid distribution method
sel - selectivity
ptn - partition
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
*************************************
PARAMETERS WITH ALTERED VALUES
******************************
Compilation Environment Dump
is_recur_flags = 8
Bug Fix Control Environment


*************************************
PARAMETERS WITH DEFAULT VALUES
******************************
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
parallel_execution_enabled = true
parallel_query_forced_dop = 0
parallel_dml_forced_dop = 0
parallel_ddl_forced_degree = 0
parallel_ddl_forced_instances = 0
_query_rewrite_fudge = 90
optimizer_features_enable = 11.2.0.4
_optimizer_search_limit = 5
.... continued to a long list of parameters ........
....................................................
Bug Fix Control Environment
fix 3834770 = 1
fix 3746511 = enabled
fix 4519016 = enabled
.... continued to a long list of bug fixes ........
...................................................
***************************************
PARAMETERS IN OPT_PARAM HINT
****************************
***************************************
Column Usage Monitoring is ON: tracking level = 1
***************************************

Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for 0b1t991khf449.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
OBYE: Considering Order-by Elimination from view SEL$1 (#0)
***************************
Order-by elimination (OBYE)
***************************
OBYE: OBYE bypassed: no order by to eliminate.
CVM: Considering view merge in query block SEL$1 (#0)
OJE: Begin: find best directive for query block SEL$1 (#0)
OJE: End: finding best directive for query block SEL$1 (#0)
CNT: Considering count(col) to count(*) on query block SEL$1 (#0)
*************************
Count(col) to Count(*) (CNT)
*************************
CNT: COUNT() to COUNT(*) not done.
query block SEL$1 (#0) unchanged
Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for 0b1t991khf449.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
SU: Considering subquery unnesting in query block SEL$1 (#0)
********************
Subquery Unnest (SU)
********************
SJC: Considering set-join conversion in query block SEL$1 (#0)
*************************
Set-Join Conversion (SJC)
*************************
SJC: not performed
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
PM: PM bypassed: Outer query contains no views.
PM: PM bypassed: Outer query contains no views.
query block SEL$1 (#0) unchanged
FPD: Considering simple filter push in query block SEL$1 (#0)
"ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
try to generate transitive predicate from check constraints for query block SEL$1 (#0)
finally: "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365

apadrv-start sqlid=398332482954924169
:
call(in-use=2008, alloc=16344), compile(in-use=56240, alloc=59416), execution(in-use=2456, alloc=4032)

*******************************************
Peeked values of the binds in SQL statement
*******************************************

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT COUNT(*) "COUNT(*)" FROM "HEMANT"."ALL_OBJECTS_MANY_LIST" "ALL_OBJECTS_MANY_LIST" WHERE "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
kkoqbc: optimizing query block SEL$1 (#0)

:
call(in-use=2056, alloc=16344), compile(in-use=57320, alloc=59416), execution(in-use=2456, alloc=4032)

kkoqbc-subheap (create addr=0x7f4409c4fb18)
****************
QUERY BLOCK TEXT
****************
select count(*) from all_objects_many_list
where created > sysdate-365
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (optimizer): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=0 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"

-----------------------------
SYSTEM STATISTICS INFORMATION
-----------------------------
Using NOWORKLOAD Stats
CPUSPEEDNW: 937 millions instructions/sec (default is 100)
IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
IOSEEKTIM: 10 milliseconds (default is 10)
MBRC: NO VALUE blocks (default is 8)


And here is the actual information about how the Costing is done and Execution Plan determined.

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
#Rows: 7197952 #Blks: 98279 AvgRowLen: 93.00 ChainCnt: 0.00
Index Stats::
Index: ALL_OBJ_M_L_CRTD_NDX Col#: 7
LVLS: 2 #LB: 19093 #DK: 1232 LB/K: 15.00 DB/K: 351.00 CLUF: 432893.00
Access path analysis for ALL_OBJECTS_MANY_LIST
***************************************
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]
Column (#7): CREATED(
AvgLen: 8 NDV: 1232 Nulls: 0 Density: 0.000812 Min: 2455803 Max: 2457343
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
Card: Original: 7197952.000000 Rounded: 1313133 Computed: 1313133.42 Non Adjusted: 1313133.42
Access Path: TableScan
Cost: 27174.11 Resp: 27174.11 Degree: 0
Cost_io: 26619.00 Cost_cpu: 6242311042
Resp_io: 26619.00 Resp_cpu: 6242311042
Access Path: index (index (FFS))
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 5173.00 resc_cpu: 4598699894
ix_sel: 0.000000 ix_sel_with_filters: 1.000000
Access Path: index (FFS)
Cost: 5581.95 Resp: 5581.95 Degree: 1
Cost_io: 5173.00 Cost_cpu: 4598699894
Resp_io: 5173.00 Resp_cpu: 4598699894
Access Path: index (IndexOnly)
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 3486.00 resc_cpu: 287452140
ix_sel: 0.182432 ix_sel_with_filters: 0.182432
Cost: 3511.56 Resp: 3511.56 Degree: 1
Best:: AccessPath: IndexRange
Index: ALL_OBJ_M_L_CRTD_NDX
Cost: 3511.56 Degree: 1 Resp: 3511.56 Card: 1313133.42 Bytes: 0

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


OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
Permutations for Starting Table :0
Join order[1]: ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]#0
***********************
Best so far: Table#: 0 cost: 3511.5623 card: 1313133.4203 bytes: 10505064
***********************
(newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000

*********************************
Number of join permutations tried: 1
*********************************
Enumerating distribution method (advanced)

Trying or-Expansion on query block SEL$1 (#0)
Transfer Optimizer annotations for query block SEL$1 (#0)
id=0 frofkks[i] (index start key) predicate="ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
Final cost for query block SEL$1 (#0) - All Rows Plan:
Best join order: 1
Cost: 3511.5623 Degree: 1 Card: 1313133.0000 Bytes: 10505064
Resc: 3511.5623 Resc_io: 3486.0000 Resc_cpu: 287452140
Resp: 3511.5623 Resp_io: 3486.0000 Resc_cpu: 287452140
kkoqbc-subheap (delete addr=0x7f4409c4fb18, in-use=26384, alloc=32840)
kkoqbc-end:
:
call(in-use=8664, alloc=49288), compile(in-use=59856, alloc=63560), execution(in-use=2456, alloc=4032)

kkoqbc: finish optimizing query block SEL$1 (#0)
apadrv-end
:
call(in-use=8664, alloc=49288), compile(in-use=60768, alloc=63560), execution(in-use=2456, alloc=4032)


Starting SQL statement dump

user_id=87 user_name=HEMANT module=SQL*Plus action=
sql_id=0b1t991khf449 plan_hash_value=1689651126 problem_type=3
----- Current SQL Statement for this session (sql_id=0b1t991khf449) -----
/* SQL Analyze(148,0) */ select count(*) from all_objects_many_list
where created > sysdate-365
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x6be0d530 145 package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be0d530 12098 package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be6b738 1229 package body SYS.DBMS_SQLDIAG
0x6becaea8 2 anonymous block
sql_text_length=96
sql=/* SQL Analyze(148,0) */ select count(*) from all_objects_many_list
where created > sysdate-365
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
-------------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
-------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 3512 | |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
| 2 | INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1282K | 10M | 3512 | 00:00:43 |
-------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - access("CREATED">SYSDATE@!-365)

Content of other_xml column
===========================
db_version : 11.2.0.4
parse_schema : HEMANT
plan_hash : 1689651126
plan_hash_2 : 1742296710
Outline Data:
/*+
BEGIN_OUTLINE_DATA

*** 2016-02-07 21:29:15.838
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "ALL_OBJECTS_MANY_LIST"@"SEL$1" ("ALL_OBJECTS_MANY_LIST"."CREATED"))
END_OUTLINE_DATA
*/

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
parallel_execution_enabled = true
parallel_query_forced_dop = 0
parallel_dml_forced_dop = 0
parallel_ddl_forced_degree = 0
parallel_ddl_forced_instances = 0
_query_rewrite_fudge = 90
optimizer_features_enable = 11.2.0.4
_optimizer_search_limit = 5
...... long list of optimizer parameters ...........
.....................................................
Bug Fix Control Environment
fix 3834770 = 1
fix 3746511 = enabled
fix 4519016 = enabled
...... long list of Bug Fixes .......................
.....................................................

Query Block Registry:
SEL$1 0x99b9000 (PARSER) [FINAL]

:
call(in-use=11728, alloc=49288), compile(in-use=90704, alloc=155568), execution(in-use=6408, alloc=8088)

End of Optimizer State Dump
Dumping Hints
=============
====================== END SQL Statement Dump ======================


So, this is also a supported method.  This DBMS_SQLDIAG package is available from 11.2
Unfortunately, however, DUMP_TRACE is not documented !  (see the 11.2 documentation on DBMS_SQLDIAG).

Note : If the SQL Statement and/or Plan have already been aged out / purged from the Shared Pool , a DUMP_TRACE would, obviously, not be able to print anything.
.
.
.

Categories: DBA Blogs

Trace Files -- 11 : Tracing the Optimization of an SQL Statement

Sun, 2016-01-31 07:53
So far, the previous examples have been on tracing the Execution of SQL statements and/or the Execution Plan used.

But what if you want to trace the Optimization --- identify how the Optimizer determined an "optimal" execution plan -- of an SQL statement.

Note : Pre-11g methods involved Event 10053.   But as with Event 10046, I prefer to use methods where I don't have to use an Event Number but a Name.  So, here I am not demonstrating the Event 10053 method itself.

Let's assume that there is a particular SQL identified as SQL_ID='b086mzzp82x7w' for which we need to know not just the Execution Plan but also how Oracle arrived at the Execution Plan.

Here's one way :

SQL> alter session set events 'trace[rdbms.SQL_Optimizer.*][sql:b086mzzp82x7w]';

Session altered.

SQL> select 'abc' from dual;

'AB
---
abc

SQL> select count(*) from small_insert;

COUNT(*)
----------
4

SQL> select count(*) from all_objects_many_list
2 where created > sysdate-365;

COUNT(*)
----------
25548

SQL> select count(*) from all_objects_many_list;

COUNT(*)
----------
7254201

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

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

SQL>

I have multiple SQLs executed in the session but am interested in the Optimization of only 1 SQL.  Note how the specific SQL_ID is specified in the ALTER SESSION SET EVENTS command.

The resultant trace file is a very long trace file with a listing of all the instance/session parameters (hidden and public), all the Bug Fixes and the costing done for the SQL.  The trace file captures only the SQL of interest, all the other SQLs in the same session are *not* in the trace file.

Here is an extract from the trace file :

Registered qb: SEL$1 0x2173aea0 (PARSER)
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=4 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"

SPM: statement not found in SMB

**************************
Automatic degree of parallelism (ADOP)
**************************
Automatic degree of parallelism is disabled: Parameter.

PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
OPTIMIZER INFORMATION

******************************************
----- Current SQL Statement for this session (sql_id=b086mzzp82x7w) -----
select count(*) from all_objects_many_list
where created > sysdate-365
*******************************************
Legend
The following abbreviations are used by optimizer trace.
CBQT - cost-based query transformation
JPPD - join predicate push-down
OJPPD - old-style (non-cost-based) JPPD
FPD - filter push-down
PM - predicate move-around
CVM - complex view merging
SPJ - select-project-join
SJC - set join conversion
SU - subquery unnesting
OBYE - order by elimination
OST - old style star transformation
ST - new (cbqt) star transformation
CNT - count(col) to count(*) transformation
JE - Join Elimination
JF - join factorization
CBY - connect by
SLP - select list pruning
DP - distinct placement
qb - query block
LB - leaf blocks
DK - distinct keys
LB/K - average number of leaf blocks per key
DB/K - average number of data blocks per key
CLUF - clustering factor
NDV - number of distinct values
Resp - response cost
Card - cardinality
Resc - resource cost
NL - nested loops (join)
SM - sort merge (join)
HA - hash (join)
CPUSPEED - CPU Speed
IOTFRSPEED - I/O transfer speed
IOSEEKTIM - I/O seek time
SREADTIM - average single block read time
MREADTIM - average multiblock read time
MBRC - average multiblock read count
MAXTHR - maximum I/O system throughput
SLAVETHR - average slave I/O throughput
dmeth - distribution method
1: no partitioning required
2: value partitioned
4: right is random (round-robin)
128: left is random (round-robin)
8: broadcast right and partition left
16: broadcast left and partition right
32: partition left using partitioning of right
64: partition right using partitioning of left
256: run the join in serial
0: invalid distribution method
sel - selectivity
ptn - partition
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
*************************************
PARAMETERS WITH ALTERED VALUES
Compilation Environment Dump
Bug Fix Control Environment


*************************************
PARAMETERS WITH DEFAULT VALUES
******************************
Compilation Environment Dump
........... long list of parameters and their values .........
..............................................................
.. followed by ...
........... long list of Bug Fixes that are enabled ..........
..............................................................


***************************************
PARAMETERS IN OPT_PARAM HINT
****************************
***************************************
Column Usage Monitoring is ON: tracking level = 1
***************************************

Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for b086mzzp82x7w.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
OBYE: Considering Order-by Elimination from view SEL$1 (#0)
***************************
Order-by elimination (OBYE)
***************************
OBYE: OBYE bypassed: no order by to eliminate.
CVM: Considering view merge in query block SEL$1 (#0)
OJE: Begin: find best directive for query block SEL$1 (#0)
OJE: End: finding best directive for query block SEL$1 (#0)
CNT: Considering count(col) to count(*) on query block SEL$1 (#0)
*************************
Count(col) to Count(*) (CNT)
*************************
CNT: COUNT() to COUNT(*) not done.
query block SEL$1 (#0) unchanged
Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for b086mzzp82x7w.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
SU: Considering subquery unnesting in query block SEL$1 (#0)
********************
Subquery Unnest (SU)
********************
SJC: Considering set-join conversion in query block SEL$1 (#0)
*************************
Set-Join Conversion (SJC)
*************************
SJC: not performed
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
PM: PM bypassed: Outer query contains no views.
PM: PM bypassed: Outer query contains no views.
query block SEL$1 (#0) unchanged
FPD: Considering simple filter push in query block SEL$1 (#0)
"ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
try to generate transitive predicate from check constraints for query block SEL$1 (#0)
finally: "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365

apadrv-start sqlid=12691376846034531580
:
call(in-use=2008, alloc=16344), compile(in-use=56240, alloc=58632), execution(in-use=2504, alloc=4032)

*******************************************
Peeked values of the binds in SQL statement
*******************************************

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT COUNT(*) "COUNT(*)" FROM "HEMANT"."ALL_OBJECTS_MANY_LIST" "ALL_OBJECTS_MANY_LIST" WHERE "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
kkoqbc: optimizing query block SEL$1 (#0)

:
call(in-use=2056, alloc=16344), compile(in-use=57184, alloc=58632), execution(in-use=2504, alloc=4032)

kkoqbc-subheap (create addr=0x7f5f216ff9d0)
****************
QUERY BLOCK TEXT
****************
select count(*) from all_objects_many_list
where created > sysdate-365
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (optimizer): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=0 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"

-----------------------------
SYSTEM STATISTICS INFORMATION
-----------------------------
Using NOWORKLOAD Stats
CPUSPEEDNW: 937 millions instructions/sec (default is 100)
IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
IOSEEKTIM: 10 milliseconds (default is 10)
MBRC: NO VALUE blocks (default is 8)

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
#Rows: 7197952 #Blks: 98279 AvgRowLen: 93.00 ChainCnt: 0.00
Index Stats::
Index: ALL_OBJ_M_L_CRTD_NDX Col#: 7
LVLS: 2 #LB: 19093 #DK: 1232 LB/K: 15.00 DB/K: 351.00 CLUF: 432893.00
Access path analysis for ALL_OBJECTS_MANY_LIST
***************************************
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]
Column (#7): CREATED(
AvgLen: 8 NDV: 1232 Nulls: 0 Density: 0.000812 Min: 2455803 Max: 2457343
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
Card: Original: 7197952.000000 Rounded: 1346076 Computed: 1346075.60 Non Adjusted: 1346075.60
Access Path: TableScan
Cost: 27174.11 Resp: 27174.11 Degree: 0
Cost_io: 26619.00 Cost_cpu: 6242311042
Resp_io: 26619.00 Resp_cpu: 6242311042
Access Path: index (index (FFS))
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 5173.00 resc_cpu: 4598699894
ix_sel: 0.000000 ix_sel_with_filters: 1.000000
Access Path: index (FFS)
Cost: 5581.95 Resp: 5581.95 Degree: 1
Cost_io: 5173.00 Cost_cpu: 4598699894
Resp_io: 5173.00 Resp_cpu: 4598699894
Access Path: index (IndexOnly)
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 3573.00 resc_cpu: 294660105
ix_sel: 0.187008 ix_sel_with_filters: 0.187008
Cost: 3599.20 Resp: 3599.20 Degree: 1
Best:: AccessPath: IndexRange
Index: ALL_OBJ_M_L_CRTD_NDX
Cost: 3599.20 Degree: 1 Resp: 3599.20 Card: 1346075.60 Bytes: 0

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


OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
Permutations for Starting Table :0
Join order[1]: ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]#0
***********************
Best so far: Table#: 0 cost: 3599.2033 card: 1346075.6041 bytes: 10768608
***********************
(newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000

*********************************
Number of join permutations tried: 1
*********************************
Enumerating distribution method (advanced)

Trying or-Expansion on query block SEL$1 (#0)
Transfer Optimizer annotations for query block SEL$1 (#0)
id=0 frofkks[i] (index start key) predicate="ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
Final cost for query block SEL$1 (#0) - All Rows Plan:
Best join order: 1
Cost: 3599.2033 Degree: 1 Card: 1346076.0000 Bytes: 10768608
Resc: 3599.2033 Resc_io: 3573.0000 Resc_cpu: 294660105
Resp: 3599.2033 Resp_io: 3573.0000 Resc_cpu: 294660105
kkoqbc-subheap (delete addr=0x7f5f216ff9d0, in-use=26384, alloc=32840)
kkoqbc-end:
:
call(in-use=8664, alloc=49288), compile(in-use=59704, alloc=62776), execution(in-use=2504, alloc=4032)

kkoqbc: finish optimizing query block SEL$1 (#0)
apadrv-end
:
call(in-use=8664, alloc=49288), compile(in-use=60616, alloc=62776), execution(in-use=2504, alloc=4032)


Starting SQL statement dump

user_id=87 user_name=HEMANT module=SQL*Plus action=
sql_id=b086mzzp82x7w plan_hash_value=1689651126 problem_type=3
----- Current SQL Statement for this session (sql_id=b086mzzp82x7w) -----
select count(*) from all_objects_many_list
where created > sysdate-365
sql_text_length=71
sql=select count(*) from all_objects_many_list
where created > sysdate-365
----- Explain Plan Dump -----
----- Plan Table -----

============
Plan Table
============
-------------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
-------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 3599 | |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
| 2 | INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1315K | 10M | 3599 | 00:00:44 |
-------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - access("CREATED">SYSDATE@!-365)

Content of other_xml column
===========================
db_version : 11.2.0.4
parse_schema : HEMANT
plan_hash : 1689651126
plan_hash_2 : 1742296710
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "ALL_OBJECTS_MANY_LIST"@"SEL$1" ("ALL_OBJECTS_MANY_LIST"."CREATED"))
END_OUTLINE_DATA
*/

Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
........... long list of parameters and their values .........
..............................................................
.. followed by ...
........... long list of Bug Fixes that are enabled ..........
..............................................................

Query Block Registry:
SEL$1 0x2173aea0 (PARSER) [FINAL]

:
call(in-use=11728, alloc=49288), compile(in-use=90576, alloc=152120), execution(in-use=6440, alloc=8088)

End of Optimizer State Dump
Dumping Hints
=============
====================== END SQL Statement Dump ======================

The trace file captured only the SQL of interest.  It also shows all the instance /session parameters and Bug Fixes that are relevant (these are very long lists so I have not reproduced them in entirety).
Note : The listing of parameters and Bug Fixes are very important in that if you have different execution plans in two different databases, you must verify the parameters and bug fixes and ensure that any differences in them are not relevant.

From the trace file, we can determine that this is the Execution Plan chosen :
-------------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
-------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 3599 | |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
| 2 | INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1315K | 10M | 3599 | 00:00:44 |
-------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - access("CREATED">SYSDATE@!-365)

Content of other_xml column
===========================
db_version : 11.2.0.4
parse_schema : HEMANT
plan_hash : 1689651126
plan_hash_2 : 1742296710
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "ALL_OBJECTS_MANY_LIST"@"SEL$1" ("ALL_OBJECTS_MANY_LIST"."CREATED"))
END_OUTLINE_DATA
*/

The computation of Cost appears here :
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]
Column (#7): CREATED(
AvgLen: 8 NDV: 1232 Nulls: 0 Density: 0.000812 Min: 2455803 Max: 2457343
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
Card: Original: 7197952.000000 Rounded: 1346076 Computed: 1346075.60 Non Adjusted: 1346075.60
Access Path: TableScan
Cost: 27174.11 Resp: 27174.11 Degree: 0
Cost_io: 26619.00 Cost_cpu: 6242311042
Resp_io: 26619.00 Resp_cpu: 6242311042
Access Path: index (index (FFS))
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 5173.00 resc_cpu: 4598699894
ix_sel: 0.000000 ix_sel_with_filters: 1.000000
Access Path: index (FFS)
Cost: 5581.95 Resp: 5581.95 Degree: 1
Cost_io: 5173.00 Cost_cpu: 4598699894
Resp_io: 5173.00 Resp_cpu: 4598699894
Access Path: index (IndexOnly)
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 3573.00 resc_cpu: 294660105
ix_sel: 0.187008 ix_sel_with_filters: 0.187008
Cost: 3599.20 Resp: 3599.20 Degree: 1
Best:: AccessPath: IndexRange
Index: ALL_OBJ_M_L_CRTD_NDX
Cost: 3599.20 Degree: 1 Resp: 3599.20 Card: 1346075.60 Bytes: 0

Note how different Access Paths (Table Scan, Index FFS, IndexOnly,IndexRange) are all listed. The Best is shown as an IndexRange on the ALL_OBJ_M_L_CRTD_NDX with a Cost of 3599.20 More details appear here :
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
Permutations for Starting Table :0
Join order[1]: ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]#0
***********************
Best so far: Table#: 0 cost: 3599.2033 card: 1346075.6041 bytes: 10768608
***********************
(newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000

*********************************
Number of join permutations tried: 1
*********************************
Enumerating distribution method (advanced)

Trying or-Expansion on query block SEL$1 (#0)
Transfer Optimizer annotations for query block SEL$1 (#0)
id=0 frofkks[i] (index start key) predicate="ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
Final cost for query block SEL$1 (#0) - All Rows Plan:
Best join order: 1
Cost: 3599.2033 Degree: 1 Card: 1346076.0000 Bytes: 10768608
Resc: 3599.2033 Resc_io: 3573.0000 Resc_cpu: 294660105
Resp: 3599.2033 Resp_io: 3573.0000 Resc_cpu: 294660105

This is a very detailed listing for an SQL query on a single Table (no joins) and a single candidate index.  Try running this with an SQL with Join of two or more tables and more than one candidate Index on each and see how complicated the Cost calculation becomes.


Note : To disable tracing in the session, I would run :

ALTER SESSION SET EVENTS 'trace[rdbms.SQL_Optimizer.*] off';


This sort of tracing can also be done with ALTER SYSTEM if you are not sure which session will be running the SQL_ID of interest and cannot interactively invoke the SQL from a private session.  
.
.
.



Categories: DBA Blogs

Trace Files -- 10c : Query and DML (INSERT)

Sun, 2016-01-24 04:52
In the previous posts, I have traced either
SELECT
or
INSERT or UPDATE or DELETE
statements

I have pointed out that the block statistics are reported as "FETCH" statistics for SELECTs and "EXECUTE" statistics for the DMLs

What if we have an INSERT ... AS SELECT ?

SQL ID: 5pf0puy1pmcvc Plan Hash: 2393429040

insert into all_objects_many_list select * from all_objects_short_list


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.73 16.19 166 1655 14104 28114
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.74 16.21 166 1655 14104 28114

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=1766 pr=166 pw=0 time=16204380 us)
28114 28114 28114 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=579 pr=0 pw=0 time=127463 us cost=158 size=2614881 card=28117)


insert into all_objects_many_list
select * from all_objects_short_list
where rownum < 11

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 6 11 10
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 6 11 10

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=6 pr=0 pw=0 time=494 us)
10 10 10 COUNT STOPKEY (cr=3 pr=0 pw=0 time=167 us)
10 10 10 TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=3 pr=0 pw=0 time=83 us cost=158 size=2614881 card=28117)


Since it is an INSERT statement, the block statistics are reported against EXECUTE (nothing reported against the FETCH), even though the Row Source Operations section shows use Table Access (i.e. SELECT) against the ALL_OBJECTS_SHORT_LIST table. Also note, as we have seen in the previous trace on INSERTs, the target table does not get reported in the Row Source Operations.

Here's another example.

SQL ID: 5fgnrpgk3uumc Plan Hash: 2703984749

insert into all_objects_many_list select * from dba_objects


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.25 0 0 0 0
Execute 1 0.63 3.94 82 2622 13386 28125
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.67 4.20 82 2622 13386 28125

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=2736 pr=82 pw=0 time=3954384 us)
28125 28125 28125 VIEW DBA_OBJECTS (cr=360 pr=2 pw=0 time=1898588 us cost=105 size=5820219 card=28117)
28125 28125 28125 UNION-ALL (cr=360 pr=2 pw=0 time=1735711 us)
0 0 0 TABLE ACCESS BY INDEX ROWID SUM$ (cr=2 pr=2 pw=0 time=65154 us cost=1 size=11 card=1)
1 1 1 INDEX UNIQUE SCAN I_SUM$_1 (cr=1 pr=1 pw=0 time=61664 us cost=0 size=0 card=1)(object id 986)
0 0 0 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us cost=3 size=25 card=1)
0 0 0 INDEX RANGE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)(object id 36)
28124 28124 28124 FILTER (cr=354 pr=0 pw=0 time=1094905 us)
28124 28124 28124 HASH JOIN (cr=354 pr=0 pw=0 time=911322 us cost=102 size=3402036 card=28116)
68 68 68 TABLE ACCESS FULL USER$ (cr=5 pr=0 pw=0 time=328 us cost=3 size=1224 card=68)
28124 28124 28124 HASH JOIN (cr=349 pr=0 pw=0 time=612040 us cost=99 size=2895948 card=28116)
68 68 68 INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=159 us cost=1 size=1496 card=68)(object id 47)
28124 28124 28124 TABLE ACCESS FULL OBJ$ (cr=348 pr=0 pw=0 time=147446 us cost=98 size=2277396 card=28116)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=2 size=30 card=1)
0 0 0 INDEX SKIP SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)(object id 47)
0 0 0 INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=10 card=1)(object id 39)
1 1 1 NESTED LOOPS (cr=4 pr=0 pw=0 time=262 us cost=3 size=38 card=1)
1 1 1 TABLE ACCESS FULL LINK$ (cr=2 pr=0 pw=0 time=180 us cost=2 size=20 card=1)
1 1 1 TABLE ACCESS CLUSTER USER$ (cr=2 pr=0 pw=0 time=50 us cost=1 size=18 card=1)
1 1 1 INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=21 us cost=0 size=0 card=1)(object id 11)

Only the source tables are reported in the Row Source Operations section. All the blocks are reported in the EXECUTE phase. Why does the "query" count in the EXECUTE statistics differ from the "cr" count reported for the LOAD TABLE CONVENTIONAL. (LOAD TABLE CONVENTIONAL indicates a regular non-direct-path INSERT).
.
.
.

Categories: DBA Blogs

Trace Files -- 10b : More DML Tracing

Tue, 2015-12-15 08:30
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).
.
.
.


Categories: DBA Blogs

Trace Files -- 10 : Tracing DML

Sun, 2015-12-13 08:15
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.
.
.
.



Categories: DBA Blogs

Trace Files -- 9 : Advantages

Wed, 2015-12-09 08:47
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.
Categories: DBA Blogs

Trace Files -- 8d : Full Table Scans

Sun, 2015-12-06 05:05
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 ";")

.
.
.


Categories: DBA Blogs

Auditing DBMS_STATS usage

Thu, 2015-12-03 09:05
(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>

.
.
.
Categories: DBA Blogs

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

Sun, 2015-11-29 09:46
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. .
.
.

Categories: DBA Blogs

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

Sun, 2015-11-22 04:40
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.

.
.
.


Categories: DBA Blogs

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

Sun, 2015-11-15 09:43
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).
,
,
,
Categories: DBA Blogs

Trace Files -- 7 : SQL in PL/SQL

Sun, 2015-11-08 09:50
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>


.
.
.

Categories: DBA Blogs

SSL Support

Mon, 2015-11-02 00:45
This blog now supports SSL connections.

Browse this blog using https://   instead of http://   for a secure connection when accessing a specific page.

...
Categories: DBA Blogs

Trace Files -- 6 : Multiple Executions of the same SQL

Sun, 2015-11-01 08:06
In the previous two posts, I demonstrated a single execution of an SQL query and interpreting the raw trace and the tkprof summary for it.  The demonstration also showed the Hard Parsing for the first execution of the query.

What if
(a) We have multiple executions of the same SQL ?  Likely the first execution, if the Plan doesn't already exist in the Shared Pool, requires a Hard Parse  (Also, the first execution immediately after enabling Tracing itself requires a Hard Parse).
(b) Row Counts change for subsequent executions.
(c) Something happens that causes a fresh Hard Parse for a subsequent execution.  That something could be a DDL against the source table causing Invalidation of the SQL.  Possibly even a change of the Execution Plan


I'll create a demo here.  I am taking exactly the same SQL as in the previous demo.

SQL> connect hr/oracle
Connected.
SQL> exec DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE);

PL/SQL procedure successfully completed.

SQL> select count(*) from employees;

COUNT(*)
----------
107

SQL> select count(*) from employees;

COUNT(*)
----------
214

SQL> select count(*) from employees;

COUNT(*)
----------
214

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_3119.trc

SQL>


What are the changes I made for the second and third executions ?  Quite obviously, I have duplicated the number of rows before the second execution of the query.  Then, some other change before the third execution.
These are the two changes made from another session :

SQL> insert into employees
2 select employee_id+1000, first_name||'_A', last_name||'_B', email||'.XYZ', phone_number, hire_date+1, job_id, salary, commission_pct,
3 manager_id, department_id
4 from employees
5 /

107 rows created.

SQL> commit;

Commit complete.

SQL> alter table employees drop constraint emp_email_uk;

Table altered.

SQL> drop index emp_email_uk;
drop index emp_email_uk
*
ERROR at line 1:
ORA-01418: specified index does not exist


SQL>


The first change added 107 rows to the table. The second change dropped the index that was being used by the initial Execution Plan.

Let's look at a tkprof of the trace file.  Here, I use the option aggregate=NO to separately report each execution of the query.

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3119.trc \
> My_3_Queries.PRF aggregate=NO sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 1 21:27:15 2015

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


[oracle@ora11204 Desktop]$


The aggregate=NO separates the three executions of the same SQL_ID. Extracting the lines from the tkprof, we see that each individual execution is reported separately

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
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 2 0.00 0.00 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 1 1 0 1

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=1 pw=0 time=235 us)
107 107 107 INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=412 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
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 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=66 us)
214 214 214 INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=0 pw=0 time=447 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 1426549735

select count(*)
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 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=63 us)
214 214 214 INDEX FULL SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=554 us cost=1 size=0 card=107)(object id 16405)



We can see that the first execution read 107 Rows (ROWIDs) from the Index EMP_EMAIL_UK (a Unique Key Index on the EMAIL_ADDRESS).  This also matched the expected cardinality of 107 rows (shown by "card=107").

However, the second execution, reading the same EMP_EMAIL_UK index and expected cardinality of 107 actually read 214 Rows (ROWIDs).  (Because of the additional 107 rows inserted and committed by the separate session)

The third execution used a different Index EMP_EMP_ID_PK (because the EMP_EMAIL_UK index was no longer present).  Here, too, there was a mismatch between the expected cardinality ("card=107") and the actual Rows (ROWIDs) count of 214.

The mismatch between cardinality and actual Rows (ROWIDs) from the indexes in the 2nd and 3rd executions occur because although 107 new rows are inserted, index statistics are not updated.

Did you also note that the second execution had a Parse and a "Misses in library cache during parse:" ?  The trace file (not presented in this post) shows that the cursor for the first execution had been closed but does not show Hard Parsing (no recursive SQLs).  That parse was a Soft Parse.



What if I had *NOT* used the aggregate=NO option in tkprof ?  The default is aggregate=YES.  This is what it would present  (I can take the same raw trace file and generate a new tkprof output file) :

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3119.trc \
> My_3_Queries_AGGREGATED.PRF sys=NO

TKPROF: Release 11.2.0.4.0 - Development on Sun Nov 1 21:51:51 2015

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


[oracle@ora11204 Desktop]$

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
from
employees


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

Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: 43
Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=150 us)
107 160 214 INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=0 pw=0 time=430 us cost=1 size=0 card=107)(object id 16404)


SQL ID: 7c1rnh08dp922 Plan Hash: 1426549735

select count(*)
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 2 0.00 0.00 0 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 1 0 1

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=0 pw=0 time=63 us)
214 214 214 INDEX FULL SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=554 us cost=1 size=0 card=107)(object id 16405)



Here it shows the SQL twice.

The first entry is for *2* executions, with the same Plan Hash Value.  The Rows statistics shows statistics for the 1st execution, the average and the last execution.  Thus, we can discern that not all the executions had the same Row Statistics.  The first execution read 107 Rows (ROWIDs) from the Index, the last execution read 214 from the same Index (using the same Execution Plan).  Therefore, it is important to understand that execution statistics for the same Execution Plan can vary !  If you suspect that execution statistics are varying, I recommend that you use the aggregate=NO option to tkprof.  {I suggest that you create a test case where you have 3 or more executions with the same Plan Hash Value and Execution Plan and yet have different statistics (e.g. simply Row Counts) and see how the Plan / Row statistics are reported}
Note : Earlier versions of Oracle wouldn't report "Rows (1st) Rows (avg) Rows (max)" but would likely have reported Row Source statistics only for the last execution.

The second entry is for the 3rd execution, with a different Plan Hash Value and Execution Plan (using the EMP_EMP_ID_PK index).

Conclusion :  Thus, we have one SQL with one SQL_ID, two different Execution Plans and three sets of Execution Statistics.  Simply because the underlying data or DDL can change between executions of the same SQL in the same session.

.
.
.



Categories: DBA Blogs

Trace Files -- 5.2 : Interpreting the SQL Trace Summary level

Wed, 2015-10-28 09:08
Picking up the same SQL Trace file from my previous post, I run (the well known) utility tkprof on it.

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc My_Query.PRF sys=no

TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015

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


[oracle@ora11204 Desktop]$
[oracle@ora11204 Desktop]$ cat My_Query.PRF

TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015

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

Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: dc03x7r071fvn Plan Hash: 0

BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE); END;


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

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

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 11.45 11.45
********************************************************************************

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*)
from
employees


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

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=1 pr=1 pw=0 time=14407 us)
107 107 107 INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=14577 us cost=1 size=0 card=107)(object id 16404)


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
SQL*Net message from client 2 13.27 13.27
********************************************************************************

SQL ID: 9wuhwhad81d36 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: 1
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.02 0 0 0 0
Execute 3 0.00 0.03 0 0 0 2
Fetch 2 0.00 0.01 1 1 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.06 1 1 0 3

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

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
SQL*Net message from client 3 13.27 24.73
db file sequential read 1 0.00 0.00
Disk file operations I/O 1 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 43 0.00 0.00 0 0 0 0
Fetch 90 0.00 0.01 3 165 0 68
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 133 0.00 0.01 3 165 0 68

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 3 0.01 0.01

3 user SQL statements in session.
12 internal SQL statements in session.
15 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
3 user SQL statements in trace file.
12 internal SQL statements in trace file.
15 SQL statements in trace file.
15 unique SQL statements in trace file.
284 lines in trace file.
24 elapsed seconds in trace file.


[oracle@ora11204 Desktop]$


With the "sys=no" command-line flag, I have excluded reporting the recursive (SQL) calls although the summary statistics on them do appear.  There were a total of 43 executions of recursive calls.  The SQL*Net message from client is a wait of 13.27seconds (which is normally considered as an "idle wait").  We see this also in the previous post on the raw trace as the wait event before Tracing is disabled.
The only significant wait event was "db file sequential read" which is less than 1centisecond so is reported as 0.00second.  However, from the previous post, we can see that the raw trace file shows a wait time of 6,784 microseconds
.
.
.


Categories: DBA Blogs

Trace Files -- 5.1 : Reading an SQL Trace

Wed, 2015-10-28 08:53
Here's a short introduction to reading an SQL Trace.

First I execute these in my sqlplus session :

SQL> connect hr/oracle
Connected.
SQL> exec DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE);

PL/SQL procedure successfully completed.

SQL> select count(*) from employees;

COUNT(*)
----------
107

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_3039.trc

SQL>



Now, I extract selective portions of the trace file.

The header of the trace file gives me inormation about the platform and session/module :

Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
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_HOME = /u01/app/oracle/product/11.2.0/orcl
System name: Linux
Node name: ora11204
Release: 2.6.39-400.17.1.el6uek.x86_64
Version: #1 SMP Fri Feb 22 18:16:18 PST 2013
Machine: x86_64
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 27
Unix process pid: 3039, image: oracle@ora11204 (TNS V1-V3)


*** 2015-10-28 22:19:42.291
*** SESSION ID:(141.7) 2015-10-28 22:19:42.291
*** CLIENT ID:() 2015-10-28 22:19:42.291
*** SERVICE NAME:(SYS$USERS) 2015-10-28 22:19:42.291
*** MODULE NAME:(SQL*Plus) 2015-10-28 22:19:42.291
*** ACTION NAME:() 2015-10-28 22:19:42.291


The trace file tells me that I am running 64bit Oracle 11.2.0.4 on a speciic Linux (UEK) kernel on a host called "ora11204".  This is useful information if I have to provide the trace file to Oracle Support.  (True, it doesn't list all the Oracle patches that may have been applied).
It then identifies my Service Name and Module (and Action if I had set it with DBMS_APPLICATION_INFO).

Next, the trace file tells me when and how I have enabled tracing.

PARSING IN CURSOR #140174891232936 len=73 dep=0 uid=43 oct=47 lid=43 tim=1446041982290677 hv=3228613492 ad='99446cc8' sqlid='dc03x7r071fvn'
BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE); END;
END OF STMT
EXEC #140174891232936:c=1000,e=31608,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1446041982290670
WAIT #140174891232936: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041982291265


It tells me that I have used DBMS_SESSION to enable tracing.

That cursor is then closed.

*** 2015-10-28 22:19:53.745
WAIT #140174891232936: nam='SQL*Net message from client' ela= 11453710 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041993745004
CLOSE #140174891232936:c=0,e=38,dep=0,type=0,tim=1446041993745175


We can identify the CURSOR Number (140174891232936-- this numbering format was introduced in 11g, if I am correct) that was closed.  This number is NOT the SQL_ID (which is dc03x7r071fvn -- yes even PLSQL blocks and procedures have SQL_IDs).  This number is NOT the SQL Hash Value either (the SQL Hash Value is present as hv=3228613492).

After that we start seeing the recursive (SYS) calls executed during the parsing of the actual user query (the query on EMPLOYEES).

PARSING IN CURSOR #140174891988920 len=202 dep=1 uid=0 oct=3 lid=0 tim=1446041993745737 hv=3819099649 ad='997c03e0' sqlid='3nkd3g3ju5ph1'
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #140174891988920:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1446041993745733
FETCH #140174891988920:c=999,e=88,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=2853959010,tim=1446041993745957
CLOSE #140174891988920:c=0,e=11,dep=1,type=3,tim=1446041993746025
=====================
PARSING IN CURSOR #140174891955728 len=493 dep=1 uid=0 oct=3 lid=0 tim=1446041993746138 hv=2584065658 ad='997a6590' sqlid='1gu8t96d0bdmu'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
EXEC #140174891955728:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3526770254,tim=1446041993746134
FETCH #140174891955728:c=0,e=53,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=3526770254,tim=1446041993746225
CLOSE #140174891955728:c=0,e=8,dep=1,type=3,tim=1446041993746254


I have shown only the first two recursive calls.  These are identified by "dep=1"  (the parent call by the user we shall see is at depth level 0) and also by uid=0, lid=0  (schema id and privilege userid being 0 for SYS).  len=493 is the length of the SQL statement.

The elapsed time in microseconds is the "e=" value while the CPU time is "c=" in microseconds.  The "p=" value is Physical Reads, the "cr=" value is Consistent Gets, "cu=" is Current Gets, "r=" is Number of Rows.  "og=" shows the Optimizer Goal (og=4 is "Choose").  "tim=" is an ever-increasing timestamp (i.e. to calculate elapsed time between two SQL calls you can deduct the first "tim" value from the second.

Following these two are a number of other recursive SQL calls that I shall skip over until I come to my user SQL.

PARSING IN CURSOR #140174891232936 len=30 dep=0 uid=43 oct=3 lid=43 tim=1446041993782992 hv=282764354 ad='99446f28' sqlid='7c1rnh08dp922'
select count(*) from employees
END OF STMT
PARSE #140174891232936:c=8998,e=37717,p=3,cr=165,cu=0,mis=1,r=0,dep=0,og=1,plh=3580537945,tim=1446041993782979
EXEC #140174891232936:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3580537945,tim=1446041993783188
WAIT #140174891232936: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041993783286
WAIT #140174891232936: nam='Disk file operations I/O' ela= 76 FileOperation=2 fileno=4 filetype=2 obj#=16404 tim=1446041993790690
WAIT #140174891232936: nam='db file sequential read' ela= 6784 file#=4 block#=211 blocks=1 obj#=16404 tim=1446041993797581
FETCH #140174891232936:c=7000,e=14409,p=1,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3580537945,tim=1446041993797727
STAT #140174891232936 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=1 pw=0 time=14407 us)'
STAT #140174891232936 id=2 cnt=107 pid=1 pos=1 obj=16404 op='INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=14577 us cost=1 size=0 card=107)'
WAIT #140174891232936: nam='SQL*Net message from client' ela= 486 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446041993819989
FETCH #140174891232936:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3580537945,tim=1446041993820032
WAIT #140174891232936: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446041993820057


The "dep=0" and "uid" and "lid" not being 0 indicate that this is a User SQL.  "oct" is the Oracle Command Type.
Here in addition to information on the PARSE call, the EXEC call, the individual WAITs and the FETCH call, we can also see Row Source Statistics indicated by the STAT lines.
The Parse was 37,717 microseconds and the FETCH time was 14,409 microseconds.  (This is a very quick running SQL but since it had never been parsed in ths instance, the Parse time exceeded the FETCH time),  The "mis=1" for the Parse indicates a Miss in the Library Cache -- so Oracle had to do a Hard Parse.
I would look at EXEC for INSERT/UPDATE/DELETE statements but here for a simple SELECT, I look at the FETCH time.
For the 'db file sequential read' wait of 6,784microseconds, we can also see the File Number ("file#"), the Block ID ("block#"), number of Blocks (1 for this wait event) and Object ID ("obj#")


The STAT lines have additional information about the position ("pos")  and parent id ("pid") in the Execution Plan.  The Object ID is indicated by "obj" and the operation by "op". STAT lines show the Consistent Gets ("cr"), Physical Reads ("pr") , the Time ("time") in microseconds, the cost ("cost") and expected cardinality ("card") for each step of the Execution Plan. Note that the expected cardinality is "card" but the actual count of rows is "cnt".

Next, the cursor is closed, and tracing disabled.

*** 2015-10-28 22:20:07.096
WAIT #140174891232936: nam='SQL*Net message from client' ela= 13276436 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446042007096511
CLOSE #140174891232936:c=0,e=19,dep=0,type=0,tim=1446042007096668
=====================
PARSING IN CURSOR #140174891232936 len=48 dep=0 uid=43 oct=47 lid=43 tim=1446042007097875 hv=2592126054 ad='96fff810' sqlid='9wuhwhad81d36'
BEGIN DBMS_SESSION.SESSION_TRACE_DISABLE; END;
END OF STMT
PARSE #140174891232936:c=999,e=1129,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1446042007097870
EXEC #140174891232936:c=0,e=313,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1446042007098285


Note how the CURSOR ID get's reused by the next SQL if the previous SQL cursor was closed.  Thus "140174891232936" was used by the PLSQL call  that enabled Tracing, then closed, then by the user SQL query on EMPLOYEES, then Closed, then by the  PLSQL call that disabled Tracing.
(The recursive SQLs in between had different CURSOR IDs).

(As an observation : Notice how the "obj#" doesn't get cleared even when the next wait is an "SQL*Net message to client" or "SQL*Net message from client")
.
.
.

Categories: DBA Blogs