13.7 Oracle event interface

---

SQL Trace is a simple straightforward approach to getting to the execution plan generated by Oracle for the various SQL queries. The information provided by these trace files is only minimal. While SQL_TRACE is a good start to getting to the basic execution behavior, it seldom provides any details on the actual reasons for the performance characteristics or the reasons why the optimizer showed a specific behavior during query execution.

Oracle provides certain events that can be enabled at the system or session level to capture information for all sessions or at the session level.

Event 10046

Enabling event 10046 at various levels provides varying details about the execution plans, performance characteristics, and other related information.

Level 1

This is enabled at the system level using the following statement:

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1';

or at the session level

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1'

Setting event 10046 at level 1 is equivalent to setting the SQL_TRACE parameter to TRUE in the init<SID>.ora file or enabling trace at a session level. The output produced by this event is generated in the user dump destination directory. The trace file could be interpreted in a more readable format using the TKPROF similar to the SQL_TRACE feature listed above.

The following is the output generated by tracing event 10046 at level 1 on the SQL query:

call    count  cpu  elapsed  disk  query  current  rows ------- ----- ---- ------- ---- ------ ------- ------- Parse   2205    0.14   0.15    0    1608     0      0 Execute 6880    3.19   4.14    0       0     0      0 Fetch   6880    3.19   6.24    67  38590     0    6880 ------- ----- ---- ------- ---- ------ ------- ------- total   15965   6.52   10.54   67   40198    0    6880     Misses in library cache during parse: 0 Optimizer goal: CHOOSE Parsing user id: 33 (MVALLATH) Rows   Row Source Operation ----- --------------------------------------------- 487    SORT ORDER BY (cr=3218 r=67 w=66 time=374942 us) 487    TABLE ACCESS BY GLOBAL INDEX ROWID USER_SECURITY PARTITION: 1 1       (cr=3218 r=67 w=66 time=366031 us) 978    NESTED LOOPS (cr=3130 r=67 w=66 time=362323 us) 490    NESTED LOOPS (cr=2638 r=67 w=66 time=350329 us) 490      NESTED LOOPS (cr=1656 r=67 w=66 time=337860 us) 490       VIEW (cr=674 r=67 w=66 time=322853 us) 490     HASH JOIN (cr=674 r=67 w=66 time=321329 us) 56373 INDEX FAST FULL SCAN PK_USRLI PARTITION: 1 1 (cr=190 r=1 w=0 time=44521 us)(object id 24891) 490     INDEX FAST FULL SCAN USRLI_INDX1 (cr=484 r=0 w=0 time=73787 us) (object id 24706) 490      TABLE ACCESS BY LOCAL INDEX ROWID USER_PROFILE PARTITION: 1 1 (cr=982 r=0 w=0 time=11879 us) 490     INDEX UNIQUE SCAN PK_USPRL PARTITION: 1 1 (cr=492 r=0 w=0 time=5923 us)(object id 24741) 490    TABLE ACCESS BY LOCAL INDEX ROWID COMPANY PARTITION: 1 1 (cr=982 r=0 w=0 time=9774 us) 490     INDEX UNIQUE SCAN PK_COMP PARTITION: 1 1 (cr=492 r=0 w=0 time=4757 us)(object id 24813) 487      INDEX RANGE SCAN USEC_INDX1 (cr=492 r=0 w=0 time=8898 us)(object id 24694)     Rows    Execution Plan ---- ----------------------------------------------- 0      SELECT STATEMENT GOAL: CHOOSE 487     SORT (ORDER BY) 487      TABLE ACCESS GOAL: ANALYZED (BY GLOBAL INDEX ROWID) OF          'USER_SECURITY' PARTITION: START=1 STOP=1 978       NESTED LOOPS 490        NESTED LOOPS 490          NESTED LOOPS 490       VIEW OF 'index$_join$_003' 490      HASH JOIN 156373   INDEX GOAL: ANALYZED (FAST FULL SCAN) OF         'PK_USRLI' (UNIQUE) PARTITION: START=1 STOP=1 490    INDEX GOAL: ANALYZED (FAST FULL SCAN) OF       'USRLI_INDX1' (NON-UNIQUE) 490     TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF         'USER_PROFILE' PARTITION: START=1 STOP=1 490    INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_USPRL'         (UNIQUE) PARTITION: START=1 STOP=1 490    TABLE ACCESS GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF        'COMPANY' PARTITION: START=1 STOP=1 490     INDEX GOAL: ANALYZED (UNIQUE SCAN) OF 'PK_COMP'         (UNIQUE) PARTITION: START=1 STOP=1 487      INDEX GOAL: ANALYZED (RANGE SCAN) OF 'USEC_INDX1'          (NON-UNIQUE)

