Slow Query with an Interesting Execution Plan

8 02 2010

February 8, 2010

In one of the recent Oracle forums threads a person reported experiencing performance problems with a particular query, and in an atypical fashion, the original poster also provided an explain plan for the SQL statement, and stated their database release.
http://forums.oracle.com/forums/thread.jspa?messageID=4068085

A slightly reformatted version of the SQL statement looked like this:

SELECT
  A.BROKER_NAME,
  A.PARENT_BROKER_CODE,
  MAX(C.LAST_UPDATE_DATE) as LAST_SUBMISSION_DATE,
  BROKER_CODE as CHILD_BROKER_CODE,
  d.LOCATION
FROM
  CM_CACHE_BROKER a,
  REM_TAG_VALUE b,
  CM_ENUM_TAG c,
  CM_CACHE_BROKER_detail d
WHERE
  A.PARENT_BROKER_CODE = B.TAG_VALUE
  AND EXISTS
    (SELECT
      1
    FROM
      REM_TAG_LIST d
    WHERE
      D.TAG_LIST_ID = B.TAG_LIST_ID
      AND D.TAG_LIST_CODE = 'FCBrokerCode')
  AND B.TAG_VALUE_ID = C.TAG_VALUE_ID
  AND a.BROKER_ID=d.BROKER_ID
GROUP BY
  BROKER_NAME,
  PARENT_BROKER_CODE,
  BROKER_CODE,
  location
order by
  BROKER_NAME;

Just from looking at the SQL statement, we start seeing a couple of problems:

  • Not all of the columns are aliased – which table are those columns coming from?
  • The table aliases are confusingly assigned – what tables are involved with this predicate: “a.BROKER_ID=d.BROKER_ID”
  • The table in the EXISTS subquery, REM_TAG_LIST, uses the same alias “D” as the CM_CACHE_BROKER_detail table in the main section of the query, so looking at the Predicate Information section of a DBMS_XPLAN output could be confusing.  A recent article on another blog offers suggestions for improving the readability of table aliases.

The original poster in the thread provided an interesting execution plan, created using EXPLAIN PLAN FOR:

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1299486493

--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name                   | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                        |  7947 |  1544K|       | 10839   (1)| 00:02:11 |       |       |
|   1 |  SORT GROUP BY                      |                        |  7947 |  1544K|  3368K| 10839   (1)| 00:02:11 |       |       |
|*  2 |   HASH JOIN                         |                        |  7947 |  1544K|       | 10493   (1)| 00:02:06 |       |       |
|   3 |    TABLE ACCESS FULL                | CM_CACHE_BROKER_DETAIL |  6266 |   189K|       |    29   (0)| 00:00:01 |       |       |
|   4 |    TABLE ACCESS BY LOCAL INDEX ROWID| CM_ENUM_TAG            |    41 |  1025 |       |  4970   (1)| 00:01:00 |       |       |
|   5 |     NESTED LOOPS                    |                        |  4796 |   786K|       | 10463   (1)| 00:02:06 |       |       |
|*  6 |      HASH JOIN                      |                        |   117 | 16731 |       |   978   (1)| 00:00:12 |       |       |
|   7 |       TABLE ACCESS FULL             | CM_CACHE_BROKER        |  3781 |   158K|       |    15   (0)| 00:00:01 |       |       |
|   8 |       NESTED LOOPS                  |                        | 74085 |  7234K|       |   962   (1)| 00:00:12 |       |       |
|   9 |        TABLE ACCESS BY INDEX ROWID  | REM_TAG_LIST           |     1 |    43 |       |     1   (0)| 00:00:01 |       |       |
|* 10 |         INDEX UNIQUE SCAN           | AK1_REM_TAG_LIST_CODE  |     1 |       |       |     0   (0)| 00:00:01 |       |       |
|  11 |        TABLE ACCESS BY INDEX ROWID  | REM_TAG_VALUE          | 74085 |  4123K|       |   961   (1)| 00:00:12 |       |       |
|* 12 |         INDEX RANGE SCAN            | REM_TAG_VALUE_IDX1     | 74085 |       |       |   115   (1)| 00:00:02 |       |       |
|  13 |      PARTITION HASH ALL             |                        |  4120 |       |       |    32   (0)| 00:00:01 |     1 |    16 |
|* 14 |       INDEX RANGE SCAN              | IDX5_ENUM_TAG          |  4120 |       |       |    32   (0)| 00:00:01 |     1 |    16 |
--------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("A"."BROKER_ID"="D"."BROKER_ID")
   6 - access("B"."TAG_VALUE"=SYS_OP_C2C("A"."PARENT_BROKER_CODE"))
  10 - access("D"."TAG_LIST_CODE"=U'FCBrokerCode')
  12 - access("D"."TAG_LIST_ID"="B"."TAG_LIST_ID")
  14 - access("B"."TAG_VALUE_ID"="C"."TAG_VALUE_ID")

