SQL Trace

This is just a short note to point out that I finally uploaded under the downloadable files of TOP a new version of TVD$XTAT. To download it click here. Not only I introduced some new features, but I also fixed several bugs.

The detailed change log since Beta 10 is the following:

Last January, in the following tweet, I pointed out that the documentation vaguely mentions that a trace file may be split into several files.

Did you successfully tested the new MAX_DUMP_FILE_SIZE behavior? If yes, which version/OS?https://t.co/4F9f9wsT95 pic.twitter.com/X2Y7FNf1HG

— Christian Antognini (@ChrisAntognini) January 20, 2016

Today I started having a look to the Oracle Database Exadata Express Cloud Service announced last week at Oracle OpenWorld. Note that since the amount of resources provided (in summary, 1 OCPU, 20 or 50 GB of database storage) is very limited, in general, in my opinion that service will only be useful for functional tests. In fact, if it wasn’t because that is the very first 12.2 release (12.2.0.0.3 according to V$VERSION) available, I doubt I would care about it…

A first important thing to know is that the service gives access to a PDB via SQL*Net only (in addition to the web-based interfaces like APEX). In other words, the OS access is precluded.

The second edition of Cary Millsap‘s MASTERING ORACLE TRACE DATA (MOTD) is finally available. You can order it through amazon.com. I had the pleasure not only to review MOTD while Cary was working on it, but also to write a foreword that summarizes what I think about the book. So, if you are asking yourself whether you should buy MOTD, here is my opinion/foreword…

With the INMEMORY clause you can specify 4 sub-clauses:

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…