Tracking Performance Problems – Inserting a Hint into SQL in a Compiled Program

18 12 2009

December 18, 2009

What follows is part of a presentation that I gave in 2008. 

The lead into this slide is that a report in an ERP package was running far slower than expected following an upgrade of the ERP package.  Of course the SQL statements are hard coded into the ERP package, so there is not much that can be done, right?  I created a 10046 extended SQL trace file at level 12, and then passed the trace file through my Toy Project for Performance Tuning (http://hoopercharles.wordpress.com/2009/12/13/toy-project-for-performance-tuning-2/).  One of the outputs of my program’s 10046 trace file parser provides an overview of the trace file, as well as an overview of each SQL statement.  A screen shot of that output follows:

The screen shot shows that there were 10,399 execute calls in the trace file that consumed 47.67 seconds of the server’s CPU time, and that the elapsed time/wall clock time from the server’s perspective for executing the SQL statements is 50.32 seconds for the executions.  There were 16,146 fetch calls that consumed 263.48 seconds of the server’s CPU time, and the elapsed time/wall clock time from the server’s perspective for fetching the rows for the SQL statements is 263.64 seconds.  Note that there were 0 physical reads and 8,804,970 consistent gets during the fetch (what’s that buffer cache hit ratio?).  The SQL*Net message from client wait totaled 107.33 seconds, but 42.62 seconds were in a single block of time (likely at the end of the trace file, just before tracing was disabled), so the actual total time waiting for the next request from the client is about 64.7 seconds in 22,825 round-trips.

If we scroll down a bit, we might find a couple of the greatest contributors to the server-side processing:

The screen shot shows that there are two groups of SQL statements that combined contributed to 86% of the total server-side processing time for the report.  The first SQL statement group is identified as Cursor 16 Ver 1, and the second is identified as Cursor 17 Ver 1. 

We could then search the remainder of this file to locate those identifiers.

The above screen shot shows that there are two identical SQL statements in the first group – the first SQL statement (Cursor 16 Ver 1) was parsed, but never executed.  The row source execution plan from the 10046 trace file (in the STAT lines) shows that the optimizer decided to use the index X_RECEIVABLE_3 that is on the column ENTITY_ID (there are two distinct values for this column), rather than the much more selective index on the INVOICE_ID column.  Notice the number of consistent gets and the CPU utilization for this one SQL statement that was executed 934 times.

Why was the index selected?  Would a DBMS_XPLAN help?

The DBMS_XPLAN output shows that the optimizer estimated that the X_RECEIVABLE_3 index would return a single row, when in fact it returned 66124 rows.  A problem where statistics were not collected in the last 15 years?  No.

Maybe a 10053 trace will help:

In the above we see that the predicted number of rows returned with the X_RECEIVABLE_3 index will be less than that for the other indexes, and the expected CPU resources will also be slightly less, but something is not right.  The optimizer selected not to use the primary key index on the RECEIVABLE table.  Note that the calculated cost for all three indexes is 2.

Let’s try an experiment with a NO_INDEX hint to prevent the optimizer from using the X_RECEIVABLE_3 index:

In the above, notice that the primary key index (SYS_C006885) was selected by the optimizer, that the execution time dropped from 0.31 seconds to 0.01 seconds (or less), and the number of consistent gets dropped from 1311 to 5.  A rather nice improvement, but how do we force the ERP package to not use the index without the ability to modify the program’s source code?

We could do something like this, if we assume that bind variable peeking is the source of the problem:

CREATE OR REPLACE TRIGGER LOGON_FIX_APP_PERF AFTER LOGON ON DATABASE
DECLARE
  SHOULD_EXECUTE INTEGER;
BEGIN
  SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,2),'VM',1,'VF',1,0)+DECODE(INSTR(PROGRAM,'\',-1),0,0,DECODE(SUBSTR(UPPER(SUBSTR(PROGRAM,INSTR(PROGRAM,'\',-1)+1)),1,2),'VM',1,'VF',1,0)) INTO SHOULD_EXECUTE FROM V$SESSION WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1);
  IF SHOULD_EXECUTE > 0 THEN
    EXECUTE IMMEDIATE 'ALTER SESSION SET "_optim_peek_user_binds"=FALSE';
  END IF;
END;
/

The above logon trigger results in the following row source execution plans:

But, the above approach may be too broad as it will affect every SQL statement executed by a program that begins with the letters VM or VF.  It did help this report:

The time to fetch all rows dropped from 264 seconds to just 11 seconds, and the full report displays in just over a minute.

Let’s see if we are able to trick the optimizer into not using the X_RECEIVABLE_3 index without disabling bind variable peeking.  First, we need to enable private outlines in the current session:

ALTER SESSION SET USE_PRIVATE_OUTLINES=TRUE;

For demonstration purposes, I will explicitly tell the optimizer to use the X_RECEIVABLE_3 index when creating the outline (the exact SQL statement used by the program should be used, without the hint):

CREATE OR REPLACE PRIVATE OUTLINE P_RECEIVABLE1 ON
select /*+ INDEX(I X_RECEIVABLE_3) */ sum(a.apply_amount)
from RECV_MEMO_APPLY a, RECEIVABLE i
where a.inv_invoice_id = :1          
and a.apply_date <= :2             
and a.inv_invoice_id = i.invoice_id
and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :3 and ENTITY_ID = :4;

Note that I had to specify a hint in this case as I was at the time testing in Oracle 11g R1 (11.1.0.6), which refused to use the X_RECEIVABLE_3 on its own to reproduce the problem seen with Oracle 10.2.0.x.

Let’s view the hints generated by the optimizer when it created the outline:

SELECT
  HINT#,
  HINT_TEXT
FROM
  OL$HINTS
WHERE
  OL_NAME='P_RECEIVABLE1';

HINT#  HINT_TEXT
    1  USE_NL(@"SEL$1" "A"@"SEL$1")
    2  LEADING(@"SEL$1" "I"@"SEL$1" "A"@"SEL$1")
    3  INDEX(@"SEL$1" "A"@"SEL$1" ("RECV_MEMO_APPLY"."INV_INVOICE_ID" "RECV_MEMO_APPLY"."MEMO_INVOICE_ID"))
    4  INDEX(@"SEL$1" "I"@"SEL$1" ("RECEIVABLE"."ENTITY_ID"))
    5  OUTLINE_LEAF(@"SEL$1")
    6  ALL_ROWS
    7  OPTIMIZER_FEATURES_ENABLE('10.2.0.2')
    8  IGNORE_OPTIM_EMBEDDED_HINTS

We can then verify that in fact the slow execution plan was selected:

EXPLAIN PLAN FOR
select /*+ INDEX(I X_RECEIVABLE_3) */ sum(a.apply_amount)
from RECV_MEMO_APPLY a, RECEIVABLE i
where a.inv_invoice_id = :1          
and a.apply_date <= :2             
and a.inv_invoice_id = i.invoice_id
and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :3                   and ENTITY_ID = :4;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY(NULL,NULL,'BASIC +NOTE'));

------------------------------------------------------------
| Id  | Operation                      | Name              |
------------------------------------------------------------
|   0 | SELECT STATEMENT               |                   |
|   1 |  SORT AGGREGATE                |                   |
|   2 |   TABLE ACCESS BY INDEX ROWID  | RECV_MEMO_APPLY   |
|   3 |    NESTED LOOPS                |                   |
|   4 |     TABLE ACCESS BY INDEX ROWID| RECEIVABLE        |
|   5 |      INDEX RANGE SCAN          | X_RECEIVABLE_3    |
|   6 |     INDEX RANGE SCAN           | X_RECV_MEMO_APP_1 |
------------------------------------------------------------

Next, we will create a stored outline that explicitly specifies not to use the X_RECEIVABLE_3 index:

CREATE OR REPLACE PRIVATE OUTLINE P_RECEIVABLE_TEMP ON
select /*+ NO_INDEX(I X_RECEIVABLE_3) */ sum(a.apply_amount)
from RECV_MEMO_APPLY a, RECEIVABLE i
where a.inv_invoice_id = :1          
and a.apply_date <= :2             
and a.inv_invoice_id = i.invoice_id
and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :3                   and ENTITY_ID = :4;

Let’s view the hints generated by the optimizer when it created the outline:

SELECT
  HINT#,
  HINT_TEXT
FROM
  OL$HINTS
WHERE
  OL_NAME='P_RECEIVABLE_TEMP';

HINT#  HINT_TEXT
    1  USE_NL(@"SEL$1" "A"@"SEL$1")
    2  LEADING(@"SEL$1" "I"@"SEL$1" "A"@"SEL$1")
    3  INDEX(@"SEL$1" "A"@"SEL$1" ("RECV_MEMO_APPLY"."INV_INVOICE_ID" "RECV_MEMO_APPLY"."MEMO_INVOICE_ID"))
    4  INDEX(@"SEL$1" "I"@"SEL$1" ("RECEIVABLE"."INVOICE_ID"))
    5  OUTLINE_LEAF(@"SEL$1")
    6  ALL_ROWS
    7  OPTIMIZER_FEATURES_ENABLE('10.2.0.2')
    8  IGNORE_OPTIM_EMBEDDED_HINTS

We can then verify that the faster execution plan was selected:

EXPLAIN PLAN FOR
select /*+ NO_INDEX(I X_RECEIVABLE_3) */ sum(a.apply_amount)
from RECV_MEMO_APPLY a, RECEIVABLE i
where a.inv_invoice_id = :1          
and a.apply_date <= :2             
and a.inv_invoice_id = i.invoice_id
and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :3                   and ENTITY_ID = :4;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY(NULL,NULL,'BASIC +NOTE'));

