11
Using Autotrace in SQL*Plus

This chapter provides information on using the Autotrace feature in SQL*Plus and the iSQL*Plus statistics report.

This chapter contains the following sections:

Overview of the Autotrace Report

In SQL*Plus you can automatically get a report on the execution path used by the SQL optimizer and the statement execution statistics. The report is generated after a successful SQL DML statement, such as SELECT, DELETE, UPDATE or INSERT. It is useful for monitoring and tuning the performance of these DML statements.

Configuring the Autotrace Report

You can control the report by setting the AUTOTRACE system variable. See Table 11-1.

Table 11-1 Autotrace Settings

Autotrace Setting	Result
`SET AUTOTRACE OFF`	No `AUTOTRACE` report is generated. This is the default.
`SET AUTOTRACE ON EXPLAIN`	The `AUTOTRACE` report shows only the optimizer execution path.
`SET AUTOTRACE ON STATISTICS`	The `AUTOTRACE` report shows only the SQL statement execution statistics.
`SET AUTOTRACE ON`	The `AUTOTRACE` report includes both the optimizer execution path and the SQL statement execution statistics.
`SET AUTOTRACE TRACEONLY`	Similar to `SET` `AUTOTRACE` `ON`, but suppresses the printing of the user's query output, if any. If STATISTICS is enabled, query data is still fetched, but not printed.

Setups Required for the Autotrace Report

To use this feature, the PLUSTRACE role must be granted to the user, such as HR. DBA privileges are required to grant the PLUSTRACE role.

Additionally, a PLAN_TABLE table must be created in the user's schema, such as the HR schema. For information on creating the PLAN_TABLE, see "Creating the PLAN_TABLE Output Table".

To create the PLUSTRACE role and grant it to the DBA, run the commands in Example 11-1 from a SQL*Plus session.

Example 11-1 Creating the PLUSTRACE Role

CONNECT / AS SYSDBA 
@$ORACLE_HOME/SQLPLUS/ADMIN/PLUSTRCE.SQL 

drop role plustrace;
Role dropped.
create role plustrace;
Role created.
.
grant plustrace to dba with admin option;
Grant succeeded.

To grant the PLUSTRACE role to the HR user, run the commands in Example 11-2 from a SQL*Plus session.

Example 11-2 Granting the PLUSTRACE Role

CONNECT / AS SYSDBA 
GRANT PLUSTRACE TO HR; 
Grant succeeded.

See Also:

Oracle9i SQL Reference for more information about granting roles and creating the PLAN_TABLE table
SQL*Plus User's Guide and Reference for more information about the PLUSTRACE role and about the AUTOTRACE variable of the SET command
Oracle9i Database Administrator's Guide for information about roles

Execution Plans for SQL Statements

An execution plan shows the SQL optimizer's query execution path. Each line of the execution plan has a sequential line number. SQL*Plus also displays the line number of the parent operation. For a discussion and an example of an execution plan, see "Understanding Execution Plans".

The execution plan output is generated using the EXPLAIN PLAN command.The format of the output can vary depending on your setups. The format of the columns of the PLAN_TABLE may be altered with the COLUMN command. For example, to stop the PARENT_ID column being displayed, enter the following:

COLUMN PARENT_ID NOPRINT

The default formats can be found in the site profile, such as, GLOGIN.SQL.

See Also:

Chapter 9, "Using EXPLAIN PLAN" for more information about generating and interpreting the output of EXPLAIN PLAN

Database Statistics for SQL Statements

The statistics are recorded by the server when your statement executes and indicate the system resources required to execute your statement. The results include the statistics listed in Table 11-2.

Table 11-2 Database Statistics

Database Statistic Name	Description
recursive calls	Number of recursive calls generated at both the user and system level. Oracle maintains tables used for internal processing. When Oracle needs to make a change to these tables, it internally generates an internal SQL statement, which in turn generates a recursive call.
db block gets	Number of times a CURRENT block was requested.
consistent gets	Number of times a consistent read was requested for a block.
physical reads	Total number of data blocks read from disk. This number equals the value of "physical reads direct" plus all reads into buffer cache.
redo size	Total amount of redo generated in bytes.
bytes sent via SQL*Net to client	Total number of bytes sent to the client from the foreground processes.
bytes received via SQL*Net from client	Total number of bytes received from the client over Oracle Net.
SQL*Net roundtrips to/from client	Total number of Oracle Net messages sent to and received from the client.
sorts (memory)	Number of sort operations that were performed completely in memory and did not require any disk writes.
sorts (disk)	Number of sort operations that required at least one disk write.
rows processed	Number of rows processed during the operation.

