Application vs. hard-run, very different!

[Cookies]

Well, here is our problem.
Now I need to figure out why it is a problem.
The first is from the application. The second I ran as a hard-run. WHY ARE THEY SO DIFFERENT?

Both on same DB environment.

AS you see the first is a cartesian product, but that still does not justify the time involved with query. If they are the same, why are the results so different?

SELECT /* ReadingsDataAccess */ mi.end_dt-(15/60)/24 AS reading_start,
mi.usage_nbr AS usage,
arp.rate_period_type_cd AS rpt
FROM meter_interval mi, account_device ad, account_rate_period arp
WHERE mi.org_id = :1 AND
mi.device_id=ad.device_id AND
ad.org_id = :2 AND
ad.cust_id = :3 AND
ad.svc_type_cd = :4 AND
ad.prem_seq_nbr = :5 AND
mi.org_id = arp.org_id AND
arp.org_id = ad.org_id AND
arp.cust_id = ad.cust_id AND
arp.svc_type_cd = ad.svc_type_cd AND
arp.prem_seq_nbr = ad.prem_seq_nbr AND
arp.rate_plan_cd = :6 AND
arp.usage_qty IS NOT NULL AND
(mi.end_dt -(15/60)/24) >= arp.start_dt AND
(mi.end_dt -(15/60)/24) < arp.end_dt AND
mi.end_dt > :7 AND
mi.end_dt <= :8 AND
mi.end_dt <= arp.end_dt

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.04       0.06          0          0          0           0
Fetch       33     28.26      32.84          0      33951          0         308
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       41     28.30      32.91          0      33951          0         308


Rows     Row Source Operation
-------  ---------------------------------------------------
     96  FILTER  (cr=8491 r=0 w=0 time=7195646 us)
     96   NESTED LOOPS  (cr=8491 r=0 w=0 time=7195355 us)
    284    MERGE JOIN CARTESIAN (cr=9 r=0 w=0 time=16508 us)
    284     INDEX RANGE SCAN AC_RPRD_TYPCD_IX (cr=8 r=0 w=0 time=4495 us)(object id 144472)
    284     BUFFER SORT (cr=1 r=0 w=0 time=7004 us)
      1      INDEX RANGE SCAN ACC_DEV_ACC_DEV_PK (cr=1 r=0 w=0 time=56 us)(object id 144043)
     96    INDEX RANGE SCAN MTRINT_USAGE_NBR_IX (cr=8482 r=0 w=0 time=7171041 us)(object id 144257
) 

BUT, when I run it through sql-plus on prod_copy I get the below.
Why would it be so different?

Is there any way to see the variables getting thrown in?
That is the only thing I can think of that we do not know about.

********************************************************************************

SELECT /* ReadingsDataAccess */ mi.end_dt-(15/60)/24 AS reading_start,
mi.usage_nbr AS USAGE,
arp.rate_period_type_cd AS rpt
FROM METER_INTERVAL mi, ACCOUNT_DEVICE ad, ACCOUNT_RATE_PERIOD arp
WHERE mi.org_id = '4' AND
mi.device_id=ad.device_id AND
ad.org_id = '4' AND
ad.cust_id = '1033' AND
ad.svc_type_cd = 'E' AND
ad.prem_seq_nbr = 1 AND
mi.org_id = arp.org_id AND
arp.org_id = ad.org_id AND
arp.cust_id = ad.cust_id AND
arp.svc_type_cd = ad.svc_type_cd AND
arp.prem_seq_nbr = ad.prem_seq_nbr AND
arp.rate_plan_cd = 'Residential TOU' AND
arp.usage_qty IS NOT NULL AND
(mi.end_dt -(15/60)/24) >= arp.start_dt AND
(mi.end_dt -(15/60)/24) < arp.end_dt AND
mi.end_dt > SYSDATE-2 AND
mi.end_dt <= SYSDATE-1 AND
mi.end_dt <= arp.end_dt

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.04       0.03          0          0          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch      196      0.09       0.06          0        344          0         384
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      204      0.13       0.10          0        344          0         384

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 45