-----------------------------------------------------------
| Id  | Operation                     | Name              |
-----------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |
|   1 |  SORT AGGREGATE               |                   |
|   2 |   NESTED LOOPS                |                   |
|   3 |    TABLE ACCESS BY INDEX ROWID| RECEIVABLE        |
|   4 |     INDEX UNIQUE SCAN         | SYS_C0011925      |
|   5 |    TABLE ACCESS BY INDEX ROWID| RECV_MEMO_APPLY   |
|   6 |     INDEX RANGE SCAN          | X_RECV_MEMO_APP_1 |
-----------------------------------------------------------

Next is the potentially dangerous part – refer to Metalink Notes:604022.1, 726802.1, 730062.1, 144194.1, 728647.1, 5893396.8, as well as http://www.jlcomp.demon.co.uk/04_outlines.rtf

We delete the outline hints from the outline with the slow execution plan (the one with the INDEX(I X_RECEIVABLE_3) hint in this case):

DELETE FROM
  OL$HINTS
WHERE
  OL_NAME='P_RECEIVABLE1';

Then we copy the hints from the outline for the fast execution plan (with our NO_INDEX hint):

INSERT INTO
  OL$HINTS
SELECT
  'P_RECEIVABLE1',
  HINT#,
  CATEGORY,
  HINT_TYPE,
  HINT_TEXT,
  STAGE#,
  NODE#,
  TABLE_NAME,
  TABLE_TIN,
  TABLE_POS,
  REF_ID,
  USER_TABLE_NAME,
  COST,
  CARDINALITY,
  BYTES,
  HINT_TEXTOFF,
  HINT_TEXTLEN,
  JOIN_PRED,
  SPARE1,
  SPARE2,
  HINT_STRING
