How To Trace Queries in Oracle with AUTOTRACE

Oracle has a great utility for performance debugging and query tracing; AUTOTRACE. It’s probably one of the most overlooked tools considering how powerful it could be. I will explain now, in a few simple steps, what does it do and how to use it.

What is autotrace?

The autotrace is a tool, which gives you immediate results of your query, together with explain plan and statistics. You might be asking what is the difference between a regular explain plan and the autotrace. As you might read in my previous article about Explain Plan it only estimates what could be the output (based on available statistics), unlike the autotrace that executes the query first and gather stats and the actual explain plan for the execution.

How to use autotrace?

The autotrace can be used only in SQL*Plus. SQL*Plus is a command-line interface for connecting to the Oracle database instances. Let’s review some SQL*Plus basics.

First of all, check your connection if everything is working fine. Run the following command in the command line; replace <tns_alias> with your own alias from the TNSNAMES.ora file representing your connection string.

-- template
tnsping <tns_alias>

--example
tnsping oracle_world

You should see the full connection string from the TNSNAMES.ora file followed by the OK (60 msec) message. That indicates a successful connection.

You are ready to connect now:

--template
sqlplus username@tns_alias

--example
sqlplus admin@oracle_world

-- you can also use proxy access
sqlplus admin[john_doe]@oracle_world

After entering your password you are in. Welcome to SQL*Plus 🙂

Autotrace basics

As mentioned above, the autotrace will give you all the necessary data to know how costly the query is, how it was executed, and many more.

You can of course select only some metrics to be shown.

  • SET AUTOTRACE ON – shows both: execution plan and statistics with the result of the query
  • SET AUTOTRACE ON EXPLAIN – shows returned rows and the explain plan
  • SET AUTOTRACE ON STATISTICS – shows  returned rows and the statistics
  • SET AUTOTRACE TRACEONLY – shows both: execution plan and statistics without the results of the query (use please when the result is big)
  • SET AUTOTRACE TRACE EXPLAIN – shows the execution plan only without executing the query
  • SET AUTOTRACE OFF – disables tracing

Let’s see how a typical example might look.

--connect to the database via SQL*Plus
sqlplus admin@oracle_world

--set linesize to the max so we can see the whole output unwrapped
set linesize 32000;

-- set autotrace traceonly (do not output the results)
set autotrace traceonly;

-- issue the following query
SELECT p.position_name
, avg(e.salary) as avg_salary
, max(e.salary) as max_salary
, min(e.salary) as min_salary
FROM employee e
--
LEFT JOIN position p
ON p.id_position = e.id_position
--
WHERE 1=1
AND e.dtime_hired >= add_months(trunc(sysdate), -1)
--
GROUP BY p.position_name;



-- output of the autotrace
15 rows selected.

Elapsed: 00:00:03.13

Execution plan
----------------------------------------------------------
Plan hash value: 1846629066

------------------------------------------------------------------------------------------
| Id  | Operation                 | Name     | Rows   | Bytes   | Cost (%CPU) | Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |          |     15 |     424 |   36    (4) | 00:00:01 |
|   1 |  HASH GROUP BY            |          |     15 |     424 |   36    (4) | 00:00:01 |
| * 2 |   HASH JOIN OUTER         |          |    250 |  225091 |   15    (3) | 00:00:01 |
| * 3 |    TABLE ACCESS FULL      | EMPLOYEE |      9 |     324 |    3    (1) | 00:00:01 |
|   4 |    TABLE ACCESS FULL      | POSITION |    300 | 1890909 |   18    (3) | 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
----------------------------------------------------------
* 2 - access("P"."ID_POSITION" = "E"."ID_POSITION"(+))
* 3 - filter("E"."DTIME_HIRED">=ADD_MONTHS(TRUNC(SYSDATE@!),-1))

Statistics
----------------------------------------------------------
         10  recursive calls
          3  db block gets
        377  consistent gets
      10808  physical reads
          0  redo size
       1053  bytes sent via SQL*Net to client
        371  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         15  rows processed