tuning question

[Laurel]

Hi Erman!
Any advice on that ?

 SELECT SUM(NVL(AEL.ACCOUNTED_DR,0.0) - NVL(AEL.ACCOUNTED_CR,0.0) )
FROM PAYMENT_LINES AEL,PAYMENT_HEADERS AEH
WHERE AEL.AE_HEADER_ID = AEH.AE_HEADER_ID AND (:b1 IS NULL OR AEH.ACCOUNTING_DATE >= FND_DATE.CANONICAL_TO_DATE(:b1) ) AND (:b3 IS NULL OR AEH.ACCOUNTING_DATE <= FND_DATE.CANONICAL_TO_DATE(:b3) ) AND AEL.AE_LINE_TYPE_CODE IN ( 'LIABILITY','PREPAY' ) AND AEL.THIRD_PARTY_ID = :b5;

PAYMENT_LINES - 5,5 mln rows

PAYMENT_HEADERS 1,5 mnl rows

select count (*) PAYMENT_LINES AEL from AEL.AE_LINE_TYPE_CODE IN ( 'LIABILITY','PREPAY' ) ;

2,5 mnl rows

PAYMENT_LINES_N4 index is on ( THIRD_PARTY_D,THIRD_PARTY_SUB_ID);

PAYMENT_HEADERS_U1 index is unique on  PAYMENT_HEADERS(AE_HEADER_ID)

When executing this it , it goes very fast   1631 execution times using the SAME execution plan:

| Id  | Operation                     | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |     1 |    50 |   186   (0)| 00:00:03 |
|   1 |  SORT AGGREGATE               |                   |     1 |    50 |            |          |
|   2 |   NESTED LOOPS                |                   |     4 |   200 |   186   (0)| 00:00:03 |
|*  3 |    TABLE ACCESS BY INDEX ROWID| PAYMENT_LINES_ALL   |     4 |   128 |   178   (0)| 00:00:03 |
|*  4 |     INDEX RANGE SCAN          | PAYMENT_LINES_N4    |   876 |       |     5   (0)| 00:00:01 |
|*  5 |    TABLE ACCESS BY INDEX ROWID| PAYMENT_HEADERS_ALL |     1 |    18 |     2   (0)| 00:00:01 |
|*  6 |     INDEX UNIQUE SCAN         | PAYMENT_HEADERS_U1  |     1 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

But then it drastically slows down ...But the execution plan is the same

from average time from 0.314 to max 34.86  per execution and at the same time increased logical io..

 SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ --------------
    134902      1 25-OCT-18 11.30.07.363 PM      gdbbry6ffwmtt      1134951010        1,631         .314       11,989.6
    134903      1 26-OCT-18 12.00.32.036 AM      gdbbry6ffwmtt                           63       28.267      483,428.3
    134904      1 26-OCT-18 12.30.56.668 AM      gdbbry6ffwmtt                           77       22.435      486,315.5
    134905      1 26-OCT-18 01.00.27.323 AM      gdbbry6ffwmtt                           51       34.864      483,535.9
    134906      1 26-OCT-18 01.30.51.950 AM      gdbbry6ffwmtt                           77       22.437      484,825.3
    134907      1 26-OCT-18 02.00.19.564 AM      gdbbry6ffwmtt                           57       31.226      492,802.6
    134908      1 26-OCT-18 02.30.44.207 AM      gdbbry6ffwmtt                           79       21.756      487,045.1
    134909      1 26-OCT-18 03.00.02.823 AM      gdbbry6ffwmtt                           75       23.828      481,076.8
    134910      1 26-OCT-18 03.30.36.411 AM      gdbbry6ffwmtt                           82       20.983      491,630.9
    134911      1 26-OCT-18 04.00.01.126 AM      gdbbry6ffwmtt                           78       22.814      484,869.8
    134912      1 26-OCT-18 04.30.22.693 AM      gdbbry6ffwmtt                           84       21.233      486,296.2
    134913      1 26-OCT-18 05.00.50.261 AM      gdbbry6ffwmtt                          106       10.808      238,767.7

 

Any advice here what should I do ?  
I tried to rebuild indexes - no help..
Also its 10.2.0.3 release, no cardinality feedback issue..

Thx!
Br,Laurel

[ErmanArslansOracleBlog]

Hi Laurel,

1)Is the amount of data almost the same?
2)Is the first execution fast? (all the subsequent executions are slow?)
3)Are you sure that those queries were using the same execution plan?
4)What happens when you flush the shared pool and retest these slow queries?
5)send me an autotrace output.. (autotorace on)

[Laurel]

Hi Erman!
Thx as always for an answer..
This sql calles in loop in report per row .
Its feels like query performs 1631 executions and all those blocks are on memory disk as takes 0.314 sec per execution
then for the rest of data it goes to the cold disk as same execution plan but for  single execution takes 34,864 sec ..
I asked our server admin - its all on same disk and there is no more cold/hot disks as long time before...

So its weird.

1. Its the same sql running  in a loop in a report. So, always the same amount of data.
2. Same loop after 1631 executions speed drop 0,314->34
3.200% sure its the same executon plan
4. When flush, same thing
5. here is the trace file from report.

Anything comes to your mind ?report1.doc
Thx!

[ErmanArslansOracleBlog]

I think that, after a while, you encounter a resource problem.
Probably, it is about memory.
It should be about SGA (buffer cache)
Your query is doing db file sequential read. (index read)
It spends its time on fetching.


Did you check ASH and/or AWR during the execution of these slow queries?
Do you see buffer waits? What do you see exactly?

[Laurel]

Hi Erman!
Thx again!
Here is 30 min report when its running and when IO is slow.
User IO wait and db sequential read..
Maybe you see something that explains why the IO drops so much..
I checked we dont have RMAN or some hard IO scheduled at the same time


Thx!awr_report_134902_1349032.html

[ErmanArslansOracleBlog]

Your I/O is fast actually.
You wait for buffers.
So you do work.. You do I/O.. You do buffer Gets.

Your SGA seems to small? Can you retry after setting it to a higher value?