AUTOTRACE Problem

I’ve commented before about how AUTOTRACE is a favoured tool for a quick performance check of a query. So, whenever a developer pays an interest in it I’m glad to help where I can.

Recently a developer told me that AUTOTRACE wasn’t working for them. They sent across their script, which enabled AUTOTRACE with:

SET AUTOTRACE TRACEONLY

and the output they were getting. The output was very strange (this is from an 11.2.0.3 database):

Statistics
----------------------------------------------------------
          0  user rollbacks
          0  global enqueue releases
          0  physical read requests optimized
          0  physical write total multi block requests
          0  hot buffers moved to head of LRU
          0  commit wait performed
          0  global undo segment hints helped
          0  global undo segment hints were stale
          0  IMU commits
          0  IMU Flushes
        244  rows processed

Running their script in my own account revealed nothing wrong; the AUTOTRACE output was present and correct. Looking into the roles and privileges on the developer’s account showed nothing amiss either… but their account did show as having an expired password. A change of their password and the problem was resolved.

Why did resetting a password resolve an AUTOTRACE problem? What might not be understood about AUTOTRACE is that it creates a new session in order to do its profiling. With the password expired I guess that AUTOTRACE couldn’t do its usual work and generated the strange output above. It’s not good that it didn’t report some sort of login problem but it didn’t take long to resolve. I’ve simply made a mental note (and a blog post to remind me) to check for expired passwords next time someone tells me that AUTOTRACE isn’t working for them.

Advertisements

Oracle lies!

“Everybody lies” was the common phrase used by Dr Gregory House in the TV show House MD. It seems Oracle is no different…

I was recently asked to help a developer tune a change they had made to a query. The query was relatively lengthy given that it was for an OLTP system, hence the need to ensure it ran as efficiently as possible.

Running the original query through Autotrace generated approximately 1,700 logical IO operations, which is one of the critical metrics I use for quickly judging efficiency. Autotrace on the modified query initially reported twice the logical IOs that was quickly identified to be a problem with the way Oracle was ordering the tables. A simple application of the LEADING hint brought the logical IO down… but only to around 1,800, which was 100 higher than the original query.

For the next hour I struggled to work out why the modified query was reporting a higher logical IO figure than the original query. Yes, the query had been modified but the change was the replacement of a subquery that returned a single value with a bind variable holding that value. My expectation was that the modified query should be 3 IO operations less than the original query (just to note, the change to the query really wasn’t worth it from a query tuning perspective but was primarily being done for other reasons).

After applying hints that forced the modified query to behave as closely as possible to the original query the logical IO was still 100 greater. Verification of the result-set showed that both queries did return the same results too, which is another thing to verify when performing any sort of query tuning.

My next step was to examine the execution of both queries using SQL monitor and this was when I discovered that Oracle had been lying to me all along. At the core of the query were about half a dozen tables. The execution plan reported by Autotrace joined them in a particular order and the hints I had applied to the modified query mimicked this order. However, the SQL plan details as revealed by SQL monitor showed that Oracle joined the tables in a different order, choosing to lead with a different table.

I had fallen into the one trap with Autotrace execution plan that I had noted in my earlier blog post:

The main point to note is that the execution plan is simply the proposed plan and in certain situations the database may choose to execute the query differently. For example, the execution plan may be altered as a result of bind variable peeking.

Another way of uncovering the difference in the predicted and actual plans would have been to extract the real plan from the SGA, using dbms_xplan.display_cursor.

It’s not common for the execution plan reported by Explain Plan or Autotrace to be different to the one that Oracle will actually use when executing the query but it is possible. Perhaps I should have been open to the possibility of this earlier and saved myself a bit of angst. Simply hinting the modified query with the different table order resolved the problem of the IO difference. I went home that day happy but mentally cursing Oracle for lying to me and leading me astray in the first place.

Using autotrace – part 2

In the previous part of this post we briefly looked at autotrace, what it is, how to access it and what it can tell us. In this part we’ll use autotrace to make some observations about simple queries to illustrate it’s usefulness.

The examples that follow were performed on an Oracle 11.2.0.2 64-bit database running on Windows 7 64-bit.