So, what is unusual about the execution plan?  Look closely at the Predicate Information section.  The “D” alias for ID 2 refers to a different table than the “D” alias for ID 12.  It might have been slightly more interesting if transitive closure changed the predicate for ID 12 to the following, where the “D” aliases on each side of the equal sign referred to different tables (I wonder if this would cause wrong results):

access("D"."TAG_LIST_ID"="D"."TAG_LIST_ID")

OK, but that is not the interesting portion of the Predicate Information section of the execution plan.  Notice that the predicate for ID 6 shows “=SYS_OP_C2C(“A”.”PARENT_BROKER_CODE”))“.  Just what does that SYS_OP_C2C mean?  A web search found two articles describing this function:

Implicit Character Set to Character Set References:
http://jonathanlewis.wordpress.com/2007/07/29/nls/
http://joze-senegacnik.blogspot.com/2009/12/what-is-purpose-of-sysopc2c-internal.html

But, we are not done yet.  Notice that the predicate for ID 10 shows “=U’FCBrokerCode’“.  That “U” character appears to be in an unusual location.  user503699 in the OTN thread provided a test case that triggered an execution plan with a “U” character in a similar position in the access predicates.  The cause?  A column in a table was defined as a NVARCHAR2 datatype, and the WHERE clause of a query specified that the column value must be equal to ‘A’.

Here is a demonstration of what might be happening, using an example similar to what user503699 posted in the OTN thread:

CREATE TABLE T1 (
  C1 VARCHAR2(100),
  C2 NVARCHAR2(100));

INSERT INTO
  T1
SELECT
  'A'||ROWNUM,
  'A'||ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT; 

The above created a table with 100,000 rows with a VARCHAR2 and a NVARCHAR2 column.  Next, we will query the table and display the execution plan:

SELECT
  *
FROM
  T1
WHERE
  C2='A100000';

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID  0j7y39qb11zk3, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   C2='A100000'

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   103 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     4 |   616 |   103   (1)| 00:00:02 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("C2"=U'A100000')

Note
-----
   - dynamic sampling used for this statement

In the above, notice the oddly placed “U”, just like we saw in the OP’s OTN post – this happened when a passed in string was converted for comparison with the NVARCHAR2 column.  Now, a second test:

SELECT
  *
FROM
  T1
WHERE
  C2='A100000'
  AND C1=C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID  6anxauy8vv87b, child number 0
-------------------------------------
SELECT   * FROM   T1 WHERE   C2='A100000'   AND C1=C2

Plan hash value: 3617692013

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |   103 (100)|          |
|*  1 |  TABLE ACCESS FULL| T1   |     9 |  1386 |   103   (1)| 00:00:02 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("C2"=U'A100000' AND SYS_OP_C2C("C1")=U'A100000'))

Note
-----
   - dynamic sampling used for this statement

OK, that ended up a little different than what was expected.  Notice, through the magic of transitive closure on Oracle 11.1.0.7, the AND C1=C2 join condition was removed and replaced with what might be a less efficient predicate, but shows the seemingly unnecessary use of the SYS_OP_C2C function:

  AND SYS_OP_C2C("C1")=U'A100000'

Back to the original problem.  So, what is the cause of the performance problems for the query posted by the OP?  No one yet suggested that the OP should immediately re-execute the query with the following hint to see if the hint helps the query complete faster: 

  /*+ OPT_PARAM('FAST','TRUE') */

Maybe there is a more logical path to fixing the performance problem?


Actions

Information

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




Follow

Get every new post delivered to your Inbox.

Join 144 other followers

%d bloggers like this: