Home » RDBMS Server » Performance Tuning » same sql but different responce time (oracle database (OLTP) 9.2.0.7 on aix)
same sql but different responce time [message #290230] Fri, 28 December 2007 02:23 Go to next message
dba4bank
Messages: 49
Registered: October 2007
Location: TURKEY
Member
hi guru,

I have a sql script. when I execute it at 9:00 AM it takes 2 minutes. But one hour later when I execute same sql script,it takes 22 minutes.

my cache hit ratio value is 99
and cache buffer is 6 gb

it is result of trace file with tkprof . The script was executed at 9:00 AM

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 3114

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  FILTER  (cr=7363216 r=0 w=0 time=156137915 us)
      0   NESTED LOOPS  (cr=7363216 r=0 w=0 time=156137913 us)
      0    NESTED LOOPS  (cr=7363216 r=0 w=0 time=156137913 us)
    625     NESTED LOOPS  (cr=7361334 r=0 w=0 time=156130010 us)
    625      NESTED LOOPS  (cr=7358832 r=0 w=0 time=156122823 us)
    625       NESTED LOOPS  (cr=7356330 r=0 w=0 time=156114828 us)
      5        TABLE ACCESS FULL GTAX (cr=3 r=0 w=0 time=71 us)
    625        TABLE ACCESS BY INDEX ROWID GTRX (cr=7356327 r=0 w=0 time=156114352 us)
58082020         INDEX RANGE SCAN IGTRX6 (cr=610657 r=0 w=0 time=28736885 us)(object id 100185)
    625       TABLE ACCESS BY INDEX ROWID GTRXISSNEW (cr=2502 r=0 w=0 time=6584 us)
    625        INDEX UNIQUE SCAN CGTRXISSNEW1 (cr=1877 r=0 w=0 time=4341 us)(object id 100187)
    625      TABLE ACCESS BY INDEX ROWID GTRXACQ (cr=2502 r=0 w=0 time=6056 us)
    625       INDEX UNIQUE SCAN CGTRXACQ1 (cr=1877 r=0 w=0 time=3996 us)(object id 100183)
      0     TABLE ACCESS BY INDEX ROWID GTRXMST (cr=1882 r=0 w=0 time=6390 us)
      0      INDEX RANGE SCAN IGTRXMST2 (cr=1882 r=0 w=0 time=5998 us)(object id 92105)
      0    TABLE ACCESS BY INDEX ROWID GAMRCHNT
      0     INDEX UNIQUE SCAN IAMRCHNT1 (object id 15082)
      0   SORT AGGREGATE
      0    TABLE ACCESS FULL GTAX

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

ALTER SESSION SET sql_trace=FALSE


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer goal: RULE
Parsing user id: 3114

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      6      0.00       0.00          0          0          0           1
Fetch        3    159.75     156.13          0    7363219          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       14    159.75     156.13          0    7363219          0           5
 ***************************************************************
it is result of trace file with tkprof . The script was executed at 11:00 AM
Misses in library cache during parse: 0

Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: 3114

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  FILTER  (cr=7363216 r=6474738 w=0 time=1341816030 us)
      0   NESTED LOOPS  (cr=7363216 r=6474738 w=0 time=1341816029 us)
      0    NESTED LOOPS  (cr=7363216 r=6474738 w=0 time=1341816028 us)
    625     NESTED LOOPS  (cr=7361334 r=6474541 w=0 time=1340806684 us)
    625      NESTED LOOPS  (cr=7358832 r=6474353 w=0 time=1339794706 us)
    625       NESTED LOOPS  (cr=7356330 r=6474151 w=0 time=1338616293 us)
      5        TABLE ACCESS FULL GTAX (cr=3 r=0 w=0 time=62 us)
    625        TABLE ACCESS BY INDEX ROWID GTRX (cr=7356327 r=6474151 w=0 time=1338615813 us)
58082020         INDEX RANGE SCAN IGTRX6 (cr=610657 r=600307 w=0 time=187562947 us)(object id 100185)
    625       TABLE ACCESS BY INDEX ROWID GTRXISSNEW (cr=2502 r=202 w=0 time=1176623 us)
    625        INDEX UNIQUE SCAN CGTRXISSNEW1 (cr=1877 r=65 w=0 time=406884 us)(object id 100187)
    625      TABLE ACCESS BY INDEX ROWID GTRXACQ (cr=2502 r=188 w=0 time=1010639 us)
    625       INDEX UNIQUE SCAN CGTRXACQ1 (cr=1877 r=60 w=0 time=388037 us)(object id 100183)
      0     TABLE ACCESS BY INDEX ROWID GTRXMST (cr=1882 r=197 w=0 time=1007648 us)
      0      INDEX RANGE SCAN IGTRXMST2 (cr=1882 r=197 w=0 time=1006966 us)(object id 92105)
      0    TABLE ACCESS BY INDEX ROWID GAMRCHNT
      0     INDEX UNIQUE SCAN IAMRCHNT1 (object id 15082)
      0   SORT AGGREGATE
      0    TABLE ACCESS FULL GTAX

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

ALTER SESSION SET sql_trace=FALSE


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: 3114



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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.01          0          0          0           0
Execute      6      0.00       0.00          0          0          0           1
Fetch        3    353.02    1341.81    6474738    7363219          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       14    353.02    1341.83    6474738    7363219          0           5

Misses in library cache during parse: 5
Misses in library cache during execute: 1




[Updated on: Fri, 28 December 2007 15:54] by Moderator

Report message to a moderator

Re: same sql but different responce time [message #290259 is a reply to message #290230] Fri, 28 December 2007 04:01 Go to previous messageGo to next message
Michel Cadot
Messages: 64103
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Execution plans and charts are unreadable if they are not formated.
Read and follow OraFAQ Forum Guide, especially "How to format your post?" section.
Make sure that lines of code do not exceed 80 characters when you format. Use the "Preview Message" button.

Quote:

cache hit ratio value is 99

Then either your cache is far too big or you have an application problem.

First read How to Identify Performance Problem and Bottleneck and provide the requested information you'll find in guide.

Regards
Michel
Re: same sql but different responce time [message #290353 is a reply to message #290230] Fri, 28 December 2007 07:51 Go to previous messageGo to next message
dba4bank
Messages: 49
Registered: October 2007
Location: TURKEY
Member
ratio = 0.986262488190877 pretty good value
Re: same sql but different responce time [message #290362 is a reply to message #290353] Fri, 28 December 2007 09:15 Go to previous messageGo to next message
Michel Cadot
Messages: 64103
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
No, it is a pretty BAD value.
It is an indication that, as I said, either you waste space with too big cache or you have bad applications/queries.

Regards
Michel
Re: same sql but different responce time [message #290375 is a reply to message #290362] Fri, 28 December 2007 10:48 Go to previous messageGo to next message
dba4bank
Messages: 49
Registered: October 2007
Location: TURKEY
Member
ok sir thx your interested.
so do you know what is the best value for cache hit ratio??
Re: same sql but different responce time [message #290376 is a reply to message #290375] Fri, 28 December 2007 10:51 Go to previous messageGo to next message
Michel Cadot
Messages: 64103
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
There is no best value, it is just an indicator.
Too low, too high or changing it is a warning that some investigations have to be done.

Regards
Michel
Re: same sql but different responce time [message #290378 is a reply to message #290230] Fri, 28 December 2007 10:59 Go to previous messageGo to next message
BlackSwan
Messages: 25033
Registered: January 2009
Location: SoCal
Senior Member
Buffer Cache Hit Ratio is a mythical indicator of performance.
It can mean whatever you want it to mean.
Re: same sql but different responce time [message #290420 is a reply to message #290378] Fri, 28 December 2007 16:13 Go to previous messageGo to next message
rleishman
Messages: 3724
Registered: October 2005
Location: Melbourne, Australia
Senior Member
At 9am, you had no hits on the disk. The entire query was satisfied by cached data. That seems pretty unlikely considering it read 58 million rows from an index. This is probably because you - or someone else - just ran it a few minutes earlier.

At 11am, surprise surprise, people have been running other queries and your 58 million rows have been swapped out of cache. Now they must be read from disk.

An index range scan reads blocks from disk ONE AT A TIME. So you had 6 million separate round-trips to the disk. Full table scans can read many blocks at once, so are much more efficient for large scans.

It is unreasonable to think that you can always have this many rows cached. If you cannot change the indexes on GTRX, you should modify the query to perform a full table scan.

If you can change the indexes, note that you are scanning 58 million index entries but fetching only 625 rows. It strikes me that the indexing could be a little more ... um ... directed.

What are the WHERE clauses on GRTX? And what are the indexes?

Ross Leishman
Re: same sql but different responce time [message #290648 is a reply to message #290230] Mon, 31 December 2007 00:40 Go to previous messageGo to next message
dba4bank
Messages: 49
Registered: October 2007
Location: TURKEY
Member
hi gurus,
first of all thx for your reply.


FROM GTRX A, GTRXACQ Q,GTRXMST B,GAMRCHNT D,GTRXISSNEW F,GTAX X
WHERE A.CGTYPTRX ||'' IN ('001','002','052','054','151','152')
AND A.DRECDGEN BETWEEN TRUNC(sysdate) - 65 and TRUNC(sysdate+1)

There are a lot of indexes on GTRX.one of them is on the A.DRECDGEN column.

and I agree with you about swapped out of cache 58 milions rows.
Re: same sql but different responce time [message #290655 is a reply to message #290648] Mon, 31 December 2007 01:02 Go to previous messageGo to next message
Michel Cadot
Messages: 64103
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Once more, please read and follow OraFAQ Forum Guide, especially "How to format your post?" section.
Make sure that lines of code do not exceed 80 characters when you format. Use the "Preview Message" button.

Regards
Michel
Re: same sql but different responce time [message #290802 is a reply to message #290655] Mon, 31 December 2007 20:10 Go to previous message
rleishman
Messages: 3724
Registered: October 2005
Location: Melbourne, Australia
Senior Member
You need an index on (CGTYPTRX, DRECDGEN), and you need to remove the ||'', it was added by someone who wanted to suppress that index in favour of the one on DRECDGEN.

Ross Leishman
Previous Topic: memory sizng on
Next Topic: Choose your Buffer Cache Hit Ratio
Goto Forum:
  


Current Time: Sat Dec 03 10:08:19 CST 2016

Total time taken to generate the page: 0.21096 seconds