FROM
  OL$HINTS
WHERE
  OL_NAME='P_RECEIVABLE_TEMP';

COMMIT;

Then we instruct Oracle to refresh the private outline:

EXEC DBMS_OUTLN_EDIT.REFRESH_PRIVATE_OUTLINE('P_RECEIVABLE1')

Now, let’s try generating the plan for the original query again (with the forced/hinted X_RECEIVABLE_3 index usage):

EXPLAIN PLAN FOR
select /*+ INDEX(I X_RECEIVABLE_3) */ sum(a.apply_amount)
from RECV_MEMO_APPLY a, RECEIVABLE i
where a.inv_invoice_id = :1          
and a.apply_date <= :2             
and a.inv_invoice_id = i.invoice_id
and i.status != 'X'
and i.total_amount != 0 and i.recv_gl_acct_id = :3                   and ENTITY_ID = :4;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY(NULL,NULL,'BASIC +NOTE'));

-----------------------------------------------------------
| Id  | Operation                     | Name              |
-----------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |
|   1 |  SORT AGGREGATE               |                   |
|   2 |   NESTED LOOPS                |                   |
|   3 |    TABLE ACCESS BY INDEX ROWID| RECEIVABLE        |
|   4 |     INDEX UNIQUE SCAN         | SYS_C0011925      |
|   5 |    TABLE ACCESS BY INDEX ROWID| RECV_MEMO_APPLY   |
|   6 |     INDEX RANGE SCAN          | X_RECV_MEMO_APP_1 |
-----------------------------------------------------------

