SQL Trace

Extended SQL trace (a.k.a. debugging event 10046 at a level higher than 1) is one of the key features provided by Oracle to troubleshoot applications using Oracle Database. For many years the available levels were always the same (4, 8 and 12). In fact, since I wrote my first paper about it in May 2000 and the release of 11g nothing changed.

With 11g, as I described in this post, new levels (16 and 32) were introduced.

This is just a short post to point out that the company I work for, Trivadis, is organizing 3 classes with Cary Millsap. The topic, as the title suggests, is Cary’s 1-day class entitled “Mastering Oracle Trace Data”.

The following dates and locations are planned:

• September 11, 2012 – Münich (DE)
• September 13, 2012 – Zürich (CH)
• September 18, 2012 – Vienna (AT)

For detailed information have a look to the flyer. Note that the early bird registration period, that entitles you a 15% discount, ends on August 1.

Recently I was involved in a project where I had to trace the database calls of an application based on Oracle Portal 10.1.4. The basic requirements were the following:

• Tracing takes place in the production environment
• Tracing has to be enable for a single user only
• Instrumentation code cannot be added to the application

Given that Oracle Portal uses a pool of connections and that for each HTTP call it can use several database sessions, statically enable SQL trace for specific sessions was not an option.

The release 11.2.0.2 not only provides a lot of documented new features, but also provides undocumented ones. Today, I would like to spend few words about the undocumented changes introduced in the TKPROF output. In this area it is interesting to point out that after the introduction of wait events in Oracle9i, there were really few enhancement in the formatting of the output.

To show you what’s new in the output, I executed the same commands I already used in the post covering the 11.2.0.1 new features of TKPROF. I just removed the histogram on SH.SALES.CHANNEL_ID before running them (I did that because I was not interested in having different execution plans).

The relevant part of the output generated by TKPROF is the following:

• Version 11.2.0.1

SQL ID: 94mzsr37n3vz0
Plan Hash: 1550251865
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch    61263      3.58       3.65        756      69331          2      918843
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61273      3.59       3.65        756      69331          2      918843

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

Rows     Row Source Operation
-------  ---------------------------------------------------
 258025  PARTITION RANGE ALL PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=664296 us cost=536 size=6661619 card=229711)
 258025   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=465129 us cost=536 size=6661619 card=229711)

• Version 11.2.0.2

SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865

SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch    61263      3.58       3.65        756      69331          2      918843
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61273      3.59       3.65        756      69331          2      918843

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
    258025     183769     540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=13866 pr=151 pw=0 time=492737 us cost=536 size=6661619 card=229711)
    258025     183769     540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=13866 pr=151 pw=0 time=396774 us cost=536 size=6661619 card=229711)

As you can see the differences (in order or appearance, not relevance) are the following :

• The position of the “Plan Hash” information has slightly changed. By the way, that part of the output is different in every one of the last 4 releases! (11.1.0.6, 11.1.0.7, 11.2.0.1 and 11.2.0.2). It goes without saying that this difference is almost irrelevant.
• Just after the parsing information a new line (“Number of plan statistics captured”) informs about the number of execution plans found in the trace file. Note that the presence of several execution plans also depends on the 11g feature I described here.
• While 11.2.0.1 provides a single column (“Rows”) for reporting the number of rows returned by every row source operation, 11.2.0.2 provides three columns (“Rows (1st)”, “Rows (avg)” and “Rows (max)”). The idea is to point out whether the executions returned the same amount of data. For that purpose the output provides the number of rows returned by the first execution and, for all executions, the average and maximum number of returned rows.
• The runtime statistics provided for each row source operation are also different. Specifically, while in 11.2.0.1 the values are the ones of the first execution found in the trace file, in 11.2.0.2 they are averages based on all executions.

The new/changed information is good. But, be careful, averages hide a lot of information. So, while the new output is more useful than the old one, it’s not perfect. In fact, if you really want to know what happened at runtime, you have to give a look to the raw trace file information. In this case the information associated to the execution plans are the following (notice how the number or returned rows, attribute “cnt”, and the number of logical reads in consistent mode, attribute “cr”, changes between executions):

STAT #182927356440 id=1 cnt=258025 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=664296 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=2 cnt=258025 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=465129 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=1 cnt=540328 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1146677 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=2 cnt=540328 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=739039 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=1 cnt=118416 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=421391 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=2 cnt=118416 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=333077 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=1 cnt=0 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218050 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=2 cnt=0 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218013 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=1 cnt=2074 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=13271 us cost=536 size=6661619 card=229711)'
STAT #182927356440 id=2 cnt=2074 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=228613 us cost=536 size=6661619 card=229711)'

Another difference is related to the processing of trace files while aggregation is disabled (i.e. “aggregate=no”) and the SORT parameter is specified. The following two outputs, based on the same trace file as above, illustrate this (notice how several execution plans are displayed in the 11.2.0.1 output). Honestly, this could be seen as a bug fix.

• Version 11.2.0.1

SQL ID: 94mzsr37n3vz0
Plan Hash: 1550251865
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch     8037      1.01       1.02          0      12924          0      120490
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     8043      1.01       1.02          0      12924          0      120490

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

Rows     Row Source Operation
-------  ---------------------------------------------------
 118416  PARTITION RANGE ALL PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=421391 us cost=536 size=6661619 card=229711)
 118416   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=333077 us cost=536 size=6661619 card=229711)
      0  PARTITION RANGE ALL PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218050 us cost=536 size=6661619 card=229711)
      0   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218013 us cost=536 size=6661619 card=229711)
   2074  PARTITION RANGE ALL PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=13271 us cost=536 size=6661619 card=229711)
   2074   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=228613 us cost=536 size=6661619 card=229711)

• Version 11.2.0.2

SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865

SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch     8037      1.01       1.02          0      12924          0      120490
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     8043      1.01       1.02          0      12924          0      120490

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 34
Number of plan statistics captured: 3

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
    118416      40163     118416  PARTITION RANGE ALL PARTITION: 1 28 (cr=4308 pr=0 pw=0 time=217571 us cost=536 size=6661619 card=229711)
    118416      40163     118416   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=4308 pr=0 pw=0 time=259901 us cost=536 size=6661619 card=229711)

The last thing I would like to point out, but without discussing the details, is that there are some changes in the trace files as well. The most obvious is the numbering of cursors…

While writing a post about the TKPROF new features in 11.2.0.2 I noticed that I didn’t write one about an important change introduced in 11.2.0.1. So, before finishing the other one, let’s have a look to what changed in 11.2.0.1.
One problem with TKPROF up to 11gR1 is that when the AGGREGATE parameter is set to [...]

During an evolution the database engine compares the performance of two execution plans. The aim is to find out which one provides the better performance. For that purpose it has to run the SQL statement on which the SQL plan baseline is based and compare some execution statistics. The following output of the DBMS_SPM.EVOLVE_SQL_PLAN_BASELINE function [...]

The aim of this post is to describe a strange (buggy) situation that I observed recently. But before doing that, I shortly summarize what a parent cursor and a child cursor are as well as when they can be shared. By the way, I borrowed this description from the pages 20/21 of my book. Hence, [...]

As of Oracle Database 11g the DBMS_SQLTUNE package provides the SELECT_SQL_TRACE function. Its purpose is to load the content of a SQL trace file into a SQL tuning set. But, as it often happens, a feature can be (mis)used for another purpose. The aim of this post is to show how to take advantage of [...]

Last week I had to analyze a strange performance problem. Since the cause/solution was somehow surprising, at least for me, I thought to share it with you.
Let me start by quickly describing the setup and what was done to reproduce the problem:

Database version: Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 (64-bit)
Operating system: Solaris 10 (SPARC)
To [...]