jump to navigation

Looking at Oracle’s performance with SQL*Plus and AUTOTRACE April 6, 2012

Posted by Mich Talebzadeh in Oracle.
trackback

Understanding the Cost Based Optimizer’s behaviour and query performance is crucial for delivering quality applications with acceptable response time. Like it or not in most cases performance is taken as deployment issue and perhaps that is a reason why a lot of efforts is usually spent in production to get the performance under control.

All database engines provide means to measure the SQL performance. SQL performance is usually one of the most crucial factors in determining the quality of applications that use databases as their backend.

We will therefore look at the methods that we can deploy in Oracle to understand the response of the query.

Ignoring other tools at our disposal we will first take a look at AUTOTRACE. My test bed is Oracle 11gR2

AUTOTRACE

AUTOTRACE is a utility switch within SQL*Plus that shows the plan of the queries being executed and the resources being used. First AUTOTRACE utility needs to be set up.

A typical approach would be:

cd $ORACLE_HOME/rdbms/admin
log into SQL*Plus as SYSTEM
Run @utlxplan
As SYS
  CREATE PUBLIC SYNONYM PLAN_TABLE FOR PLAN_TABLE;
  GRANT ALL ON PLAN_TABLE TO PUBLIC;

By making the PLAN_TABLE table PUBLIC, you let anyone trace using SQL*Plus (which is fine in my view). This prevents the overhead of each user having to install his or her own plan table. The alternative is  to run @utlxplan in every schema that will use AUTOTRACE.

The next step is creating and granting the PLUSTRACE role:

cd $ORACLE_HOME/sqlplus/admin
As SYS
Run @plustrce
GRANT PLUSTRACE TO PUBLIC;

So far so good. In a nutshell what does AUTOTRACE provide? AUTOTRACE allows one to a get a report on the execution path used by the SQL optimizer and the statement execution statistics. The report is generated after successful SQL DQ (SELECT) and SQL DML (INSERT, UPDATE, DELETE  and MERGE) statements. It is useful for monitoring and tuning the performance of typical queries in Oracle.

We can control the depth of query report by setting the AUTOTRACE with different switches. Examples below show:


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 it suppresses the printing of the user’s query output, if any.

It is important to note that AUTOTRACE shows the execution plan for a single SQL statement. A PL/SQL block does not have an execution plan.  If it contains one or more SQL statements, then each of those will have an execution plan.

Understanding AUTOTRACE Output applied to the case of Oracle use of index with NOT EQUALS

To understand how we can utilise AUTOTRACE, we start with a simple table comprising three columns and we will test whether Oracle uses index with NOT EQUALS.  We will call this table t1 and we ensure that this table has enough rows to provide meaningful test values. The structure of this table is as follows :

CREATE TABLE t1 AS
SELECT
ROWNUM k1,
DECODE(ROWNUM,1,1,0) c,
LPAD('A',255,'A') c3
FROM
DUAL
CONNECT BY
LEVEL<=1000000;
-- Create a unique index on column k1
CREATE UNIQUE INDEX ind_t1_k1 ON t1(k1);
-- Create an index on column c
CREATE INDEX ind_t1_c on t1(c);
-- Now that the table is ready with a million rows, update stats
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)

Note that column k1 is monolithically increasing number. Column “c” depends on k1. When k1 = 1 then it is otherwise it is zero. Column lpad is just padding. In this case for column c the first entry would be 1 and the rest would be zero. This will create a highly skewed column.

Let us try to run a simple query as follows:

SET TIMING ON
SET AUTOTRACE ON
SELECT k1, c FROM t1 WHERE c <> 0;

The execution plan from AUTOTRACE is shown below

System altered.
K1          C
---------- ----------
1          1
Elapsed: 00:00:00.29
Execution Plan
----------------------------------------------------------
Plan hash value: 523648936
-------------------------------------------------------------------------------------------
| Id  | Operation              | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |                  |     1 |     8 |  6388   (1)| 00:01:17 |
|   1 |  VIEW                  | index$_join$_001 |     1 |     8 |  6388   (1)| 00:01:17 |
|*  2 |   HASH JOIN            |                  |       |       |            |          |
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C         |     1 |     8 |  2276   (1)| 00:00:28 |
|   4 |    INDEX FAST FULL SCAN| IND_T1_K1        |     1 |     8 |  2621   (1)| 00:00:32 |
-------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access(ROWID=ROWID)
3 - filter("C"<>0)
Statistics
----------------------------------------------------------
1  recursive calls
0  db block gets
3930  consistent gets
3911  physical reads
0  redo size
586  bytes sent via SQL*Net to client
523  bytes received via SQL*Net from client
2  SQL*Net roundtrips to/from client
0  sorts (memory)
0  sorts (disk)
1  rows processed