Note that even though we hinted/forced Oracle to use the X_RECEIVABLE_3 index, it now selected to use the primary key index SYS_C0011925 due to the hacked private outline.  Oracle IGNORED MY HINT (actually, it did exactly as the outline instructed).

Now, let’s make the outline a bit more permanent, converting it from a private outline to a public outline:

CREATE PUBLIC OUTLINE PP_RECEIVABLE1 FROM PRIVATE P_RECEIVABLE1;
ALTER SYSTEM SET USE_STORED_OUTLINES=TRUE;
DROP PRIVATE OUTLINE P_RECEIVABLE1;
DROP PRIVATE OUTLINE P_RECEIVABLE_TEMP;

If we then generate a DBMS_XPLAN for the original query (in my example, the one with the forced index hint), we see the following:

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE               |                   |      1 |      1 |      1 |00:00:00.01 |       5 |
|   2 |   NESTED LOOPS                |                   |      1 |      1 |      0 |00:00:00.01 |       5 |
|*  3 |    TABLE ACCESS BY INDEX ROWID| RECEIVABLE        |      1 |      1 |      1 |00:00:00.01 |       3 |
|*  4 |     INDEX UNIQUE SCAN         | SYS_C0011925      |      1 |      1 |      1 |00:00:00.01 |       2 |
|*  5 |    TABLE ACCESS BY INDEX ROWID| RECV_MEMO_APPLY   |      1 |      1 |      0 |00:00:00.01 |       2 |
|*  6 |     INDEX RANGE SCAN          | X_RECV_MEMO_APP_1 |      1 |      1 |      0 |00:00:00.01 |       2 |
-------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(("I"."STATUS"<>'X' AND "I"."TOTAL_AMOUNT"<>0 AND "I"."RECV_GL_ACCT_ID"=:3 AND
              "ENTITY_ID"=:4))
   4 - access("I"."INVOICE_ID"=:1)
   5 - filter("A"."APPLY_DATE"<=:2)
   6 - access("A"."INV_INVOICE_ID"=:1)

Note
-----
   - outline "PP_RECEIVABLE1" used for this statement

But there is a catch.  The USE_STORED_OUTLINES parameter cannot be set in the init.ora or spfile, so we need a STARTUP trigger to set the parameter:

CREATE OR REPLACE TRIGGER ENABLE_OUTLINES_TRIG AFTER STARTUP ON DATABASE
BEGIN
  EXECUTE IMMEDIATE('ALTER SYSTEM SET USE_STORED_OUTLINES=TRUE');
END;

 
After implementing the stored outlines there is a new top SQL statement in the 10046 trace profile file.  But, at some point we have to stop (before the effects of compulsive tuning disorder are achieved). 

My original idea for hacking the stored outlines came from the book “Troubleshooting Oracle Performance”. 

Note that hacking stored outlines should not be the first step.  Instead, see if it is possible to modify optimizer parameters at the session level first to achieve the desired execution plan.  Once the desired execution plan is achieved, create the stored outline to freeze the execution plan.


Actions

Information

One response

2 01 2010
Blogroll Report 11/12/2009-18/12/2009 « Coskan’s Approach to Oracle

[...] 28-How to tune by hacking stored outlines ? Charles Hooper-Tracking Performance Problems – Inserting a Hint into SQL in a Compiled Program [...]

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 140 other followers

%d bloggers like this: