Record Print Status Too Slow, Sql#1

Poor performing Sql #1

(This sql was formatted for readability)

INSERT
INTO AP_INVOICE_RELATIONSHIPS
  (
    ORIGINAL_INVOICE_ID
  , RELATED_INVOICE_ID
  , CREATED_BY
  , CREATION_DATE
  , ORIGINAL_PAYMENT_NUM
  , LAST_UPDATED_BY
  , LAST_UPDATE_DATE
  , CHECKRUN_NAME
  )
SELECT ORIG.INVOICE_ID
, NEW.INVOICE_ID
, :B4
, SYSDATE
, NEW.ORIGINAL_PAYMENT_NUM
, :B4
, SYSDATE
, :B1
FROM AP_INVOICES_ALL ORIG
, AP_SELECTED_INVOICES_ALL NEW
, IBY_FD_PAYMENTS_V IBYPMTS
, IBY_FD_DOCS_PAYABLE_V IBYDOCS
WHERE IBYDOCS.CALLING_APP_DOC_UNIQUE_REF1 = TO_CHAR(NEW.CHECKRUN_ID)
AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF2   = TO_CHAR(NEW.INVOICE_ID)
AND IBYPMTS.ORG_TYPE                      = 'OPERATING_UNIT'
AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF3   = TO_CHAR(NEW.PAYMENT_NUM)
AND IBYPMTS.PAYMENT_ID                    = IBYDOCS.PAYMENT_ID
AND IBYPMTS.COMPLETED_PMTS_GROUP_ID       = :B3
AND IBYPMTS.ORG_ID                        = :B2
AND NEW.ORIGINAL_INVOICE_ID               = ORIG.INVOICE_ID
AND NEW.CHECKRUN_NAME                     = :B1 ; 

This sql was using following plan

Plan hash value: 2909465723

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                 |                          |       |       |   934 (100)|          |
|   1 |  LOAD TABLE CONVENTIONAL         |                          |       |       |            |          |
|   2 |   NESTED LOOPS                   |                          |       |       |            |          |
|   3 |    NESTED LOOPS                  |                          |     1 |   103 |   934   (1)| 00:00:12 |
|   4 |     MERGE JOIN CARTESIAN         |                          |   168 | 13608 |   242   (0)| 00:00:03 |
|   5 |      NESTED LOOPS                |                          |     1 |    55 |     6   (0)| 00:00:01 |
|*  6 |       TABLE ACCESS BY INDEX ROWID| AP_SELECTED_INVOICES_ALL |     1 |    49 |     5   (0)| 00:00:01 |
|*  7 |        INDEX RANGE SCAN          | AP_SELECTED_INVOICES_N5  |     1 |       |     4   (0)| 00:00:01 |
|*  8 |       INDEX UNIQUE SCAN          | AP_INVOICES_U1           |     1 |     6 |     1   (0)| 00:00:01 |
|   9 |      BUFFER SORT                 |                          |  1563 | 40638 |   241   (0)| 00:00:03 |
|  10 |       TABLE ACCESS BY INDEX ROWID| IBY_PAYMENTS_ALL         |  1563 | 40638 |   236   (0)| 00:00:03 |
|* 11 |        INDEX RANGE SCAN          | IBY_PAYMENTS_ALL_N10     |  1563 |       |    14   (0)| 00:00:01 |
|* 12 |     INDEX RANGE SCAN             | IBY_DOCS_PAYABLE_ALL_N6  |    45 |       |     2   (0)| 00:00:01 |
|* 13 |    TABLE ACCESS BY INDEX ROWID   | IBY_DOCS_PAYABLE_ALL     |     1 |    22 |    19   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------

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

   6 - filter(TO_NUMBER("ORIGINAL_INVOICE_ID") IS NOT NULL)
   7 - access("NEW"."CHECKRUN_NAME"=:B1)
   8 - access("ORIG"."INVOICE_ID"=TO_NUMBER("ORIGINAL_INVOICE_ID"))
  11 - access("IBY_PAY"."COMPLETED_PMTS_GROUP_ID"=:B3 AND "IBY_PAY"."ORG_ID"=:B2 AND
              "IBY_PAY"."ORG_TYPE"='OPERATING_UNIT')
  12 - access("IBY_PAY"."PAYMENT_ID"="IBY_DOCS"."PAYMENT_ID")
  13 - filter(("IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF1"=TO_CHAR("NEW"."CHECKRUN_ID") AND
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF2"="NEW"."SYS_NC00115$" AND
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF3"=TO_CHAR("NEW"."PAYMENT_NUM")))

Q: Why this plan is bad?

A: The merge Cartesian join is the culprit. In my case there were around 98,000 invoices. So accessing ap_selected_invoices_all on checkrun name will return 98,000 rows. since all of the invoices were paid without any error, so it had created 98,000 rows in iby_docs_payable_all table too. All these invoices had same completed_pmts_group_id value. So accessing iby_payments_all on completed_pmts_group_id and then iby_docs_payable_all on payment_id will return same 98,000 rows. This kind of join between ap_selected_invoices and iby table is not efficient. The better plan would be to access iby_docs_payable_all using following columns

1. CALLING_APP_ID
2. CALLING_APP_DOC_UNIQUE_REF1
3. CALLING_APP_DOC_UNIQUE_REF2
4. CALLING_APP_DOC_UNIQUE_REF3

And then access iby_payments_all table.

i feel there is no need to use view IBY_FD_PAYMENTS_V in this query. Completed_pmts_group_id and org_type columns are available in iby_docs_payable_all table itself. Did Oracle forget about normalization? same columns in both the table. what were they thinking?

I am not sure calling_appi_id = 200 is not added to where clause. This query is being called from AP side. if Oracle development had added this condition then Oracle optimizer might have found using index iby_docs_payable_n13 is better than doing merge join Cartesian.

So we got bad sql_text, sql_id, plan_hash_value from gv$sql. This is the sql statement without formatting

INSERT INTO AP_INVOICE_RELATIONSHIPS( ORIGINAL_INVOICE_ID, RELATED_INVOICE_ID, CREATED_BY, CREATION_DATE, ORIGINAL_PAYMENT_NUM, LAST_UPDATED_BY, LAST_UPDATE_DATE, CHECKRUN_NAME) SELECT ORIG.INVOICE_ID, NEW.INVOICE_ID, B4 , SYSDATE, NEW.ORIGINAL_PAYMENT_NUM, B4 , SYSDATE, B1 FROM AP_INVOICES_ALL ORIG, AP_SELECTED_INVOICES_ALL NEW, IBY_FD_PAYMENTS_V IBYPMTS, IBY_FD_DOCS_PAYABLE_V IBYDOCS WHERE IBYDOCS.CALLING_APP_DOC_UNIQUE_REF1 = TO_CHAR(NEW.CHECKRUN_ID) AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF2 = TO_CHAR(NEW.INVOICE_ID) AND IBYPMTS.ORG_TYPE = 'OPERATING_UNIT' AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF3 = TO_CHAR(NEW.PAYMENT_NUM) AND IBYPMTS.PAYMENT_ID = IBYDOCS.PAYMENT_ID AND IBYPMTS.COMPLETED_PMTS_GROUP_ID = B3 AND IBYPMTS.ORG_ID = B2 AND NEW.ORIGINAL_INVOICE_ID = ORIG.INVOICE_ID AND NEW.CHECKRUN_NAME = B1 ;


Using plan_hash_value and sql_id, I executed following script using a concurrent program to create sql plan. ( this script can be used from sqlplus too, I used concurrent program because I do not have permission to execute any package from sqlplus)

declare
 l_ret_value NUMBER;
 l_clob CLOB;
begin
 l_ret_value := DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE
                ( sql_id          =>'awf51xwyyanvn'
                , plan_hash_value => '2909465723'
 fnd_file.put_line(fnd_file.log,'Return Value :' || l_ret_value);                ) ;

end;
/

Check log file, if Return value is 1 then one plan is loaded otherwise there was some error while loading plan.


Run following sql to get sql_handle and plan_name. These will be needed to drop the bad plan.

select sql_handle, plan_name from dba_sql_plan_baselines a;


Then we added hint to sql statement so that execution plan is using nested loop between ap_selected_invoices_all, biy_docs_payable_all, iby_payments_all and ap_invoices_all. This was the small script to execute it from sqlplus

declare
  b1 varchar2(30) := 'SL EFT 06-APR-2012 1';
  b2 number := 81;
  b3 number := 745;
  b4 number := 1;
begin

INSERT INTO AP_INVOICE_RELATIONSHIPS( ORIGINAL_INVOICE_ID, RELATED_INVOICE_ID, CREATED_BY, CREATION_DATE, ORIGINAL_PAYMENT_NUM, LAST_UPDATED_BY, LAST_UPDATE_DATE, CHECKRUN_NAME) SELECT /*+ leading (new) use_nl (new ibydocs ibypmts orig) index_ss(ibydocs iby_docs_payable_all_n13) */ORIG.INVOICE_ID, NEW.INVOICE_ID, B4 , SYSDATE, NEW.ORIGINAL_PAYMENT_NUM, B4 , SYSDATE, B1 FROM AP_INVOICES_ALL ORIG, AP_SELECTED_INVOICES_ALL NEW, IBY_FD_PAYMENTS_V IBYPMTS, IBY_FD_DOCS_PAYABLE_V IBYDOCS WHERE IBYDOCS.CALLING_APP_DOC_UNIQUE_REF1 = TO_CHAR(NEW.CHECKRUN_ID) AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF2 = TO_CHAR(NEW.INVOICE_ID) AND IBYPMTS.ORG_TYPE = 'OPERATING_UNIT' AND IBYDOCS.CALLING_APP_DOC_UNIQUE_REF3 = TO_CHAR(NEW.PAYMENT_NUM) AND IBYPMTS.PAYMENT_ID = IBYDOCS.PAYMENT_ID AND IBYPMTS.COMPLETED_PMTS_GROUP_ID = B3 AND IBYPMTS.ORG_ID = B2 AND NEW.ORIGINAL_INVOICE_ID = ORIG.INVOICE_ID AND NEW.CHECKRUN_NAME = B1 ;

end;

Note: I had to make sure that sql statement remains same except hint part. Slight change in sql statement cause failure in DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE

Now run “select module, sql_id, plan_hash_value, a.* from gv$sql a where sql_text like 'INSERT%INTO AP_INVOICE_RELATIONSHIPS%(%' order by last_active_time desc;” to get sql_id and plan_hash_value for sql with hint.

Use those sql_id, plan_hash_value for sql with proper hint and sql_handle for bad plan and run following script

declare
 l_ret_value NUMBER;
 l_clob CLOB;
begin
 l_ret_value := DBMS_SPM.LOAD_PLANS_FROM_CURSOR_CACHE
                ( sql_id          =>'gkhvwymvww8v6'
                , plan_hash_value => '1577246184'
                , sql_handle      => 'SQL_1be05243ae2286bc' --<< pertains to  bad sql plan
                ) ;


   fnd_file.put_line(fnd_file.log,'Return Value :' || l_ret_value);
end;
/

Now drop the BAD sql plan for the query

declare
 l_ret_value NUMBER;
 l_clob CLOB;
begin
) ;

   l_ret_value := DBMS_SPM.DROP_SQL_PLAN_BASELINE
                  ( SQL_HANDLE      => 'SQL_1be05243ae2286bc'           
                  , PLAN_NAME       => 'SQL_PLAN_1rs2k8fr251pwc6fe2586' -- < pertains to bad plan
                  );

   fnd_file.put_line(fnd_file.log,'Return Value :' || l_ret_value);
end;
/ 

This is the plan that works for us

Plan hash value: 1577246184
 
-------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                 |                          |     1 |   128 |   250K  (1)| 00:50:03 |
|   1 |  LOAD TABLE CONVENTIONAL         | AP_INVOICE_RELATIONSHIPS |       |       |            |          |
|   2 |   NESTED LOOPS                   |                          |       |       |            |          |
|   3 |    NESTED LOOPS                  |                          |     1 |   128 |   250K  (1)| 00:50:03 |
|   4 |     NESTED LOOPS                 |                          |     1 |   102 |   250K  (1)| 00:50:03 |
|   5 |      NESTED LOOPS                |                          |  9382 |   879K|   240K  (1)| 00:48:11 |
|   6 |       TABLE ACCESS BY INDEX ROWID| AP_SELECTED_INVOICES_ALL | 58310 |  4213K|  7461   (1)| 00:01:30 |
|*  7 |        INDEX RANGE SCAN          | AP_SELECTED_INVOICES_N5  | 58310 |       |   473   (1)| 00:00:06 |
|   8 |       TABLE ACCESS BY INDEX ROWID| IBY_DOCS_PAYABLE_ALL     |     1 |    22 |     4   (0)| 00:00:01 |
|*  9 |        INDEX SKIP SCAN           | IBY_DOCS_PAYABLE_ALL_N13 |     1 |       |     3   (0)| 00:00:01 |
|* 10 |      INDEX UNIQUE SCAN           | AP_INVOICES_U1           |     1 |     6 |     1   (0)| 00:00:01 |
|* 11 |     INDEX UNIQUE SCAN            | IBY_PAYMENTS_ALL_U1      |     1 |       |     1   (0)| 00:00:01 |
|* 12 |    TABLE ACCESS BY INDEX ROWID   | IBY_PAYMENTS_ALL         |     1 |    26 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   7 - access("NEW"."CHECKRUN_NAME"=:B1)
   9 - access("IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF1"=TO_CHAR("NEW"."CHECKRUN_ID") AND 
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF2"=TO_CHAR("INVOICE_ID") AND 
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF3"=TO_CHAR("NEW"."PAYMENT_NUM"))
       filter("IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF1"=TO_CHAR("NEW"."CHECKRUN_ID") AND 
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF2"=TO_CHAR("INVOICE_ID") AND 
              "IBY_DOCS"."CALLING_APP_DOC_UNIQUE_REF3"=TO_CHAR("NEW"."PAYMENT_NUM"))
  10 - access("ORIG"."INVOICE_ID"=TO_NUMBER("NEW"."ORIGINAL_INVOICE_ID"))
  11 - access("IBY_PAY"."PAYMENT_ID"="IBY_DOCS"."PAYMENT_ID")
  12 - filter("IBY_PAY"."COMPLETED_PMTS_GROUP_ID"=TO_NUMBER(:B3) AND 
              "IBY_PAY"."ORG_TYPE"='OPERATING_UNIT' AND "IBY_PAY"."ORG_ID"=TO_NUMBER(:B2))

Now run "Record Print Status" to check if new plan is used or not. This query can give the sql plan used by the query.

select * from table( 
    dbms_xplan.display_sql_plan_baseline( 
        sql_handle=>'SQL_1be05243ae2286bc', 
        format=>'basic'));