We’ll start off by creating a test table with 3 columns, a primary key on one of the columns and populate it with 1 million rows. Like any good Oracle developer we gather statistics on the table once we’ve populated it.

SET ECHO ON
SET DEFINE OFF

CREATE TABLE test_tab
  (id      NUMBER(10) NOT NULL
  ,val     NUMBER(10) NOT NULL
  ,padding CHAR(50)   NOT NULL
  )
/

INSERT INTO test_tab
SELECT rownum
,      MOD(rownum,1000)
,      'X'
FROM   dual
CONNECT BY rownum <= 1000000
/

COMMIT
/

CREATE UNIQUE INDEX test_tab_pk
ON test_tab (id)
/

ALTER TABLE test_tab
ADD CONSTRAINT test_tab_pk
PRIMARY KEY (id)
/

EXEC dbms_stats.gather_table_stats('','TEST_TAB')

First up, let’s run a simple query to look up a single row from the table with autotrace enabled in its default state. A word of warning though, the script clears the buffer and library caches first so please don’t try this on your production system! The script we’ll execute is:

SET ECHO ON

ALTER SYSTEM FLUSH BUFFER_CACHE
/

ALTER SYSTEM FLUSH SHARED_POOL
/

SET AUTOTRACE ON

SELECT *
FROM   test_tab
WHERE  id = 123456
/

SET AUTOTRACE OFF

Which gives us the following output:

SQL> SET ECHO ON
SQL>
SQL> ALTER SYSTEM FLUSH BUFFER_CACHE
  2  /

System altered.

SQL>
SQL> ALTER SYSTEM FLUSH SHARED_POOL
  2  /

System altered.

SQL>
SQL> SET AUTOTRACE ON
SQL>
SQL> SELECT *
  2  FROM   test_tab
  3  WHERE  id = 123456
  4  /

        ID        VAL PADDING
---------- ---------- --------------------------------------------------
    123456        456 X

Execution Plan
----------------------------------------------------------
Plan hash value: 752309145

-------------------------------------------------------------------------------------------
| Id  | Operation                   | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |             |     1 |    60 |     3   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| TEST_TAB    |     1 |    60 |     3   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | TEST_TAB_PK |     1 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ID"=123456)

Statistics
----------------------------------------------------------
         73  recursive calls
          0  db block gets
         77  consistent gets
         45  physical reads
          0  redo size
        579  bytes sent via SQL*Net to client
        509  bytes received via SQL*Net from client
          1  SQL*Net roundtrips to/from client
          6  sorts (memory)
          0  sorts (disk)
          1  rows processed

SQL>
SQL> SET AUTOTRACE OFF

As can be expected, the execution plan section of the output shows that Oracle obtained the relevant row from the table via the primary key index. The execution plan shown is the same as would be obtained from using EXPLAIN PLAN FOR … followed by DBMS_XPLAN.DISPLAY. The Statistics section is where autotrace shows its “value add” beyond the execution plan.

The Statistics from the initial query tells us (keep in mind that the library and buffer caches had been cleared):

  • Oracle needed to do 73 internal query operations to run the query. These internal queries are lookups into the data dictionary to ensure the table exists, what columns the table has, whether the user has access to the table, etc.
  • The 0 db block gets tells us that Oracle did not access any data in “current” mode, which is what would be required if Oracle were to update the data.
  • 77 consistent gets gives us the number of logical I/O operations Oracle made into it’s block cache. Many of these would have resulted from the recursive queries Oracle ran.
  • Oracle was required to make 45 physical reads against the disk in order to get the data needed for the query. This too will include data needed for the recursive calls made and not just the TEST_TAB table that the query ran against.
  • Since the query did not modify the data the redo size is 0, which would be expected.
  • The next two entries tells us how much data was transferred from the database to the SQL Plus client. The roundtrips entry tells us that all the data was done via 1 roundtrip and that Oracle didn’t need to stream data to SQL Plus across multiple trips to retrieve all the data.
  • 6 sorts of data were required to complete the query. Given that the execution plan didn’t contain an operation requiring a sort we can assume that the sorts were done by the recursive calls.
  • Finally the query resulted in 1 row being returned back to the client.

If we were to execute the exact same query again without flushing the library and buffer caches, the autotrace statistics would change:

SQL> SET ECHO ON
SQL> SET AUTOTRACE ON
SQL>
SQL> SELECT *
  2  FROM   developer.test_tab
  3  WHERE  id = 123456
  4  /

        ID        VAL PADDING
---------- ---------- --------------------------------------------------
    123456        456 X

Execution Plan
----------------------------------------------------------
Plan hash value: 752309145

-------------------------------------------------------------------------------------------
| Id  | Operation                   | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |             |     1 |    60 |     3   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| TEST_TAB    |     1 |    60 |     3   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | TEST_TAB_PK |     1 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("ID"=123456)

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

SQL>
SQL> SET AUTOTRACE OFF
SQL>
SQL> SELECT blevel
  2  FROM   user_indexes
  3  WHERE  index_name = 'TEST_TAB_PK'
  4  /

    BLEVEL
----------
         2

The execution plan section shows that we executed a query that was identical to the previous one. However, since Oracle now has the query cached in its library and the table data cached in the buffer cache we see the elimination of recursive calls and sorts in the statistics section. More importantly, logical I/O (consistent gets) has dropped dramatically and is now just 4. We can calculate this value by looking at the execution plan and the size of the index. According to Oracle it “walked” the index to find where the relevant row was in the table and then jumped straight to the row. Querying the data dictionary we see that the index contains 2 branch levels (BLEVEL from the USER_INDEXES view) so that accounts for 2 consistent gets, accessing the index leaf block gives us 1 more consistent get and reading the row in the table gives us another 1, which totals the 4 that autotrace reports.

As might be anticipated, the number of bytes sent to and from the SQL Plus client remains the same, as does the number of rows processed.

The last autotrace example illustrates the impact that the number of rows that the client fetches at a time has on the processing of a query. In this example, we retrieve 1,000 rows from our table. In the first query we retrieve 10 rows at a time and in the second query we take 500 rows at a time.

Our script is:

SET ECHO ON

VARIABLE l_start NUMBER
VARIABLE l_end   NUMBER

EXEC :l_start := 123000
EXEC :l_end   := 123999

SET ARRAYSIZE 10

SET AUTOTRACE TRACEONLY

SELECT *
FROM   test_tab
WHERE  id BETWEEN :l_start AND :l_end
/

SET ARRAYSIZE 500

SELECT *
FROM   test_tab
WHERE  id BETWEEN :l_start AND :l_end
/

SET AUTOTRACE OFF

and the output is:

SQL> SET ECHO ON
SQL>
SQL> VARIABLE l_start NUMBER
SQL> VARIABLE l_end   NUMBER
SQL>
SQL> EXEC :l_start := 123000

PL/SQL procedure successfully completed.

SQL> EXEC :l_end   := 123999

PL/SQL procedure successfully completed.

SQL>
SQL> SET ARRAYSIZE 10
SQL>
SQL> SET AUTOTRACE TRACEONLY
SQL>
SQL> SELECT *
  2  FROM   test_tab
  3  WHERE  id BETWEEN :l_start AND :l_end
  4  /

1000 rows selected.

Execution Plan
----------------------------------------------------------
Plan hash value: 1954378606

--------------------------------------------------------------------------------------------
| Id  | Operation                    | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |             |  2500 |   146K|    53   (0)| 00:00:01 |
|*  1 |  FILTER                      |             |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| TEST_TAB    |  2500 |   146K|    53   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | TEST_TAB_PK |  4500 |       |    12   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(TO_NUMBER(:L_START)<=TO_NUMBER(:L_END))
   3 - access("ID">=TO_NUMBER(:L_START) AND "ID"<=TO_NUMBER(:L_END))

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        214  consistent gets
          0  physical reads
          0  redo size
      32791  bytes sent via SQL*Net to client
       1609  bytes received via SQL*Net from client
        101  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       1000  rows processed

SQL>
SQL> SET ARRAYSIZE 500
SQL>
SQL> SELECT *
  2  FROM   test_tab
  3  WHERE  id BETWEEN :l_start AND :l_end
  4  /

1000 rows selected.

Execution Plan
----------------------------------------------------------
Plan hash value: 1954378606