Explain Plan should be interpreted as a tree using the indentation to identify parent/child relationships. Thus it has a hierarchical structure, and the Bytes, Cost, Time etc. is a sum of corresponding metrics for all its children plus the metrics of the operation itself. In each tree level, it shows the following:

  • Id is the Operation identifier
  • Operation is the type of operation perfomed by the execution engine
  • Name is the name of the operation
  • Rows is the estimated number of rows processed
  • Bytes is the estimated amount of data (in bytes) returned by the operation
  • Cost is the estimated cost of the operation. This is a unitless number used by the optimizer. %CPU is percent share of the Cost attributed to CPU
  • Time is the estimated total elapsed time spent processing the operation. It is in mm:ss:millisecond

Predicate Information is pretty self explanatory

Statistics are as follows:

  • recursive calls is the number of SQL calls that are generated in User and System levels on behalf of the main SQL. Mostly these are internally generated SQL calls by Oracle
  • db block gets shows data from blocks read as-of-now (Current data). It seems Oracle uses db block get only for fetching internal information such as reading segment header information for a table in FULL TABLE SCAN.
  • consistent gets is to do with read consistency in Oracle. Oracle must provide a *read consistent* set of data to the user. This is to ensure that, unless the update is committed, any user who queries the table’s data, see only the original data value and not the updated one (uncommitted update). For this, when required, Oracle takes the original values of the changed data from the UNDO segment and unchanged data (un-updated rows) from the  buffer cache to generate the full set of output.
  • physical reads is the number of physical block reads of buffers from disk. Not to be confused with Physical IO
  • redo size is the redo Log generated sized in bytes.
  • bytes sent via SQL*Net to client is the total amount of data in bytes sent to the client over the network
  • bytes received via SQL*Net from client is the total amount of data in bytes received from the client over the network
  • SQL*Net roundtrips to/from client is total number of messages sent to and received from the client via network
  • sorts (memory) is the number of sorts that didn’t write to disk
  • sorts (disk) is the number of sorts that has written at least once to disk
  • rows processed is the number of rows processed

SET TIMING ON shows the elapsed time taken by the query.It displays elapsed time in: Hours:Minutes:Seconds.Milliseconds

Now back to the example above, the query took 290 milliseconds to run. Looking at the excecution plan we see two  INDEX FAST FULL SCAN on both indexes followed by a hash join. One should note that the optimizer can use an index with not equals,  but it would not in general and it would not make sense in general unless the data was so massively skewed (as is the case with column c).  Perhaps it would be easier to point out that the optimizer will not use an index range scan for a not equals. In all cases with not equals, if the optimizer decides to use an index , then it will do an index fast full scan. With an index fast full scan, the execution engine reads the index as if it were a table using multiblock IO, does not read it in sorted order, just reads the blocks as it hits them. In our example, the execution engine does a scan of the two indexes extracting the row IDs (ROWID) from both indexes. The leaf level of index  stores the index key value and the ROWID. In this case ROWID from both indexes will be the same.  Then it can get the result by doing a hash join between these two result sets on the ROWID values because any time the two rows have a ROWID in common, that points to the data row. The base table blocks thus need not be touched. The important point to note is that this requires the optimizer to be able to establish that every column in the query can be found in indexes on the table and the cost of index join would be cheaper than using the leading index and getting data from the data blocks.

As an example if we look at at the operation identified by Id = 4 and INDEX FAST FULL SCAN, we can see that the operation was done on index  IND_T1_K1 which returned 1 row with 8 bytes. The optimizer costing was 2621 units, of which 1% was attributed to CPU usage. It took 320 milliseconds to perform this operation.

Comments»

No comments yet — be the first.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: