Poor performance after enabling db links

Unknown

I am going to remove the hints today. The ETL process will run again overnight. Once it finishes, I'll get a look at the execution plan and post it.

I suggest you do a full code review of those ETL processes and make sure they are FULLY INSTRUMENTED to log each step executed using a custom logging packaged based on autonomous procedures.

At a minimum you should be logging, for EVERY STEP of a batch process: start time, end time, number of rows affected.

In addition it is common practice to log parameter or bind values for key queries.

Are you currently doing such logging?

See my prototype code in this old thread

How to get a called procedure/function name within package?

Charles M

Unfortunately the hints were still in place during last night's run, so we got the same execution plan it looks like. I am working with Oracle to make sure they get disabled.

Charles M

Hi rp0428,

The ODI tool does have its own logging features. There are database tables that store various logging data, as well as front-end statistics of each execution. For example, here a clip of some of the steps in the GUI:

Regards,

Charles

AndrewSayer

Charles M wrote:Unfortunately the hints were still in place during last night's run, so we got the same execution plan it looks like. I am working with Oracle to make sure they get disabled.

Do you have a testing environment where you can try it out in a controlled way manually? Being able to run it in your testing environment allows you to identify all the tweaks that need doing before it's fully ready to run in production.

It is risky to make changes to your production code (which is what you'd be doing) without testing it first. Whilst I might be confident you won't be making it any worse, there is always the possibility that something else is going on.

Charles M

Hi Andrew,

We do have non-production instances. We have been working in those environments prior to making any production changes. We're still trying to understand why the hints were not removed.

Regards,

Charles

Charles M

Ok, the hints were removed this time (except for the "anti-join" ... as this was not mentioned specifically in the note). It looks like there was much better performance this time:

SQL_ID  9ka5c4ga6w85q, child number 0
-------------------------------------
SELECT "C1_INTEGRATION_ID","C2_SRC_EFF_FROM_DT" FROM
"APPS"."C$_735216750_4_0" "C$_735216750_4_0"Plan hash value: 2342579954----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time    |
----------------------------------------------------------------------------------------------------------------------------
|  0 | SELECT STATEMENT                  |                              |      |      |      |  548K(100)|          |
|  1 |  VIEW                              |                              |  1943K|  226M|      |  548K  (1)| 01:40:34 |
|  2 |  UNION-ALL                        |                              |      |      |      |            |          |
|  3 |    SORT GROUP BY                  |                              |  1942K|  151M|  202M| 39677  (1)| 00:07:17 |
|*  4 |    HASH JOIN                      |                              |  1942K|  151M|  2176K|  1853  (8)| 00:00:21 |
|*  5 |      TABLE ACCESS FULL            | FND_FLEX_VALUES              | 65490 |  1407K|      |  786  (2)| 00:00:09 |
|*  6 |      TABLE ACCESS FULL            | FND_FLEX_VALUE_NORM_HIERARCHY | 81690 |  4786K|      |  523  (1)| 00:00:06 |
|  7 |    SORT GROUP BY                  |                              |  817 | 35948 |  5160K|  508K  (1)| 01:33:18 |
|*  8 |    FILTER                        |                              |      |      |      |            |          |
|*  9 |      TABLE ACCESS FULL            | FND_FLEX_VALUE_NORM_HIERARCHY | 81690 |  3510K|      |  522  (1)| 00:00:06 |
|  10 |      NESTED LOOPS                  |                              |    1 |    86 |      |  167  (0)| 00:00:02 |
|  11 |      NESTED LOOPS                |                              |    1 |    59 |      |    6  (0)| 00:00:01 |
|  12 |        NESTED LOOPS                |                              |    1 |    45 |      |    5  (0)| 00:00:01 |
|  13 |        TABLE ACCESS BY INDEX ROWID| FND_FLEX_VALUE_SETS          |    1 |    17 |      |    2  (0)| 00:00:01 |
|* 14 |          INDEX UNIQUE SCAN        | FND_FLEX_VALUE_SETS_U1        |    1 |      |      |    1  (0)| 00:00:01 |
|* 15 |        TABLE ACCESS BY INDEX ROWID| FND_FLEX_VALUES              |    1 |    28 |      |    3  (0)| 00:00:01 |
|* 16 |          INDEX RANGE SCAN          | FND_FLEX_VALUES_N1            |    1 |      |      |    2  (0)| 00:00:01 |
|* 17 |        INDEX UNIQUE SCAN          | FND_FLEX_VALUES_TL_U1        |    1 |    14 |      |    1  (0)| 00:00:01 |
|* 18 |      INDEX RANGE SCAN            | FND_FLEX_VALUE_NORM_HIER_U1  |    58 |  1566 |      |  161  (0)| 00:00:02 |
----------------------------------------------------------------------------------------------------------------------------Predicate Information (identified by operation id):
---------------------------------------------------  4 - access("FLEX_VALUE_SET_ID"="FLEX_VALUE_SET_ID")
      filter(("FLEX_VALUE">="CHILD_FLEX_VALUE_LOW" AND "FLEX_VALUE"<="CHILD_FLEX_VALUE_HIGH" AND
              (("SUMMARY_FLAG"='Y' AND "RANGE_ATTRIBUTE"='P') OR ("SUMMARY_FLAG"='N' AND "RANGE_ATTRIBUTE"='C'))))
  5 - filter((INTERNAL_FUNCTION("SUMMARY_FLAG") AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1'))
  6 - filter((INTERNAL_FUNCTION("RANGE_ATTRIBUTE") AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1'))
  8 - filter( IS NULL)
  9 - filter(NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1')
  14 - access("FLEX_VALUE_SET_ID"=:B1 AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1')
  15 - filter((INTERNAL_FUNCTION("SUMMARY_FLAG") AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1'))
  16 - access("FLEX_VALUE_SET_ID"="FLEX_VALUE_SET_ID" AND "FLEX_VALUE"=:B1)
      filter("FLEX_VALUE_SET_ID"=:B1)
  17 - access("FLEX_VALUE_ID"="FLEX_VALUE_ID" AND "LANGUAGE"=USERENV('LANG') AND
              NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1')
  18 - access("FLEX_VALUE_SET_ID"=:B1 AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1')
      filter((INTERNAL_FUNCTION("RANGE_ATTRIBUTE") AND NVL("ZD_EDITION_NAME",'ORA$BASE')='SET1' AND
              "FLEX_VALUE_SET_ID"="FLEX_VALUE_SET_ID" AND (("FORMAT_TYPE"='N' AND
              "FND_NUMBER"."CANONICAL_TO_NUMBER"("FLEX_VALUE")>="FND_NUMBER"."CANONICAL_TO_NUMBER"("CHILD_FLEX_VALUE_LOW") AND
              "FND_NUMBER"."CANONICAL_TO_NUMBER"("FLEX_VALUE")<="FND_NUMBER"."CANONICAL_TO_NUMBER"("CHILD_FLEX_VALUE_HIGH")) OR
              (INTERNAL_FUNCTION("FORMAT_TYPE") AND TO_DATE("FLEX_VALUE",DECODE("MAXIMUM_SIZE",5,'HH24:MI',8,'HH24:MI:SS',9,'DD-MO
              N-RR',11,'DD-MON-YYYY',15,'DD-MON-RR HH24:MI',17,'DD-MON-YYYY HH24:MI',18,'DD-MON-RR HH24:MI:SS',20,'DD-MON-YYYY
              HH24:MI:SS'))>=TO_DATE("CHILD_FLEX_VALUE_LOW",DECODE("MAXIMUM_SIZE",5,'HH24:MI',8,'HH24:MI:SS',9,'DD-MON-RR',11,'DD-
              MON-YYYY',15,'DD-MON-RR HH24:MI',17,'DD-MON-YYYY HH24:MI',18,'DD-MON-RR HH24:MI:SS',20,'DD-MON-YYYY HH24:MI:SS'))
              AND TO_DATE("FLEX_VALUE",DECODE("MAXIMUM_SIZE",5,'HH24:MI',8,'HH24:MI:SS',9,'DD-MON-RR',11,'DD-MON-YYYY',15,'DD-MON-
              RR HH24:MI',17,'DD-MON-YYYY HH24:MI',18,'DD-MON-RR HH24:MI:SS',20,'DD-MON-YYYY
              HH24:MI:SS'))<=TO_DATE("CHILD_FLEX_VALUE_HIGH",DECODE("MAXIMUM_SIZE",5,'HH24:MI',8,'HH24:MI:SS',9,'DD-MON-RR',11,'DD
              -MON-YYYY',15,'DD-MON-RR HH24:MI',17,'DD-MON-YYYY HH24:MI',18,'DD-MON-RR HH24:MI:SS',20,'DD-MON-YYYY HH24:MI:SS')))
              OR ("FORMAT_TYPE"<>'N' AND "FORMAT_TYPE"<>'D' AND "FORMAT_TYPE"<>'T' AND "FLEX_VALUE">="CHILD_FLEX_VALUE_LOW" AND
              "FLEX_VALUE"<="CHILD_FLEX_VALUE_HIGH")) AND (("SUMMARY_FLAG"='Y' AND "RANGE_ATTRIBUTE"='P') OR ("SUMMARY_FLAG"='N'
              AND "RANGE_ATTRIBUTE"='C'))))64 rows selected.

All-in-all (start-to-finish ... select, insert, etc.) the task took about 12 minutes. Much better than 2 hours + ...

Regards,

Charles

Unknown

Ok, the hints were removed this time (except for the "anti-join" ... as this was not mentioned specifically in the note). It looks like there was much better performance this time:

Ok - but why does that plan show almost 2 million rows while the first one you posted only shows 25k.

Something else must be different.

jgarry

Yes, rp0428 has a point.  You could have a situation where having more data pokes at the optimizer to use a better plan.  You probably need to use some kind of plan stability, taking into account the variance of input.  It's possible that removing hints allows the optimizer to properly use statistics it already knows about, but it's also possible you are setting up for a future "why did this become slow again?"

You probably want to google up on adaptive cursor sharing and histograms too.

AndrewSayer

Whilst what rp0428 said is probably relevent, you are no longer nested looping to a full tablescan because it couldnt merge your views.

I say that executed a MUCH better plan.

-edit

Now I can see those were just estimate cardinalities being compared to estimate cardinalities. I have a lot of confidence that you’d only do that same bulky hash join at the top part with more rows, so it’s not going to change with higher volume. It will perform a million times better than the nested loops version.

As for the anti join part, I’ll take a closer look later when my thumbs aren’t about to fall off, but clearly this was a leap in the right direction.

Charles M

Thanks for the update/edit Andrew. Sorry to be have been away on this recently, we have had some other activities taking up our time.

I should be able to reply, more thoroughly, to this and the previous posts as well.

Thanks again for everyone's attention on this ... it has been a big win for us getting the timing down. It has held steady since the hints were taken away.

Charles