OraFAQ Forum: Performance Tuning

Home » RDBMS Server » Performance Tuning » cache issue (11.2.0.2, WIndows 2008 R2)

Show: Today's Messages :: Polls :: Message Navigator
E-mail to friend

cache issue [message #620855]

Wed, 06 August 2014 12:01

sant_new1
Messages: 46
Registered: June 2014

Member

Hi friends,
We are troubleshooting several performance issues on the application, the specific test case below takes about 23 seconds in the 1st run. In reality it should only a second or more to run..
Identified one SQL that takes about 21.36 seconds from the overall elapsed 23 seconds. When the user ran the same test again on the application, it only took 1 second in the 2nd run. ThHe same sql that took 21.36 seconds in the first run took only 0.33 seconds in the second run.

I understand it is due to the buffer cache that the 2nd run was much faster but is this a normal behaviour or will tuning/analyzing the SQL improve the performance in the 1st run or when the SQL's are not in cache?

  
1st RUN: 

SELECT DISTINCT table1.id, ...................
...,0
FROM
  table1,table2,table3,table4,table5,table6
where
..............;
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.17       0.14          0         12          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.87      21.22       6360      12712          0         158
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.04      21.36       6360      12724          0         158
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 151

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                      6360        0.05         20.60
  SQL*Net message from client                     2        0.41          0.47
  SQL*Net more data to client                     4        0.00          0.00
 
2nd RUN:
 
SELECT DISTINCT table1.id, ...................
...,0
FROM
  table1,table2,table3,table4,table5,table6
where
..............;
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.10       0.12          0         12          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.15       0.20         11      13125          0         158
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.26       0.33         11      13137          0         158
 
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 151
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                        11        0.00          0.02
  SQL*Net message from client                     2        0.38          0.42
  SQL*Net more data to client                     4        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
********************************************************************************

Thank you very much

Report message to a moderator

Re: cache issue [message #620861 is a reply to message #620855]

Wed, 06 August 2014 12:26

BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal

Senior Member

It depends.
Nobody can know if any SQL statement is optimized without actually seeing the complete SELECT statement, the EXPLAIN PLAN & numerous other details.

Your question is similar to me asking you the question below after showing you a picture of my belt on a plain background

Is my belt long enough?

Report message to a moderator

Re: cache issue [message #620866 is a reply to message #620861]

Wed, 06 August 2014 12:41

sant_new1
Messages: 46
Registered: June 2014

Member

I totally understand.. but just wanted to know if it's a common and expected behavior that the SQL takes very long in the 1st run, but when ran again it took far less time.. If that is how it will be, we can probably go to the next text case and there is no action required to analyze more on this particular test case.. Any suggestions are greatly appreciated..

Thanks much

Report message to a moderator

Re: cache issue [message #620868 is a reply to message #620866]

Wed, 06 August 2014 12:53

BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal

Senior Member

If you can't, won't, don't believe what you see for yourself, then why would you believe anything posted here by strangers?

Report message to a moderator

Re: cache issue [message #620880 is a reply to message #620868]

Wed, 06 August 2014 14:38

sant_new1
Messages: 46
Registered: June 2014

Member

Here is the SQL statement and the row source operation during the 1st run..


SELECT DISTINCT busnp.ijp_a, busnp.first_name,........
 ..............................
FROM busnp, ccp , jpdp astdp, locator_keypad keyp, locp WHERE 
  (ccp.mdr = 'PRL' AND  ccp.goc = '*' AND  astdp.goc = ccp.goc 
  AND astdp.ijp =  ccp.ijp AND astdp.irole = 1 
  AND busnp.iloc = astdp.iloc AND 
  astdp.pose_c = 'HUI' AND (busnp.ijp_a = ccp.ijp) AND ccp.sta = 'N') 
  AND (locp.iloc =  keyp.iloc AND keyp.kword LIKE 'LOLA' AND 
  keyp.ktype = 'M' AND busnp.ijp_a = locp.ijp 
  AND busnp.iaddr = locp.iaddr AND 
  (busnp.ijp_b = locp.ijp2 OR busnp.pinst <> 'RE') 
  AND busnp.goc IN ('*','LI_WEE','RE_WEJ','SE','KLER_J','NMN')
  AND busnp.mdr = 'PRL') 


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.17       0.14          0         12          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.87      21.22       6360      12712          0         158
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.04      21.36       6360      12724          0         158

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 151  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  VIEW  MMV (cr=0 pr=0 pw=0 time=0 us cost=5 size=1156 card=2)
      0   UNION-ALL  (cr=0 pr=0 pw=0 time=0 us)
      0    NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=53 card=1)
      0     TABLE ACCESS BY INDEX ROWID MTH (cr=0 pr=0 pw=0 time=0 us cost=1 size=14 card=1)
      0      INDEX UNIQUE SCAN MTH_IX (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589975)
      0     TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=39 card=1)
      0      INDEX UNIQUE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      0    MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=0 us cost=3 size=75 card=1)
      0     NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=53 card=1)
      0      TABLE ACCESS BY INDEX ROWID MTH (cr=0 pr=0 pw=0 time=0 us cost=1 size=14 card=1)
      0       INDEX UNIQUE SCAN MTH_IX (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589975)
      0      TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=39 card=1)
      0       INDEX RANGE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      0     BUFFER SORT (cr=0 pr=0 pw=0 time=0 us cost=2 size=22 card=1)
      0      TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=22 card=1)
      0       INDEX RANGE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      0  VIEW  MMV (cr=0 pr=0 pw=0 time=0 us cost=5 size=1156 card=2)
      0   UNION-ALL  (cr=0 pr=0 pw=0 time=0 us)
      0    NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=53 card=1)
      0     TABLE ACCESS BY INDEX ROWID MTH (cr=0 pr=0 pw=0 time=0 us cost=1 size=14 card=1)
      0      INDEX UNIQUE SCAN MTH_IX (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589975)
      0     TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=39 card=1)
      0      INDEX UNIQUE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      0    MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=0 us cost=3 size=75 card=1)
      0     NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=53 card=1)
      0      TABLE ACCESS BY INDEX ROWID MTH (cr=0 pr=0 pw=0 time=0 us cost=1 size=14 card=1)
      0       INDEX UNIQUE SCAN MTH_IX (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589975)
      0      TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=39 card=1)
      0       INDEX RANGE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      0     BUFFER SORT (cr=0 pr=0 pw=0 time=0 us cost=2 size=22 card=1)
      0      TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=22 card=1)
      0       INDEX RANGE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      3  VIEW  MMV (cr=36 pr=0 pw=0 time=270 us cost=5 size=1112 card=2)
      3   UNION-ALL  (cr=36 pr=0 pw=0 time=266 us)
      0    NESTED LOOPS  (cr=9 pr=0 pw=0 time=58 us cost=2 size=53 card=1)
      0     TABLE ACCESS BY INDEX ROWID MTH (cr=9 pr=0 pw=0 time=53 us cost=1 size=14 card=1)
      3      INDEX UNIQUE SCAN MTH_IX (cr=6 pr=0 pw=0 time=38 us cost=1 size=0 card=1)(object id 589975)
      0     TABLE ACCESS BY INDEX ROWID MTT (cr=0 pr=0 pw=0 time=0 us cost=1 size=39 card=1)
      0      INDEX UNIQUE SCAN MT_UNIQ (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 589976)
      3    MERGE JOIN CARTESIAN (cr=27 pr=0 pw=0 time=165 us cost=3 size=75 card=1)
      3     NESTED LOOPS  (cr=18 pr=0 pw=0 time=73 us cost=2 size=53 card=1)
      3      TABLE ACCESS BY INDEX ROWID MTH (cr=9 pr=0 pw=0 time=22 us cost=1 size=14 card=1)
      3       INDEX UNIQUE SCAN MTH_IX (cr=6 pr=0 pw=0 time=13 us cost=1 size=0 card=1)(object id 589975)
      3      TABLE ACCESS BY INDEX ROWID MTT (cr=9 pr=0 pw=0 time=46 us cost=1 size=39 card=1)
      3       INDEX RANGE SCAN MT_UNIQ (cr=6 pr=0 pw=0 time=28 us cost=1 size=0 card=1)(object id 589976)
      3     BUFFER SORT (cr=9 pr=0 pw=0 time=85 us cost=2 size=22 card=1)
      3      TABLE ACCESS BY INDEX ROWID MTT (cr=9 pr=0 pw=0 time=38 us cost=1 size=22 card=1)
      3       INDEX RANGE SCAN MT_UNIQ (cr=6 pr=0 pw=0 time=24 us cost=1 size=0 card=1)(object id 589976)
    158  HASH UNIQUE (cr=14484 pr=6377 pw=0 time=21394421 us cost=11 size=456 card=1)
    158   NESTED LOOPS  (cr=12676 pr=6360 pw=0 time=22728812 us)
    158    NESTED LOOPS  (cr=12518 pr=6359 pw=0 time=22721513 us cost=10 size=456 card=1)
    158     NESTED LOOPS  (cr=12504 pr=6358 pw=0 time=22711999 us cost=9 size=413 card=1)
    158      NESTED LOOPS  (cr=12028 pr=6358 pw=0 time=22709471 us cost=8 size=361 card=1)
    158       NESTED LOOPS  (cr=11716 pr=6124 pw=0 time=21848158 us cost=7 size=345 card=1)
    158        NESTED LOOPS  (cr=11244 pr=5813 pw=0 time=20172869 us cost=6 size=320 card=1)
   1147         NESTED LOOPS  (cr=10314 pr=5463 pw=0 time=21421000 us cost=5 size=1445 card=5)
   1147          NESTED LOOPS  (cr=6872 pr=3651 pw=0 time=14697215 us cost=4 size=915 card=5)
   1147           NESTED LOOPS  (cr=3450 pr=1825 pw=0 time=9119763 us cost=2 size=200 card=5)
   1147            INDEX RANGE SCAN keyp_IN1 (cr=7 pr=7 pw=0 time=13961 us cost=1 size=95 card=5)(object id 589144)
   1147            TABLE ACCESS BY INDEX ROWID locp (cr=3443 pr=1818 pw=0 time=6082800 us cost=1 size=21 card=1)
   1147             INDEX UNIQUE SCAN locp_PK (cr=2295 pr=750 pw=0 time=694347 us cost=1 size=0 card=1)(object id 589167)
   1147           TABLE ACCESS BY INDEX ROWID a_addr (cr=3422 pr=1826 pw=0 time=5992129 us cost=1 size=143 card=1)
   1147            INDEX UNIQUE SCAN a_addr_PK (cr=2299 pr=749 pw=0 time=461309 us cost=1 size=0 card=1)(object id 589058)
   1147          TABLE ACCESS BY INDEX ROWID ajp (cr=3442 pr=1812 pw=0 time=5736925 us cost=1 size=106 card=1)
   1147           INDEX UNIQUE SCAN ajp_PK (cr=2294 pr=749 pw=0 time=450441 us cost=1 size=0 card=1)(object id 589141)
    158         TABLE ACCESS BY INDEX ROWID ccr (cr=930 pr=350 pw=0 time=872738 us cost=1 size=31 card=1)
    158          INDEX UNIQUE SCAN ccr_ix (cr=773 pr=194 pw=0 time=61118 us cost=1 size=0 card=1)(object id 589313)
    158        TABLE ACCESS BY INDEX ROWID jpdp (cr=472 pr=311 pw=0 time=1303343 us cost=1 size=25 card=1)
    158         INDEX RANGE SCAN jpdp_IN2 (cr=319 pr=165 pw=0 time=567039 us cost=1 size=0 card=1)(object id 589133)
    158       TABLE ACCESS BY INDEX ROWID cpfin (cr=312 pr=234 pw=0 time=995715 us cost=1 size=16 card=1)
    158        INDEX RANGE SCAN cust_fk (cr=161 pr=95 pw=0 time=354872 us cost=1 size=0 card=1)(object id 589347)
    158      TABLE ACCESS BY INDEX ROWID locp (cr=476 pr=0 pw=0 time=2659 us cost=1 size=52 card=1)
    158       INDEX UNIQUE SCAN locp_PK (cr=318 pr=0 pw=0 time=1410 us cost=1 size=0 card=1)(object id 589167)
    158     INDEX UNIQUE SCAN ajp_PK (cr=14 pr=1 pw=0 time=9035 us cost=1 size=0 card=1)(object id 589141)
    158    TABLE ACCESS BY INDEX ROWID ajp (cr=158 pr=1 pw=0 time=6990 us cost=1 size=86 card=2)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                      6360        0.05         20.60
  SQL*Net message from client                     2        0.41          0.47
  SQL*Net more data to client                     4        0.00          0.00
********************************************************************************

Any help is appreciated.. THank you so much

Report message to a moderator

Re: cache issue [message #620882 is a reply to message #620880]

Wed, 06 August 2014 14:42

BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal

Senior Member

https://community.oracle.com/thread/3593020

Report message to a moderator

Re: cache issue [message #620884 is a reply to message #620882]

Wed, 06 August 2014 14:49

sant_new1
Messages: 46
Registered: June 2014

Member

Yes, that's me looking for suggestions ..

Thanks

Report message to a moderator

Re: cache issue [message #620888 is a reply to message #620855]

Wed, 06 August 2014 16:45

John Watson
Messages: 8962
Registered: January 2010
Location: Global Village

Senior Member

What you describe looks to me like the expected result: the query runs twice with the same execution plan, and for the second run it is faster because the blocks are cached. There is nothing you can do to change this behaviour. Easy to test - ALTER SYSTEM FLUSH BUFFER_CACHE and run it again.

However, I am surprised that it takes so long to do just a few thousand single block reads. You are getting terrible disc performance. If the discs really are that slow (would this be a virtualized environment, by any chance?) you might want want to push the optimizer towards a different execution plan. Have you gathered system statistics? Have you created extended stats on those multi-column predicates?

Report message to a moderator

Re: cache issue [message #620938 is a reply to message #620888]

Thu, 07 August 2014 07:05

LNossov
Messages: 318
Registered: July 2011
Location: Germany

Senior Member

I think, the disks are fast enough: 21 / 6360 ~ 0.0033 sec. for one physical read. The most of these reads are single byte reads.

Report message to a moderator

Re: cache issue [message #620942 is a reply to message #620938]

Thu, 07 August 2014 07:15

John Watson
Messages: 8962
Registered: January 2010
Location: Global Village

Senior Member

Fair enough, Leonid.

(ps - good to see you back here)

Report message to a moderator

Re: cache issue [message #620946 is a reply to message #620880]

Thu, 07 August 2014 07:24

LNossov
Messages: 318
Registered: July 2011
Location: Germany

Senior Member

I have to check the histograms for the index columns of keyp_IN1 (if they exist). Because Oracle estimates too optimistic the cardinality of the index range scan (5 instead of 1147). I would try to reduce the number of buffer gets to 4000-5000 for this sql. You can try to improve the optimizer statistics for this purpose or to change the order of table accesses in the join.

Report message to a moderator

Re: cache issue [message #620947 is a reply to message #620942]

Thu, 07 August 2014 07:25

LNossov
Messages: 318
Registered: July 2011
Location: Germany

Senior Member

Report message to a moderator

Re: cache issue [message #621578 is a reply to message #620855]

Thu, 14 August 2014 09:53

sant_new1
Messages: 46
Registered: June 2014

Member

Thank you for all the suggestions.. We had to compute statistics on one of the tables, it helped with the performance a bit.. We are also looking at histograms for the columns involved in the select..

Thanks again..

[Updated on: Thu, 14 August 2014 10:34]

Report message to a moderator

Previous Topic:	Reading byte data from BLOB vs File System
Next Topic:	view slowness..

Goto Forum:

-=] Back to Top [=-

[ Syndicate this forum (XML) ] [

]

Current Time: Thu Jan 02 17:31:49 CST 2025