Give Me a Hint – How were These Autotrace Execution Statistics Achieved?

27 06 2011

June 27, 2011

I recently received an email asking why different performance is achieved when a FIRST_ROWS hint, FIRST_ROWS(100) hint, and an unhinted version of the query are executed.  This seems to be a simple problem, yet it might also be an interesting problem.  I thought that it might be helpful to transform my response into a blog article (allowing the input of readers of this blog), rather than provide an email response (sorry, I typically do not respond to email requests).  What if (flushing the buffer cache between executions with a single execution of ALTER SYSTEM FLUSH BUFFER_CACHE;):

  • The unhinted version of the query completes 2 seconds faster than the FIRST_ROWS(100) hinted version of the query?
  • The FIRST_ROWS hinted version of the query completes 22 seconds faster than the unhinted version of the query (thus the FIRST_ROWS hinted version completes 24 seconds faster than then FIRST_ROWS(100) hinted version of the query).
  • According to the AUTOTRACE output, the execution plans for the FIRST_ROWS hinted version and the FIRST_ROWS(100) hinted version of the query both perform a descending index range scan on the primary key column for the one table (the only data source) in the query.
  • According to the AUTOTRACE output, the unhinted version of the query shows that a full table scan was performed.
  • While the FIRST_ROWS(100) hinted execution required longer to complete than the FIRST_ROWS hinted execution, the FIRST_ROWS(100) hinted execution performed 69% as many physical block reads as the FIRST_ROWS hinted execution, while exactly the same number of consistent gets were performed in both cases.
  • The queries retrieved 1,042,684 rows with an array fetch size of 15.
  • For the FIRST_ROWS(100) and FIRST_ROWS hinted versions of the query, roughly 263.97MB was returned to the client, while only about 163.62MB (62% of the hinted version) was returned in the unhinted version of the query.

The question is how would one explain the results?  Here is a slightly modified version of the query, with just the table and column names replaced:

SELECT
  C1,
  C2,
  C3,
  C4,
  C5,
  C6,
  C7
FROM
  T1      
WHERE
  C1 < 1042685
ORDER BY
  C1 DESC; 

In the above, note that C1 must be the primary key column… unless of course there are multiple columns in the primary key (or the index displayed in the execution plans really is not the primary key index).

The order of the query executions was not specified, but let’s assume that the OP listed the executions in the same order as executed.

The unhinted execution:

Elapsed: 00:00:53.00

----------------------------------------------------------------------------------------
| Id  | Operation          | Name      | Rows  | Bytes |TempSpc| Cost (%CPU)| Time
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |           |  1042K|   255M|       |   120K  (1)| 00:24:03 |
|   1 |  SORT ORDER BY     |           |  1042K|   255M|   313M|   120K  (1)| 00:24:03 |
|*  2 |   TABLE ACCESS FULL| T1        |  1042K|   255M|       | 62490   (1)| 00:12:30 |
---------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("C1"<1042685)

Statistics
----------------------------------------------------------
          1  recursive calls
          1  db block gets
     244502  consistent gets
     244458  physical reads
       2836  redo size
  171565915  bytes sent via SQL*Net to client
     765155  bytes received via SQL*Net from client
      69514  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
    1042684  rows processed 

The FIRST_ROWS hinted execution:

Elapsed: 00:00:31.11

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |  1042K|   255M|   189K  (1)| 00:37:51 |
|   1 |  TABLE ACCESS BY INDEX ROWID | T1           |  1042K|   255M|   189K  (1)| 00:37:51 |
|*  2 |   INDEX RANGE SCAN DESCENDING| PK_T1        |  1042K|       |  2136   (1)| 00:00:26 |
---------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1"<1042685)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
     345027  consistent gets
      38750  physical reads
          0  redo size
  276788545  bytes sent via SQL*Net to client
     765156  bytes received via SQL*Net from client
      69514  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1042684  rows processed

The FIRST_ROWS(100) hinted execution:

Elapsed: 00:00:55.69

Execution Plan
----------------------------------------------------------
Plan hash value: 2367722674
---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |   101 | 25957 |    22   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID | T1           |  1042K|   255M|    22   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN DESCENDING| PK_T1        |   101 |       |     3   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1"<1042685)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
     345027  consistent gets
      26788  physical reads
          0  redo size
  276788545  bytes sent via SQL*Net to client
     765156  bytes received via SQL*Net from client
      69514  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
    1042684  rows processed 

There are a number of items that we do not know about the OP’s configuration.  Just a couple of random thoughts:

  • How might we explain why only 62% as many bytes were transferred over the network in the unhinted version of the query?  Could it be a case where SQL*Net compression has helped to strip the repeating column values from adjacent rows in the result set prior to transmission over the network.  Could it be the case that the rows were ordered differently if column C1 were the only column in the primary key?  What if there were multiple columns in the primary key – could that make a difference (note that the C1 < 1042685 predicate in the WHERE clause combined with the 1,042,684 rows returned suggests that column C1 might be the only column in the primary key)?  Does SQL*Net compression not work when rows are retrieved by an index access path to avoid a sort operation?  This portion of the result is a bit interesting.
  • How might we explain the number 2836 next to redo size in the unhinted execution?  Might this be a case of Delayed Block Cleanout?  Could that number also partially explain the execution time for that version of the query?
  • How might we explain the decrease in the number of physical block reads in the FIRST_ROWS(100) hinted execution compared to the FIRST_ROWS hinted execution?  Assuming that the executions were performed in the above order, what if the ALTER SYSTEM FLUSH BUFFER_CACHE; command did not actually flush all of the blocks from the buffer cache – is that possible?  Could undo blocks for a consistent read have an impact?
  • The operations displayed in the execution plans for the two hinted queries are identical, yet the execution times are significantly different.  How might we explain the time difference?
    • — Do we know for certain that the runtime execution engine used the execution plan that was displayed?
    • — Is it possible that one of the queries was executed with SET AUTOTRACE ON specified in SQL*Plus while the fast execution was performed with SET AUTOTRACE ON STATISTICS specified in SQL*Plus (thus entirely avoiding the client-side formatting of the output)?
    • — Is it possible that SET AUTOTRACE ON was specified in both cases, yet the SQL*Plus window was minimized during the FIRST_ROWS hinted execution (thus avoiding the client-side screen refreshes)?
    • — Is it possible that there was less network congestion during the FIRST_ROWS hinted execution?
    • — Is it possible that the client computer’s CPU (or the server’s CPU) was less busy with other tasks during the FIRST_ROWS hinted execution?
    • — Is it possible that operating system caching is having an effect – if the entire execution time was spent in single block read wait events, the average single block read time for the FIRST_ROWS hinted execution was roughly 0.00080 seconds, while the average single block read time for the FIRST_ROWS(100) hinted execution was roughly 0.00208 seconds.
    • — Note that the AUTOTRACE output indicates that one recursive call was performed per execution – is it possible that the time difference and the difference in the number of physical block reads could be attributed to the recursive call?

What other items might explain the time difference in the three executions?  What advice would you provide to the OP?  Should we answer the original question using 10 more questions?








Follow

Get every new post delivered to your Inbox.

Join 137 other followers