The client referred to in the statistics is SQL*Plus. Oracle Net refers to the generic process communication between SQL*Plus and the server, regardless of whether Oracle Net is installed. You cannot change the default format of the statistics report.

See Also:

Oracle9i Database Reference for a more complete list of database statistics
Chapter 3, "Gathering Optimizer Statistics" for more information about the statistics and how to interpret them

Tracing Statements Examples

This section shows examples of the use of the AUTOTRACE feature.

Tracing Statements for Performance Statistics and Query Execution Path

If the SQL buffer contains the following statement:

SELECT E.LAST_NAME, E.SALARY, J.JOB_TITLE
  FROM EMPLOYEES E, JOBS J
    WHERE E.JOB_ID=J.JOB_ID AND E.SALARY>12000;

The statement can be automatically traced when it is run with the following:

SET AUTOTRACE ON
/

The output is similar to the following:

LAST_NAME                     SALARY JOB_TITLE
------------------------- ---------- -----------------------------------
King                           24000 President
Kochhar                        17000 Administration Vice President
De Haan                        17000 Administration Vice President
Russell                        14000 Sales Manager
Partners                       13500 Sales Manager
Hartstein                      13000 Marketing Manager

6 rows selected.

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   TABLE ACCESS (BY INDEX ROWID) OF 'EMPLOYEES'
   2    1     NESTED LOOPS
   3    2       TABLE ACCESS (FULL) OF 'JOBS'
   4    2       INDEX (RANGE SCAN) OF 'EMP_JOB_IX' (NON-UNIQUE)

Statistics
----------------------------------------------------------
          0  recursive calls
          2  db block gets
         34  consistent gets
          0  physical reads
          0  redo size
        848  bytes sent via SQL*Net to client
        503  bytes received via SQL*Net from client
          4  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          6  rows processed

Note:

Your output may vary depending on the version of the server to which you are connected and the configuration of the server.

Tracing Statements Without Displaying Query Data

To trace the same statement without displaying the query data, enter the following:

SET AUTOTRACE TRACEONLY

This option is useful when you are tuning a large query, but do not want to see the query output.

Tracing Statements Using a Database Link

To trace a statement using a database link, enter:

SET AUTOTRACE TRACEONLY EXPLAIN
SELECT * FROM EMPLOYEES@MY_LINK;

Execution Plan
-----------------------------------------------------------
0      SELECT STATEMENT (REMOTE) Optimizer=CHOOSE
1    0   TABLE ACCESS (FULL) OF 'EMPLOYEES'  MY_LINK.DB_DOMAIN

The execution plan shows that the table being accessed on line 1 of the execution plan is through the database link MY_LINK.DB_DOMAIN.

Collecting Timing Statistics

Use the SQL*Plus TIMING command to collect and display data on the amount of computer resources used to run one or more commands or blocks. TIMING collects data for an elapsed period of time, saving the data on commands run during the period in a timer.

To delete all timers, enter CLEAR TIMING at the command prompt.

See Also:

SQL*Plus User's Guide and Reference for information about the TIMING command

Tracing Parallel and Distributed Queries

When you trace a statement in a parallel or distributed query, the execution plan shows the cost based optimizer estimates of the number of rows, called the cardinality. In general, the cost, cardinality and bytes at each node represent cumulative results. For example, the cost of a join node accounts for not only the cost of completing the join operations, but also the entire costs of accessing the relations in that join.

Example 11-3 is an example of tracing statements with the parallel query option. The output varies depending on the configuration of a system. In the execution plan output, items marked with an asterisk (*) denote a parallel or remote operation. Each operation is explained in the second part of the report. The execution plan in Example 11-3 consists of columns that contain information such as:

Line number of each execution step
Function of the SQL statement
Text of the query for the Oracle Real Application Clusters database or remote database

For more information about the columns in the PLAN_TABLE, see "PLAN_TABLE Columns".

Example 11-3 Tracing Statements With Parallel Query Option

To trace a parallel query running the parallel query option:

SQL> CREATE TABLE D2_t1 (unique1 NUMBER) PARALLEL -(degree 6);
Table created.

SQL> CREATE TABLE D2_t2 (unique1 NUMBER) PARALLEL -(DEGREE 6);
Table created.

SQL> CREATE UNIQUE INDEX d2_i_unique1 ON d2_t1(unique1);
Index created.

SQL> SET LONG 500 LONGCHUNKSIZE 500
SQL> SET AUTOTRACE ON EXPLAIN
SQL> SELECT /*+ INDEX(B,D2_I_UNIQUE1) USE_NL(B) ORDERED -*/ COUNT (A.UNIQUE1)
     FROM D2_T2 A, D2_T1 B
     WHERE A.UNIQUE1 = B.UNIQUE1;

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=1 Card=1 Bytes=26)
   1    0  SORT (AGGREGATE)
   2    1   SORT* (AGGREGATE)                                      :Q2000
   3    2    NESTED LOOPS* (Cost=1 Card=41 Bytes=1066)             :Q2000
   4    3     TABLE ACCESS* (FULL) OF 'D2_T2' (Cost=1 Card=41 Byte :Q2000 s=533)
   5    3      INDEX* (UNIQUE SCAN) OF 'D2_I_UNIQUE1' (UNIQUE)     :Q2000

   2 PARALLEL_TO_SERIAL            SELECT /*+ PIV_SSF */ SYS_OP_MSR(COUNT(A1.C0
                                   )) FROM (SELECT /*+ ORDERED NO_EXPAND USE_NL
                                   (A3) INDEX(A3 "D2_I_UNIQUE1") */ A2.C0 C0,A3
                                   .ROWID C1,A3."UNIQUE1" C2 FROM (SELECT /*+ N
                                   O_EXPAND ROWID(A4) */ A4."UNIQUE1" C0 FROM "
                                   D2_T2" PX_GRANULE(0, BLOCK_RANGE, DYNAMIC)
                                   A4) A2,"D2_T1" A3 WHERE A2.C0=A3."UNIQUE1")
                                   A1

   3 PARALLEL_COMBINED_WITH_PARENT
   4 PARALLEL_COMBINED_WITH_PARENT
   5 PARALLEL_COMBINED_WITH_PARENT

Line 0 of the execution plan shows the cost based optimizer estimates the number of rows at 1, taking 26 bytes. The total cost of the statement is 1. Lines 2, 3, 4 and 5 are marked with asterisks, denoting parallel operations. For example, the NESTED LOOPS step on line 3 is a PARALLEL_TO_SERIAL operation. PARALLEL_TO_SERIAL operations execute a SQL statement to produce output serially. Line 2 also shows that the parallel query server had the identifier Q2000.

Numbers identifying parallel report lines cross reference the line of the parent report. For example, in the last line of the example:

4 PARALLEL_COMBINED_WITH_PARENT

The 4 refers to the 4 3 TABLE ACCESS*... line in the execution plan.

Monitoring Disk Reads and Buffer Gets

To monitor disk reads and buffer gets, execute the following command:

SET AUTOTRACE ON TRACEONLY STATISTICS

Example 11-4 shows typical results.

Example 11-4 Monitoring Disk Reads and Buffer Gets

Statistics
----------------------------------------------------------
        70 recursive calls
         0 db block gets
       591 consistent gets
       404 physical reads
         0 redo size
       315 bytes sent via SQL*Net to client
       850 bytes received via SQL*Net from client
         3 SQL*Net roundtrips to/from client
         3 sorts (memory)
         0 sorts (disk)
         0 rows processed

If consistent gets or physical reads is high relative to the amount of data returned, it indicates that the query is expensive and needs to be reviewed for optimization. For example, if you are expecting less than 1,000 rows back and consistent gets is 1,000,000 and physical reads is 10,000, further optimization is needed.

Note:

You can also monitor disk reads and buffer gets using V$SQL or TKPROF.

SYSTEM Variables Influencing SQL*Plus Performance

The following variables can influence SQL*Plus performance.

SET APPINFO OFF

Sets automatic registering of scripts through the DBMS_APPLICATION_INFO package. Setting APPINFO OFF disables the registering and monitoring of performance and resource usage of scripts. This reduction in overheads may improve performance.

SET ARRAYSIZE

Sets the number of rows, called a batch, that SQL*Plus will fetch from the database at one time. Valid values are 1 to 5000. A large value increases the efficiency of queries and subqueries that fetch many rows, but requires more memory. Values over approximately 100 provide little added performance. ARRAYSIZE has no effect on the results of SQL*Plus operations other than increasing efficiency.

SET DEFINE OFF

Controls whether SQL*Plus parses scripts for substitution variables. If DEFINE is OFF, SQL*Plus does not parse scripts for substitution variables. If your script does not use substitution variables, setting DEFINE OFF may result in some performance gains.

SET FLUSH OFF

Controls when output is sent to the user's display device. OFF allows the host operating system to buffer output which may improve performance by reducing the amount of program input and output.

Use OFF only when you run a script that does not require user interaction and whose output you do not need to see until the script finishes running.

SET FLUSH is not supported in iSQL*Plus.

SET SERVEROUTPUT

Controls whether SQL*Plus checks for and displays DBMS output. If SERVEROUTPUT is OFF, SQL*Plus does not check for DBMS output and does not display output after applicable SQL or PL/SQL statements. Suppressing this output checking and display may result in performance gains.

SET TRIMOUT ON

Determines whether SQL*Plus allows trailing blanks at the end of each displayed line. ON removes blanks at the end of each line, which may improve performance especially when you access SQL*Plus from a slow communications device. TRIMOUT ON does not affect spooled output.

SET TRIMOUT is not supported in iSQL*Plus.

SET TRIMSPOOL ON

Determines whether SQL*Plus allows trailing blanks at the end of each spooled line. ON removes blanks at the end of each line, which may improve performance especially when you access SQL*Plus from a slow communications device. TRIMSPOOL ON does not affect terminal output.

SET TRIMSPOOL is not supported in iSQL*Plus.

iSQL*Plus Server Statistics Report

The iSQL*Plus Server statistics report provides static environment information as well as dynamic information about iSQL*Plus sessions. The active statistics in the report are useful for monitoring and tuning iSQL*Plus. You can display the iSQL*Plus Server statistics report with:

http://machine_name.domain:port/isqlplusdba?statistics={active|full} 
[&refresh=number]

where

machine_name.domain is the URL of the Oracle HTTP Server for which you want to generate iSQL*Plus Server statistics.
port is the port number used by the iSQL*Plus Server. The default is 7777.
?statistics={active|full} specifies the level of detail to report.
- full gives all possible statistics and is the default.
- active gives dynamically changing session statistics for the iSQL*Plus Server. These statistics are also included at the end of the full report.
[&refresh=number] optionally specifies the time in seconds before the statistics report is automatically refreshed. The minimum value is 10 seconds.

To run the report, you must have Oracle HTTP Server authentication to access the iSQL*Plus DBA URL. However, an Oracle9i login is not required because there is no connection to a database. To maximize resource availability, each user of iSQL*Plus should have a database schema profile with appropriately defined limits.

See Also:

For more information about the iSQL*Plus Server statistics report, including the full set of statistics, see SQL*Plus User's Guide and Reference

Active Statistics

The active statistics report shows the current values for the statistics listed in Table 11-3. These statistics provide useful feedback for tuning the iSQL*Plus Server.

Table 11-3 Active Statistics

Statistic	Description
`Sessions active`	The number of concurrent active sessions, or the number of people currently logged in to iSQL*Plus.
`Sessions since startup`	The cumulative count of sessions established since the iSQL*Plus Server started.
`Maximum concurrent sessions`	The maximum or peak number of concurrent sessions since the iSQL*Plus Server started.
`Sessions expired since startup`	The cumulative count of the number of sessions timed-out due to inactivity since the iSQL*Plus Server started.
`Requests active`	The number of concurrent active HTTP requests. Each request corresponds to a user action such as clicking a button, and the processing of that request by iSQL*Plus. Requests active has a maximum value set by `iSQLPlusNumberOfThreads`. If it reaches this limit and user response time is poor, then response time may be improved by increasing `iSQLPlusNumberOfThreads`.
`Requests since startup`	The cumulative count of active HTTP requests since the iSQL*Plus server was started.
`Next expiry operation (minutes)`	The number of minutes (rounded down) until the next expiry process.
`Expiry operations since startup`	The number of times the expiry process has run since the iSQL*Plus Server started.
`Hash table collisions`	The number of active sessions that currently have a hash table collision. Compare this with Sessions active to see if there is a current problem with collisions.
`Hash table collisions since startup`	The cumulative count of the sessions that have had a hash table collision since the iSQL*Plus Server started. Compare this with Sessions since startup to see if there is an ongoing problem with collisions.

Interpreting Active Statistics

The following notes provide some interpretation of the active statistics.

Increasing Number of Threads

If users have more idle time compared to active time, then a higher value of iSQLPlusNumberOfThreads may be needed.

Active time is when a user request is in progress, and a thread to process it is consumed.
Idle time is when a user request has been processed, and the associated processing thread is available for use by another iSQL*Plus session.

Each thread can handle one user request. A request begins when a user clicks a button or follows a command link in iSQL*Plus, and finishes when all results have been returned to the user.

When setting the value of iSQLPlusNumberOfThreads, note the following:

If iSQLPlusHashTableSize is not specified in the isqlplus.conf file, its value increases when iSQLPlusNumberOfThreads is increased.
If the iSQLPlusNumberOfThreads value is set too small, iSQL*Plus may not be able to handle the request load. Indications of this problem are:
- Frequent Connection refused errors in ORACLE_HOME/Apache/Apache/logs/error_log
- An Oracle HTTP Server internal error:
```
The server encountered an internal error or misconfiguration and was 
unable to complete your request.
```

Increasing Hash Table Size

If users typically have more idle time compared to active time, then a higher value of iSQLPlusHashTableSize is needed for a given value of iSQLPlusNumberOfThreads. Each user session consumes one entry in the hash table even if the session is idle.

Reducing Timeout Interval

If large numbers of sessions are being timed out, it is an indication that users are not logging out cleanly, and sessions may be remaining idle. In this case, and if the iSQL*Plus Server load is high, you may want to consider reducing the iSQLPlusTimeOutInterval to more aggressively time out sessions.

Idle Timeout

The idle timeout is the time the Oracle HTTP Server waits for results from iSQL*Plus. The parameter value for the FastCGI timeout parameter, -idle-timeout, is set to 3600 seconds. This value is likely to prevent iSQL*Plus timing out before the Web browser and is sufficient for many long queries to return results before iSQL*Plus times out.

The idle timeout should not be confused with the iSQLPlusTimeOutInterval which manages the lifetime of a user's session.

11 Using Autotrace in SQL*Plus

Overview of the Autotrace Report

Configuring the Autotrace Report

Table 11-1 Autotrace Settings

Setups Required for the Autotrace Report

Example 11-1 Creating the PLUSTRACE Role

Example 11-2 Granting the PLUSTRACE Role

Execution Plans for SQL Statements

Database Statistics for SQL Statements

Table 11-2 Database Statistics

Tracing Statements Examples

Tracing Statements for Performance Statistics and Query Execution Path

Tracing Statements Without Displaying Query Data

Tracing Statements Using a Database Link

Collecting Timing Statistics

Tracing Parallel and Distributed Queries

Example 11-3 Tracing Statements With Parallel Query Option

Monitoring Disk Reads and Buffer Gets

Example 11-4 Monitoring Disk Reads and Buffer Gets

SYSTEM Variables Influencing SQL*Plus Performance

SET APPINFO OFF

SET ARRAYSIZE

SET DEFINE OFF

SET FLUSH OFF

SET SERVEROUTPUT

SET TRIMOUT ON

SET TRIMSPOOL ON

iSQL*Plus Server Statistics Report

Active Statistics

Table 11-3 Active Statistics

Interpreting Active Statistics

Increasing Number of Threads

Increasing Hash Table Size

Reducing Timeout Interval

Idle Timeout

11
Using Autotrace in SQL*Plus