Rows     Row Source Operation
-------  ---------------------------------------------------
     96  FILTER  (cr=86 r=0 w=0 time=12770 us)
     96   NESTED LOOPS  (cr=86 r=0 w=0 time=12292 us)
      9    NESTED LOOPS  (cr=16 r=0 w=0 time=2223 us)
      9     INDEX RANGE SCAN AC_RPRD_TYPCD_IX (cr=8 r=0 w=0 time=1561 us)(object id 144472)
      9     INDEX RANGE SCAN ACC_DEV_ACC_DEV_PK (cr=8 r=0 w=0 time=461 us)(object id 144043)
     96    INDEX RANGE SCAN MTRINT_USAGE_NBR_IX (cr=70 r=0 w=0 time=9389 us)(object id 144257) 

[DaPi]

Interesting problem, and surprisingly no comments in 24 hours. So I'll stick my neck out.

I guess that part of the reason is:
- when parsing (e.g.) "where mi.org_id = :1" the CBO can't know how selective that will be and must be prepared to handle a 'big' result set.
- when parsing (e.g.) "where mi.org_id = '4'" it may have some idea of the size of the result set (i.e. 0.1% or 98% of the table) and may know that it will be small (though I think it will need histograms to know that? do your analyze's have them?).

Interestingly the same indexes are used each time - could you please post their definition to sustain further cogitation?

I have seen intermediate Cartesian Joins like this, but never with any performance impact big enough to make it worth my while pursuing the problem.

[sysdba]

Looks like the data is not same:
The first returns 308 rows, while the 2nd returns 384.
Different data set causes different execution plan.
Think about this example:

select * from emp where deptno = :1;
and
select * from emp where deptno = 10;

Do you expect the same results?

Depends.

[KenEwald]

I almost stuck my neck out yesterday, but I wanted to talk to some of the other DBA's around here first.

I think we all learned something very valuable .. never rely on an explain plan with bind variables if the database is using the cost based optimizer.

The values ARE evaluated by the cost based optimizer and depending on cardinality, nulls, etc. could pick up a different execution plan.

Nothing you didn't already get from those who stuck their necks out.

Thank you for posting this very good question.

[chrisrlong]

The point, more correctly, is never to compare a statement with binds against one with hard-coded values. They are apples and oranges. With hard-coded values, the optimizer has much more information with which to make a better decision.

- Chris

[KenEwald]

Why did the chicken cross the road? Cause all the other's didn't get run over in the process.

Way to go DaPi!

Here's some more stuff to think about ... fwiw

From Shelly:

... if the index has bad selectivity it could be ignored by the cost based optimizer. Another side effect is that the explain plan behaviour will treat bind parameters as having char type. You could isolate type conversion size effect including explicit conversion function such as to_date and to_number in sql statement.

[DaPi]

Originally posted by chrisrlong
. . . never to compare a statement with binds against one with hard-coded values.

Well yes and no . . .

We want to use bind variables (to save parsing) BUT want performance based on all available knowledge (like the fixed value performance). The comparison here is valid - it prompts the question "how do I force the execution plan with bind variables to be that used with fixed values?" The answer is hints or stored outlines (though I'm not sure how in this case! ).

"From Shelly:
... if the index has bad selectivity it could be ignored by the cost based optimizer . . ."
Interestingly the same indexes are used in each case . . . .

[TimHall]

Hi.

What has been said so far isn't completely true. The CBO will 'peek' at the value of the bind variable to optimize the plan during the first hard parse. Subsequent soft parses will not peek at the value. This means that the parse of a literal or a bind variable with the same value should result in the same hard parse. See:

http://asktom.oracle.com/pls/ask/f?p...0265835652030,

Cheers

[DaPi]

Thanks for the link Tim. But I note "peeking" started in 9i - some of us only just said goodbye to 7.3.4!

Cookies - which version are you running?

[Cookies]

I am running 9.0.2
Look at the difference in time from one to the other.
totally different!
Why the hell would it do that?

Also, I have run this query by setting my own bind-variables
outside the application and it ran great. It has something
to do with going through the app somehow ... Have no idea ...

I even totally rewrote the query with the same results.

Here is more food for thought:

FIRST WITH BIND VARIABLES FROM THE APPLICATION

SELECT /* ReadingsDataAccess */  
/*+ index (mi MTRINT_USAGE_NBR_IX) index (arp AC_RPRD_TYPCD_IX) index (ad ACC_DEV_ACC_DEV_PK) */ 
mi.end_dt-(15/60)/24 AS reading_start,
mi.usage_nbr AS usage,
arp.rate_period_type_cd AS rpt
FROM account_device ad, account_rate_period arp, meter_interval mi
WHERE
ad.org_id = :1 AND
ad.cust_id = :2 AND
ad.svc_type_cd = :3 AND
ad.prem_seq_nbr = :4 AND
arp.org_id = ad.org_id AND
arp.cust_id = ad.cust_id AND
arp.svc_type_cd = ad.svc_type_cd AND
arp.prem_seq_nbr = ad.prem_seq_nbr AND
arp.rate_plan_cd = :5 AND
arp.usage_qty IS NOT NULL AND
mi.org_id = :6 AND
mi.device_id=ad.device_id AND
mi.org_id = arp.org_id AND
(mi.end_dt -(15/60)/24) >= arp.start_dt AND
(mi.end_dt -(15/60)/24) < arp.end_dt AND
mi.end_dt > :7 AND
mi.end_dt <= :8 AND
mi.end_dt <= arp.end_dt

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       10      7.87       7.73          0      10051          0          96
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      7.87       7.73          0      10051          0          96

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 56  (TEST4)

Rows     Row Source Operation
-------  ---------------------------------------------------
     96  FILTER  (cr=10051 r=0 w=0 time=7736664 us)
     96   NESTED LOOPS  (cr=10051 r=0 w=0 time=7736366 us)
    299    MERGE JOIN CARTESIAN (cr=69 r=0 w=0 time=24785 us)
    299     TABLE ACCESS BY INDEX ROWID ACCOUNT_RATE_PERIOD (cr=68 r=0 w=0 time=12369 us)
    305      INDEX RANGE SCAN AC_RPRD_TYPCD_IX (cr=8 r=0 w=0 time=4019 us)(object id 147521)
    299     BUFFER SORT (cr=1 r=0 w=0 time=6969 us)
      1      INDEX RANGE SCAN ACC_DEV_ACC_DEV_PK (cr=1 r=0 w=0 time=59 us)(object id 147517)
     96    INDEX RANGE SCAN MTRINT_USAGE_NBR_IX (cr=9982 r=0 w=0 time=7704205 us)(object id 147732)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
     96   FILTER
     96    TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
               'ACCOUNT_RATE_PERIOD'
    299     NESTED LOOPS
    299      NESTED LOOPS
    305       INDEX (RANGE SCAN) OF 'ACC_DEV_ACC_DEV_PK' (UNIQUE)
    299       INDEX (RANGE SCAN) OF 'MTRINT_USAGE_NBR_IX' (NON-UNIQUE)

      1      INDEX (RANGE SCAN) OF 'AC_RPRD_TYPCD_IX' (NON-UNIQUE) 

NEXT I RAN IT HARD-CODED:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       49      0.06       0.02          0        105          0          96
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       51      0.08       0.03          0        105          0          96

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 56  (TEST4)

Rows     Row Source Operation
-------  ---------------------------------------------------
     96  FILTER  (cr=105 r=0 w=0 time=17057 us)
     96   NESTED LOOPS  (cr=105 r=0 w=0 time=16602 us)
     16    MERGE JOIN CARTESIAN (cr=19 r=0 w=0 time=2492 us)
     16     TABLE ACCESS BY INDEX ROWID ACCOUNT_RATE_PERIOD (cr=18 r=0 w=0 time=1747 us)
     20      INDEX RANGE SCAN AC_RPRD_TYPCD_IX (cr=9 r=0 w=0 time=1333 us)(object id 147521)
     16     BUFFER SORT (cr=1 r=0 w=0 time=360 us)
      1      INDEX RANGE SCAN ACC_DEV_ACC_DEV_PK (cr=1 r=0 w=0 time=53 us)(object id 147517)
     96    INDEX RANGE SCAN MTRINT_USAGE_NBR_IX (cr=86 r=0 w=0 time=13346 us)(object id 147732)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
     96   FILTER
     96    TABLE ACCESS   GOAL: ANALYZED (BY INDEX ROWID) OF
               'ACCOUNT_RATE_PERIOD'
     16     NESTED LOOPS
     16      NESTED LOOPS
     20       INDEX (RANGE SCAN) OF 'ACC_DEV_ACC_DEV_PK' (UNIQUE)
     16       INDEX (RANGE SCAN) OF 'MTRINT_USAGE_NBR_IX' (NON-UNIQUE)

      1      INDEX (RANGE SCAN) OF 'AC_RPRD_TYPCD_IX' (NON-UNIQUE)