--------------------------------------------------------------------------------------------
| Id  | Operation                    | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |             |  2500 |   146K|    53   (0)| 00:00:01 |
|*  1 |  FILTER                      |             |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| TEST_TAB    |  2500 |   146K|    53   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | TEST_TAB_PK |  4500 |       |    12   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(TO_NUMBER(:L_START)<=TO_NUMBER(:L_END))
   3 - access("ID">=TO_NUMBER(:L_START) AND "ID"<=TO_NUMBER(:L_END))

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         19  consistent gets
          0  physical reads
          0  redo size
      14857  bytes sent via SQL*Net to client
        531  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       1000  rows processed

SQL>
SQL> SET AUTOTRACE OFF

From the autotrace output we can see that the execution plan is identical for both queries, which is not unexpected as the query is the same. It may also be fairly obvious that the number of network round trips and the amount of data sent to the SQL Plus client is greater with the smaller batch size. We did 101 round trips, totaling 32,791 bytes with a 10 row fetch size as opposed to 3 round trips and 14,857 bytes. The larger number of round trips will be especially noticeable in situations where network latency is a concern.

As a side note; why were there 101 round trips to fetch 1,000 rows when the fetch size was 10 (1000 / 10 = 100, not 101) and 3 round trips with the 500 fetch size? The answer is that after being provided with all the rows the client makes one more request and is told “that’s it”, which gives us the extra 1 round trip.

Autotrace also alerts us to one other aspect that may not be so obvious; the number of consistent gets is greater when the fetch size is 10 than when it is 500; 214 as compared to 19, a difference of 195. The reason for this is that after every batch is fetched the database is required to go back into the data where it left off. These extra visits result in more logical I/O operations since it will visit the same index and table blocks multiple times; nearly 100 extra index and table visits, which gives us the 195 extra consistent gets.

From this last example autotrace has clearly shown the extra overhead involved in having a small fetch size. Since the fetch size is controlled by the client it is worth reviewing with the client application developers that they have sized this appropriately. Of course, an assumption in this example is that the 1,000 rows were actually required. The most efficient strategy is to filter the data inside the database and only retrieve the rows that are actually required by the application.

This concludes our initial look at autotrace. It’s a quick and simple tool for obtaining some highly useful information about the performance of SQL statements. The combination of execution plan, simple statistics and easy accessibility makes it particular attractive for quick investigations when things go wrong or for evaluating different strategies when composing SQL.

Using autotrace – part 1

Database performance is always a hot issue for any application. It seems to me that whenever a user complains about performance, the database is the first place that people point their finger at. In many ways though this attitude is deserved… the performance of the database is often not considered early enough in system design and the impact of an inefficient query can be devastating. The focus of this post is on one of the simplest performance tools Oracle provides; autotrace.

Autotrace provides the database developer with a number of key pieces of information necessary to assess the performance characteristics of a query:

  • The query result-set
  • The proposed query execution plan
  • Execution statistics, including I/O, network details and sorts

It’s important to understand that autotrace can only used for a single SQL statement only, i.e. SELECT, INSERT, UPDATE, DELETE or MERGE. It cannot be used for PL/SQL blocks. For more advanced statistics that can be used with PL/SQL then you may like to look at Tom Kyte’s runstats utility.

Accessing & Enabling Autotrace

A key advantage of autotrace is that it is available to every developer as part of the database and is accessible from within tools that are commonly used, such as Oracle SQL Developer and Quest Toad.

If autotrace hasn’t been configured on your database then you will find the installation script at:

$ORACLE_HOME/sqlplus/admin/plustrce.sql

Oracle SQL Developer

SQL Developer makes autorace easy; simply enter your SQL in the editor and press F6. Alternately, the following button on the toolbar will also work:

autotrace trace in SQl Developer

Interestingly, SQL Developer displays a lot more statistics than the SQL Plus facility does leading me to conclude it’s simply mimicking the true autotrace facility. Regardless, the key autotrace statistics are present.

Quest TOAD

Autotrace can be activated in TOAD by right-clicking in an editor window and selecting ‘autotrace’ from the context menu. The menu is on the rather long and you’ll find the autotrace option somewhere near the middle. Selecting the option will put a tick next to it and TOAD will then populate the autotrace output window when a query is run. You may need to enable the autotrace output window by right-clicking in the output panel and selecting the autotrace option.

autotrace in TOAD

A word of caution about autotrace in TOAD; it seems to only track a single query execution across all editor tabs for a session. If you have multiple editor tabs open and run different queries in them simultaneously then double check the autotrace output matches the query. Perhaps this has been fixed in the later versions of TOAD though…

SQL Plus

Simply issuing the command:

SET AUTOTRACE ON

enables autotrace within SQL Plus. Other variants of the command can be used to restrict the details that are displayed. For example,

SET AUTOTRACE TRACEONLY

suppresses the display of the query result set so that only the execution plan and run time statistics are shown. This can be further limited with:

SET AUTOTRACE TRACEONLY STATISTICS

which only displays the run time statistics only. I find these last options particularly useful for comparing similar statements since it removes the “clutter” of the query output allowing me to focus on the analysis details.

Information Displayed

As previously noted, the key pieces of information displayed by autotrace are:

  • The query result-set
  • The proposed query execution plan
  • Execution statistics, including I/O, network details and sorts

The details that follow are written from the view of autotrace in SQL Plus.

Query Result-set

There’s not much to say about this section; it’s the results of the query. One point to note is that even if the query output is suppressed by using one of the options noted previously the data is still fetched from the database and transferred to the client. So, a query that returns millions of rows is still going to transfer all that data to your client; it just won’t get displayed to the screen.

In a similar vein, all of the data needs to be transferred before autotrace can report on the statistics so it will fetch the entire result-set. You may find that some queries return fast when autotrace is disabled in a GUI tool and take ages with autotrace enabled. This is probably due to the GUI client fetching only the first few rows of the result-set and displaying those immediately rather than waiting until all rows have been fetched before displaying anything.

Proposed Execution Plan

The query execution plan displayed by autotrace is the same that you would get by running:

EXPLAIN PLAN
FOR
<<insert query>>
/

SELECT *
FROM   TABLE(dbms_xplan.display())
/

I don’t intend to discuss execution plans in this post as it’s a rather large subject. The main point to note is that the execution plan is simply the proposed plan and in certain situations the database may choose to execute the query differently. For example, the execution plan may be altered as a result of bind variable peeking.

Execution Statistics

This is the section that I find most valuable. The execution statistics displayed are:

recursive calls The number of queries the database runs in addition to the query specified. This includes any data dictionary queries when hard parsing the query, e.g. looking up table and column details used in the original query. Queries executed by functions used within the query will also show up as recursive calls. CURSOR expressions will also increase the number of recursive calls.
db block gets the amount of logical I/O (logical I/O is I/O performed against the buffer cache) that is performed in “current mode”, i.e. the latest version of the block as opposed to “read consistent mode”
consistent gets the amount of logical I/O that is performed in “read consistent mode”, i.e. as the data appeared at the start of the query execution.
physical reads The amount of data that was read from storage. This may include data that was read for operations such as sorts that were too large to be performed in memory.
redo size The amount of redo, in bytes, generated by the query. Generally this will be 0 for normal SELECT queries and have some value for INSERTs, UPDATEs, MERGEs and DELETEs.
bytes sent via SQL*Net to client The amount of data sent to the client application by the database
bytes received via SQL*Net from client The amount of data received by the database from the client application
SQL*Net roundtrips to/from client The number of network communications from client to server and back again.
sorts (memory) The number of data sort operations that were able to be performed in memory.
sorts (disk) The number of data sort operations that were sufficiently large enough to require spilling to disk. These will perform more slowly than memory sorts.
rows processed The number of rows returned by a SELECT query or the number of rows modified by an INSERT, UPDATE, MERGE or DELETE statement.

You’ll note that there is no statistic regarding physical writes. This is because the DB Writer process is responsible for writing modified data blocks to disk, not the session that modified the data. A session may perform physical writes for operations such as disk sorts but this would be only part of the overall I/O picture.

In the next part on this post we explore a couple of queries and look at what autotrace tells us about them…


Other autotrace references:
autotrace in the Oracle Database documentation
Tom Kyte has a good write-up of autotrace in his book Effective Oracle by Design