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…