Interpreting the trace output generated using TKPROF:

• Call: Statistics for each cursor's activity are divided into three areas:

  Parse: Statistics from parsing the cursor. This includes information for plan generation, etc.

  Execute: Statistics for the execution phase of a cursor.

  Fetch: Statistics for actually fetching the rows.

• Count: Number of times a particular activity is performed on this particular cursor.

• CPU: CPU time used by this cursor.

• Elapsed: Elapsed time for this cursor.

• Disk: This indicates the number of blocks read from disk. Generally, it is preferable to see blocks being read from the buffer cache rather than disk.

• Query: This column is incremented if a buffer is read in consistent mode. A consistent mode buffer is one that has been generated to give a consistent read snapshot for a long-running transaction. The buffer actually contains this status in its header.

• Current: This column is incremented if a buffer is found in the buffer cache that is new enough for the current transaction and is in current mode (and it is not a CR buffer). This applies to buffers that have been read into the cache as well as buffers that already exist in the cache in current mode.

• Rows: Rows retrieved by this step.

Further in the output generated from tracing event 10046, please note the rows column in the execution plan. This indicates the number of rows that the buffer is carrying around during each of these steps. The highest number of rows is in

156373 INDEX GOAL: ANALYZED (FAST FULL SCAN) OF 'PK_USRLI' (UNIQUE) PARTITION: START =1 STOP =1

This could be where the actual performance problem lies. The main question that arises when examining the trace file would be, why are 156,373 rows being retrieved and filtered through at this step when the actual number of rows returned is only 487?

Such detailed information is not found in a regular EXPLAIN PLAN created from the AUTOTRACE feature.

Level 4

Level 1 tracing of event 10046 provides the basic SQL queries; sometimes to re-create the issue or to re-execute the query, these basic raw queries and their EXPLAIN PLAN(s) are not sufficient, especially if the query is using bind variables. Using bind variables is an excellent practice and should be in the best practices guide of the organization. For debugging and query tuning purposes it would be helpful to determine the values used during the query execution. To determine the bind variables and the corresponding bind values, event 10046 at level 4 would capture the information.

Similar to level 1, level 4 can be enabled at the system or session level using the following statements:

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4';  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4';

Level 8

Many times the query performs poorly due to several reasons other than the way in which the query is written. For example, slow performance could be due to the way the table has been stored on disk, poor distribution of data on the disk, too many tables sharing the same data files, data heavily scattered, or because the query is performing full table scans. There are no other reasons for the slow performance; however, the EXPLAIN PLAN(s) generated by the previous methods do not provide the actual reasons for the slowness. Under such circumstances, it would be good to enable event 10046 at level 8 to capture the additional information.

Similar to level 1 and level 4, level 8 can be enabled at the system or session levels through the following statements:

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER,  LEVEL 8'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

The following is the additional information generated by event 10046 at level 8:

Elapsed times include waiting on following events: Event waited on Times Waited Max. Wait Total Waited -------------------------------------------------------- db file sequential read 38479 230.02 3846.51 SQL*Net message to client 13760 0.00 0.04 SQL*Net message from client 13760 3.45 3238.44 global cache cr request 1355 0.20 3.02 library cache lock 31 0.00 0.00 SQL*Net more data from client 31 0.00 0.00 KJC: Wait for msg sends to complete 12 0.00 0.00 global cache s to x 11 0.03 0.04 buffer busy global CR 4 0.00 0.00 latch free 3 0.02 0.05 buffer busy global cache 1 0.01 0.01 ****************************************************** 

