Monthly archives for October, 2010

TKPROF New Features in 11gR2 – 11.2.0.2

Oct13
2010 3 Comments Written by Christian Antognini

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…

Posted in 11gR2, SQL Trace, TKPROF

TKPROF New Features in 11gR2 – Release 11.2.0.1

Oct12
2010 3 Comments Written by Christian Antognini

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 YES (which is the default), all information belonging to cursors having the same text is aggregated in a single SQL statement. This is fine when all cursors were executed with the same execution plan. However, this is also done when a cursor was executed with several execution plans. As a result, only one execution plan is visible in the output. The others are lost.

As of 11gR2 this problem is solved. In fact, every SQL statement in the output is only related to a single execution plan.

To illustrate this enhancement let’s have a look to the TKPROF output for the trace file generated by the following commands (the test table is the one of the SH sample schema):

VARIABLE channel_id NUMBER
EXECUTE dbms_monitor.session_trace_enable(plan_stat=>'all_executions', waits=>false)
EXECUTE :channel_id := 2;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 3;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 4;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 5;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 9;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE dbms_monitor.session_trace_disable
SELECT value FROM v$diag_info WHERE name = 'Default Trace File';

The essential thing to know about the query used in this test is that the selectivity strongly depends on the value of the CHANNEL_ID variable. The following query shows the actual distribution:

SQL> SELECT channel_id, count(*)
  2  FROM sh.sales
  3  GROUP BY channel_id
  4  ORDER BY channel_id;

CHANNEL_ID   COUNT(*)
---------- ----------
         2     258025
         3     540328
         4     118416
         9       2074

Hence, when running the commands shown above, two execution plans are expected.

When the selectivity is weak (high), the execution plan should be based on a full table scan.
When the selectivity is strong (low), the execution plan should be based on an index range scan.

After generating the trace file with 11gR2, let’s have a look to the output provided by TKPROF.

11.1.0.7

SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.04       0.03          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch    61263      2.95       2.99          0      66150          0      918843
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61273      3.01       3.03          0      66150          0      918843

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

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)

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.04       0.03          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch    61122      2.94       2.98          0      65918          0      916769
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61128      2.99       3.02          0      65918          0      916769

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

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)

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

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      141      0.00       0.00          0        232          0        2074
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      145      0.01       0.01          0        232          0        2074

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

Rows     Row Source Operation
-------  ---------------------------------------------------
   2074  PARTITION RANGE ALL PARTITION: 1 28 (cr=200 pr=0 pw=0 time=4602 us cost=325 size=78184 card=2696)
   2074   TABLE ACCESS BY LOCAL INDEX ROWID SALES PARTITION: 1 28 (cr=200 pr=0 pw=0 time=3979 us cost=325 size=78184 card=2696)
   2074    BITMAP CONVERSION TO ROWIDS (cr=32 pr=0 pw=0 time=993 us)
      3     BITMAP INDEX SINGLE VALUE SALES_CHANNEL_BIX PARTITION: 1 28 (cr=32 pr=0 pw=0 time=189 us)(object id 13980)

As you can see, in the 11.1.0.7 output the 5 executions are associated to a single SQL statement. So, according to it, it is sensible to say that all 5 executions used the same execution plan based on a full table scan. However, as described above, this is not true. The 11.2.0.1 output doesn’t exhibit the same problem. In fact, the information is separated in two SQL statements. For that reason the section providing the information about a SQL statement begins with the information not only about the SQL ID, but also about the hash value of the execution plan. Note that the SQL ID is missing from the 11.1.0.7 output. No idea why… In fact, in 11.1.0.6, it is present. The hash value, however, was added in 11gR2.

Posted in 11gR1, 11gR2, SQL Trace, TKPROF

DBMS_AUTO_SQLTUNE: ORA-01748 and Documentation Bugs

Oct06
2010 1 Comment Written by Christian Antognini

As of 11.2.0.2 a new package, DBMS_AUTO_SQLTUNE, is available for accessing and configuring Automatic SQL Tuning. The package provides three features:

Execution of the Automatic SQL Tuning task (EXECUTE_AUTO_TUNING_TASK)
Generation of a report showing the output generated by the Automatic SQL Tuning tasks (REPORT_AUTO_TUNING_TASK)
Configuration of the Automatic SQL Tuning parameters (SET_AUTO_TUNING_TASK_PARAMETER)

In this post I would like to focus on the second functionality. With it you can for example execute the following commands in SQL*Plus to get a report for the most recent task:

SET LONG 1000000 PAGESIZE 0 LINESIZE 200
COLUMN report_auto_tuning_task FORMAT A200
SELECT dbms_auto_sqltune.report_auto_tuning_task FROM dual;

The REPORT_AUTO_TUNING_TASK function is not limited to being used without parameters. In fact, its signature is the following:

FUNCTION REPORT_AUTO_TUNING_TASK RETURNS CLOB
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 BEGIN_EXEC                     VARCHAR2                IN     DEFAULT
 END_EXEC                       VARCHAR2                IN     DEFAULT
 TYPE                           VARCHAR2                IN     DEFAULT
 LEVEL                          VARCHAR2                IN     DEFAULT
 SECTION                        VARCHAR2                IN     DEFAULT
 OBJECT_ID                      NUMBER                  IN     DEFAULT
 RESULT_LIMIT                   NUMBER                  IN     DEFAULT

The purpose of the parameters is the following:

BEGIN_EXEC/END_EXEC specifies which tasks have to be reported. With the default value, NULL, the most recent task is shown.
TYPE specifies the type of the report. Presently only TEXT is supported.
LEVEL specifies the level of detail shown in the report. This is somewhat similar to the FORMAT parameter of DBMS_XPLAN. The supported values are BASIC, TYPICAL (default) and ALL.
SECTION specifies which sections are shown in the report. The supported values are SUMMARY, FINDINGS, PLANS, INFORMATION, ERRORS and ALL (default). Possibly there is a bug with the value ERRORS. In fact, during my tests, it always returned the same report as the value INFORMATION!?!?
OBJECT_ID restricts the report to a single SQL statement. You can get the ID either from the report or by querying DBA_ADVISOR_OBJECTS.OBJECT_ID.
RESULT_LIMIT specifies the maximum number of SQL statements shown in the report.

The essential thing I would like to point out is that two parameters have as name a reserved word.

SQL> SELECT keyword
  2  FROM v$reserved_words
  3  WHERE keyword IN ('BEGIN_EXEC','END_EXEC','TYPE','LEVEL','SECTION','OBJECT_ID','RESULT_LIMIT');

KEYWORD
------------------------------
LEVEL
TYPE

As a result expect to get an error like the following one if you want to use named notation:

SELECT dbms_auto_sqltune.report_auto_tuning_task(level => 'basic') FROM dual
                                                       *
ERROR at line 1:
ORA-01748: only simple column names allowed here

These are the kind of things I cannot understand! It’s so easy to choose a name that doesn’t lead to such problems. For one time I hope that Oracle will break backward compatibility and change the name of these parameters.

Another thing I wanted to point out is that the values supported by the SECTION parameter are the ones I reported above, and not the ones documented here. In fact, there are two typos in the documentation. This is probably because the same typos can also be seen in $ORACLE_HOME/rdbms/admin/dbmssqlt.sql. In other words, it seems that the guy who wrote the documentation did a simple copy/paste of the content of the SQL file.

Posted in 11gR2, Bug, Query Optimizer