The above output lists the various wait events encountered during the query execution time. Now from the above it is certain that there are several wait situations that could have caused a performance slowdown for the query, and the query itself may not be the problem.

For example, the highest value in the ''times waited'' column is for db file sequential read. This wait indicates that the query requests a sequential access on the table to retrieve rows and is waiting for the read to complete. It indicates that the database is performing single block reads. This could happen when reading from an index, rollback segment, or sort area, rebuilding a control file, and while dumping data file headers. This wait could raise several questions like, should there be an index lookup, is the table small enough that full table scans would be more efficient? If the wait is consistently increasing for several sessions on this specific query, further drilldown by looking into the segment-level information may be helpful.

An SQL*Net message from the client indicates that the Oracle process is waiting for a message from the client (the application tier). This could be due to several factors; in particular the time waited may be misleading because this also includes idle waits. However, this may not be the case on a busy systems where it could indicate network latency. To improve the SQL*Net from and to the client would require tuning the SQL*Net traffic. Enabling trace at this level and examining the session data unit (SDU) and transport data unit (TDU) values will tune the settings for this parameter. The network value could be set in the tnsnames.ora file on the client side of the application.

Level 12

Level 12 provides a combined output of all the above levels. At this level, the execution plans, bind variables, bind values (generated with level 4), and the wait events (generated with level 8) are provided in the trace files. Most often, enabling event 10046 at level 12 will provide a comprehensive method of looking at the problem in hand. However, the output generated at this level could be large and may require considerable amount of disk space. Enabling a trace at this level should be done only after ensuring sufficient space is available.

Similar to the other levels, level 12 can be enabled at the system or session levels through the following statements:

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

Event 10053

Many times, when the query is being tuned for performance and after generating the EXPLAIN PLAN, trace files, turning on event 10046, looking at wait statistics, etc., the following questions arise during the query tuning or application execution process. Why is the execution plan being generated in this fashion? Why is the runtime performance different from interactive performance?

Under these circumstances, if the database has been configured to use the CBO, event 10053 will capture the actual steps that the CBO has taken to generate the execution plan.

Enabling event 10053 is similar to enabling any other event, that is, by using an ALTER SYSTEM or ALTER SESSION statement. However, unlike event 10046 that was discussed in the previous section, event 10053 can generate trace information only at two levels, level 1 and level 2:

ALTER SYSTEM SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';  ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 2'; 

The following is a partial output of the optimizer behavior generated from event 10053 at level 1:

*************************************** OPTIMIZER STATISTICS AND COMPUTATIONS *************************************** GENERAL PLANS *********************** Join order[1]: USER_LOGIN [UL] COMPANY [CMP] USER_PROFILE [UP]    USER_SECURITY [US] Now joining: COMPANY [CMP] ******* NL Join     Outer table: cost: 4 cdn: 19 rcz: 18 resp: 4     Inner table: COMPANY      Access path: tsc Resc: 11      Join: Resc: 213 Resp: 213 Join cardinality: 27075 = outer (19) * inner (1425) * sel (1.0000e+00)   [flag=0]    Best NL cost: 214 resp: 213 Join result: cost: 214 cdn: 27075 rcz: 56   Now joining: USER_PROFILE [UP] *******  NL Join Outer table: cost: 214 cdn: 27075 rcz: 56 resp: 213 Inner table: USER_PROFILE Access path: tsc Resc: 11 Join: Resc: 298038 Resp: 298038 OPTIMIZER PERCENT INDEX CACHING = 90 Access path: index (unique) Index: PK_USPRL TABLE: USER_PROFILE RSC_CPU: 0 RSC_IO: 1 IX_SEL: 6.4350e-04 TB_SEL: 6.4350e-04 Join: resc: 1567 resp: 1567 OPTIMIZER PERCENT INDEX CACHING = 90 Access path: index (join index) Index: USPRL_INDX1 TABLE: USER_PROFILE RSC_CPU: 0 RSC_IO: 2 IX_SEL: 0.0000e+00 TB_SEL: 3.0581e-03 Join: resc: 2921 resp: 2921 OPTIMIZER PERCENT INDEX CACHING = 90 Access path: index (eq-unique) Index: PK_USPRL TABLE: USER_PROFILE RSC_CPU: 0 RSC_IO: 1 IX_SEL: 0.0000e+00 TB_SEL: 0.0000e+00 Join: resc: 1567 resp: 1567 Join cardinality: 19 = outer (27075) * inner (1554) * sel (4.5158e-07) [flag=0] Best NL cost: 1567 resp: 1567 SM Join Outer table: resc: 213 cdn: 27075 rcz: 56 deg: 1 resp: 213 Inner table: USER_PROFILE resc: 11 cdn: 1554 rcz: 98 deg: 1 resp: 11 using join:1 distribution:2 #groups:1 SORT resource Sort statistics Sort width: 29 Area size: 712704 Max Area size: 712704 Degree: 1 Blocks to Sort: 239 Row size: 72 Rows: 27075 Initial runs: 3 Merge passes: 1 IO Cost / pass: 284 Total IO sort cost: 262 Total CPU sort cost: 0 Total Temp space used: 3711000 SORT resource Sort statistics Sort width: 29 Area size: 712704 Max Area size: 712704 Degree: 1 Blocks to Sort: 23 Row size: 118 Rows: 1554 Initial runs: 1 Merge passes: 1 IO Cost / pass: 28 Total IO sort cost: 26 Total CPU sort cost: 0 Total Temp space used: 0 Merge join Cost: 511 Resp: 511 HA Join Outer table: resc: 213 cdn: 27075 rcz: 56 deg: 1 resp: 213 Inner table: USER_PROFILE resc: 11 cdn: 1554 rcz: 98 deg: 1 resp: 11 using join:8 distribution:2 #groups:1 Hash join one ptn Resc: 68 Deg: 1 (sides swapped) hash_area: 256 (max=256) buildfrag: 257 probefrag: 21 ppasses: 2 Hash join Resc: 292 Resp: 292 Outer table: resc: 11 cdn: 1554 rcz: 98 deg: 1 resp: 11 Inner table: COMPANY resc: 213 cdn: 27075 rcz: 56 deg: 1 resp: 213 using join:8 distribution:2 #groups:1 Hash join one ptn Resc: 8 Deg: 1 hash_area: 256 (max=256) buildfrag: 257 probefrag: 225 ppasses: 2 Hash join Resc: 232 Resp: 232 Join result: cost: 233 cdn: 19 rcz: 154 Now joining: USER_SECURITY [US] ******* NL Join Outer table: cost: 233 cdn: 19 rcz: 154 resp: 232 Inner table: USER_SECURITY Access path: tsc Resc: 11 Join: Resc: 441 Resp: 441 OPTIMIZER PERCENT INDEX CACHING = 90 Access path: index (join index) Index: USEC_INDX1 TABLE: USER_SECURITY RSC_CPU: 0 RSC_IO: 1 IX_SEL: 0.0000e+00 TB_SEL: 6.4893e-04 Join: resc: 233 resp: 233 Join cardinality: 19 = outer (19) * inner (1559) * sel (6.4893e-04) [flag=0] Best NL cost: 234 resp: 233 SM Join Outer table: resc: 232 cdn: 19 rcz: 154 deg: 1 resp: 232 Inner table: USER_SECURITY resc: 11 cdn: 1559 rcz: 8 deg: 1 resp: 11 using join:1 distribution:2 #groups:1 SORT resource Sort statistics Sort width: 29 Area size: 712704 Max Area size: 712704 Degree: 1 Blocks to Sort: 1 Row size: 180 Rows: 19 Initial runs: 1 Merge passes: 1 IO Cost / pass: 6 Total IO sort cost: 4 Total CPU sort cost: 0 Total Temp space used: 0 SORT resource Sort statistics Sort width: 29 Area size: 712704 Max Area size: 712704 Degree: 1 Blocks to Sort: 4 Row size: 19 Rows: 1559 Initial runs: 1 Merge passes: 1 IO Cost / pass: 9 Total IO sort cost: 6 Total CPU sort cost: 0 Total Temp space used: 0 Merge join Cost: 253 Resp: 253 HA Join Outer table: resc: 232 cdn: 19 rcz: 154 deg: 1 resp: 232 Inner table: USER_SECURITY resc: 11 cdn: 1559 rcz: 8 deg: 1 resp: 11 using join:8 distribution:2 #groups:1 Hash join one ptn Resc: 1 Deg: 1 hash_area: 256 (max=256) buildfrag: 257 probefrag: 4 ppasses: 2 Hash join Resc: 244 Resp: 244 ORDER BY sort SORT resource Sort statistics Sort width: 29 Area size: 712704 Max Area size: 712704 Degree: 1 Blocks to Sort: 1 Row size: 189 Rows: 19 Initial runs: 1 Merge passes: 1 IO Cost / pass: 6 Total IO sort cost: 4 Total CPU sort cost: 0 Total Temp space used: 0 Join result: cost: 237 cdn: 19 rcz: 162 Best so far: TABLE#: 0 CST: 4 CDN: 19 BYTES: 342 Best so far: TABLE#: 1 CST: 214 CDN: 27075 BYTES: 1516200 Best so far: TABLE#: 2 CST: 233 CDN: 19 BYTES: 2926 Best so far: TABLE#: 3 CST: 237 CDN: 19 BYTES: 3078 *********************** Join order[2]: USER_LOGIN [UL] COMPANY [CMP] USER_SECURITY [US] USER_PROFILE [UP] Now joining: USER_SECURITY [US] ******* 

The trace output from event 10053 illustrates how the CBO actually performs the cost computation process during the generation of an execution plan for a query.

Please note that unlike the RBO where the execution plan is generated based on the predefined rules, in a CBO the execution plan is generated based on the best access path after generating all the possible ordering of objects.

For example, in the above illustration the first join order is similar to what was specified in the SQL query:

Join order[1]: USER_LOGIN [UL] COMPANY [CMP] USER_PROFILE [UP] USER_SECURITY [US]

Subsequently, Oracle creates a different join order and calculates the cost of its execution path:

Join order[2]: USER_LOGIN [UL] COMPANY [CMP] USER_SECURITY [US] USER_PROFILE [UP] 

For every join operation, Oracle computes the cost of accessing the rows for a nested loop join (NL join), sort merge join (SM join), and hash join (HA join) operation.

For example, from the illustration above:

NL Join Outer table: cost: 4 cdn: 19 rcz: 18 resp: 4 Inner table: COMPANY Access path: tsc Resc: 11 Join: Resc: 213 Resp: 213 Join cardinality: 27075 = outer (19) * inner (1425) * sel (1.0000e+00) [flag=0]

From these three access methods, Oracle selects the operation that takes the least cost for execution. This is illustrated below by the ''best so far'' entry after each join order cost computation.

Best so far: TABLE#: 0 CST: 4 CDN: 19 BYTES: 342 Best so far: TABLE#: 1 CST: 214 CDN: 27075 BYTES: 1516200 Best so far: TABLE#: 2 CST: 233 CDN: 19 BYTES: 2926 Best so far: TABLE#: 3 CST: 237 CDN: 19 BYTES: 3078

For the query used in this illustration, Oracle created 14 different join order checks. However, if the best cost computed for a specific join order is not better than the previous, Oracle does not calculate the best cost for that specific join order.

Note 

In complex queries where there are several tables being joined, Oracle has to compute join orders for all possible table combinations, which could be time consuming. If queries are not being reused, for example when literals are used instead of bind variables, Oracle has to compute these join orders every single time and could create several performance problems.

Similarly, to avoid several join orders in a complex query with several table joins, the /*ORDERED*/ hint becomes very helpful. This hint will enforce the join order and based on the hint Oracle will use the user specified join order for query execution.

---