SQL Stored Procedure Performance Issues

[TheExcession]

Guys,

I'm getting wildly difference performance from some of our stored procedures on a system I am testing.

First things first - the system only has me using it.

We have an Oracle 8i database on two boxes, with Asynchronous and Synchronous replication groups in the schema.

The Application program is running in java - it answers RADIUS requests for setting up satellite calls.

now - I have certain stored procedures completing execution anywhere betwenn 20 and 120 milliseconds for the same procedure.

I've pinned all my packages into shared mem and run Analyze on all my tables and saw a marked improvement in response times but can't figure out why there such wildly varying responses to the same stored procedure executed a few seconds apart.

Any pointers from you DBA experts?

It's driving me nuts - I need to make about 10 sp calls per call setup message and so I'm getting response times between 200 and 1200 milliseconds - the customer aint too happy and nor am I.

I wouldn't mind if I could just get it consistent.

many thanks
Ex


P.S.

I didn't design the DB or write any of the SPs - our Indian firends did that for me.

I've run OraSnap on the whoile DB and nothing special seems to stand out but them I'm no DBA

If anyone would care to look at the output I can mail it you you - hint hint hint


Some stuff to look at:

=========================
LIBRARY CACHE MISS RATIO
=========================
executions Cache misses while executing LIBRARY CACHE MISS RATIO
------------ ---------------------------- ------------------------
14,817,026 352 .0000

=========================
Library Cache Section
=========================
NAMESPACE Hit ratio pin hit ratio reloads
--------------- ---------- ------------- ------------
SQL AREA 99 99 350
TABLE/PROCEDURE 93 99 1
BODY 99 99 0
TRIGGER 83 83 0
INDEX 23 23 0
CLUSTER 99 99 0
OBJECT 100 100 0
PIPE 100 100 0

>>> Edited by TheExcession on Thursday 9th September 20:57

>>> Edited by TheExcession on Thursday 9th September 20:57

[_DJ_]

My, that's rather a long shot!
I'm certainly not going to be able to answer this for you (DB's - yuk), but just to clarify:

1) You're the only user
2) You're running the query multiple times with the same parameters?
3) The result differs by a factor of 6 randomly?
4) The DB server is dedicated and definately has nothing else going on which could explain this?

D

[TheExcession]

_DJ_ said:

My, that's rather a long shot! I'm certainly not going to be able to answer this for you (DB's - yuk), but just to clarify: 1) You're the only user 2) You're running the query multiple times with the same parameters? 3) The result differs by a factor of 6 randomly? 4) The DB server is dedicated and definately has nothing else going on which could explain this? D

Yup That's about it! I need to check the frequency of the Asynchrous updates acroos to the other machine as that may have something to do with it.

For example - Eecute Time and Absolute time for the same stored procdure returning an integer.

I'm damn certain my timing is accurate too as other blocks of code that don't invole the db are giving me consistent values.

Exec Absolute Time
Time(ms) Time(ms)
159 1094752306447 StoreProcedure: getResultInt():
144 1094752297740 StoreProcedure: getResultInt():
144 1094752361536 StoreProcedure: getResultInt():
137 1094752311160 StoreProcedure: getResultInt():
135 1094752283135 StoreProcedure: getResultInt():
133 1094752346410 StoreProcedure: getResultInt():
131 1094752292894 StoreProcedure: getResultInt():
131 1094752301452 StoreProcedure: getResultInt():
118 1094752330028 StoreProcedure: getResultInt():
117 1094752318657 StoreProcedure: getResultInt():
113 1094752331614 StoreProcedure: getResultInt():
89 1094752359649 StoreProcedure: getResultInt():
81 1094752342702 StoreProcedure: getResultInt():
80 1094752322083 StoreProcedure: getResultInt():
73 1094752361756 StoreProcedure: getResultInt():
67 1094752328167 StoreProcedure: getResultInt():
64 1094752284891 StoreProcedure: getResultInt():
56 1094752338048 StoreProcedure: getResultInt():
55 1094752281758 StoreProcedure: getResultInt():
55 1094752341446 StoreProcedure: getResultInt():
54 1094752324668 StoreProcedure: getResultInt():
43 1094752288360 StoreProcedure: getResultInt():
43 1094752352218 StoreProcedure: getResultInt():
43 1094752355910 StoreProcedure: getResultInt():
42 1094752356855 StoreProcedure: getResultInt():
41 1094752340518 StoreProcedure: getResultInt():
40 1094752337179 StoreProcedure: getResultInt():
39 1094752282158 StoreProcedure: getResultInt():
39 1094752294467 StoreProcedure: getResultInt():
39 1094752301679 StoreProcedure: getResultInt():
38 1094752304393 StoreProcedure: getResultInt():
38 1094752329007 StoreProcedure: getResultInt():
38 1094752352409 StoreProcedure: getResultInt():
37 1094752305168 StoreProcedure: getResultInt():
37 1094752310840 StoreProcedure: getResultInt():
37 1094752319881 StoreProcedure: getResultInt():
37 1094752320565 StoreProcedure: getResultInt():
37 1094752325430 StoreProcedure: getResultInt():
37 1094752334536 StoreProcedure: getResultInt():
37 1094752343577 StoreProcedure: getResultInt():
36 1094752285997 StoreProcedure: getResultInt():
36 1094752329292 StoreProcedure: getResultInt():
36 1094752338315 StoreProcedure: getResultInt():
35 1094752291799 StoreProcedure: getResultInt():
35 1094752313416 StoreProcedure: getResultInt():
34 1094752290800 StoreProcedure: getResultInt():
34 1094752333394 StoreProcedure: getResultInt():
33 1094752287360 StoreProcedure: getResultInt():
33 1094752299442 StoreProcedure: getResultInt():
33 1094752317756 StoreProcedure: getResultInt():
33 1094752355040 StoreProcedure: getResultInt():
33 1094752357041 StoreProcedure: getResultInt():
32 1094752333632 StoreProcedure: getResultInt():
32 1094752360536 StoreProcedure: getResultInt():
31 1094752295555 StoreProcedure: getResultInt():
31 1094752300412 StoreProcedure: getResultInt():




Note: these are not in time order - gonna resort them in excel now and see if there is a reoccuring theme - something is kicking and slowing this stuff down - just can't figure what it is yet - e.g. is it oracle or is it OS?

11:55pm up 2 days, 4:52, 3 users, load average: 2.42, 2.12, 2.38
295 processes: 294 sleeping, 1 running, 0 zombie, 0 stopped
CPU states: 9.9% user, 18.2% system, 17.1% nice, 9.5% idle
Mem: 2074332K av, 1282580K used, 791752K free, 1683472K shrd, 420528K buff
Swap: 1542200K av, 1384K used, 1540816K free 472012K cached
Processes to display (0 for unlimited):
PID USER PRI NI SIZE RSS SHARE STAT LIB %CPU %MEM TIME COMMAND
26418 root 14 0 996 996 652 R 0 23.5 0.0 0:00 top
5475 oracle8i 6 0 99756 97M 97708 S 47M 11.7 4.8 21:05 oracle
905 oracle8i 5 0 101M 101M 99M S 43M 9.3 5.0 4:37 oracle
5431 root 8 5 27988 27M 8756 S N 0 8.6 1.3 15:44 java
887 oracle8i 1 0 5772 5772 5272 S 1020 1.8 0.2 12:03 oracle
5572 root 6 5 27988 27M 8756 S N 0 1.8 1.3 0:31 java
5582 root 5 5 27988 27M 8756 S N 0 1.8 1.3 0:31 java
5583 root 6 5 27988 27M 8756 S N 0 1.8 1.3 0:33 java
5483 oracle8i 1 0 80340 78M 78492 S 36M 1.2 3.8 1:14 oracle
5568 root 5 5 27988 27M 8756 S N 0 1.2 1.3 2:43 java





>> Edited by TheExcession on Friday 10th September 00:55

[TheExcession]

reet,

I've got toad running now so I can actually see into this beast.

It would seem to me that my java code is only using one session which is what I would expect as the db connections are pooled and with the testing I'm doing I would only expect to see one connection active at a time.

In the Instance summary I'm seeing quite a lot of table scans - would this indicate a missing index?

Any advice for other things to look for? I'm wondering if the REPADMIN is causing my problems?

Could this be the first PH Oracle tuning thread?

best
Ex

[_DJ_]

TheExcession said:

reet, I've got toad running now so I can actually see into this beast. It would seem to me that my java code is only using one session which is what I would expect as the db connections are pooled and with the testing I'm doing I would only expect to see one connection active at a time. In the Instance summary I'm seeing quite a lot of table scans - would this indicate a missing index? Any advice for other things to look for? I'm wondering if the REPADMIN is causing my problems? Could this be the first PH Oracle tuning thread? best Ex

Table scans could be the result of a missing index, but may not be. It all depends on whether Oracle thinks it is worthwhile using it. Are the stats being update regularly? Table scans are bad, but they should at least be consistent (given that all the data is in memory etc).

Can you work out which SP is triggering the table scan? You should be able to get an execution plan and work out why it's not using the index.

D

edited to add: first and last Oracle performance thread, hopefully . REPADMIN could well be causing the issue. As this isn't live yet (is it???) then couldn't you isolate the problem by simplifying it by removing replication from the config for a while? I know a few good Oracle DBA's and could probably call in a few favours but will probably need more info, and would prefer to use that as a last resort.


>> Edited by _DJ_ on Friday 10th September 11:49

[fatsteve]

1. What sort of transaction profile is it. Is it just a series of selects or are you inserting, updating and deleting.

2. How many insert/delete transactions are there (if any)

3. Are you using locally managed tablespaces and more importantly, uniform size extents?

It sounds a bit like your data is fragemented all over the place (hence the variation in the fetch times).

If you have access (and are allowed to), it may be worth rebuilding the tables and indexes, then doing a re-analyze:

spool rebuld_tables.sql
select 'alter table ' || table_name ' move tablespace ' || tablespace_name || chr(10) || '/'
from user_tables
/
spool off

then run rebuild_tables.sql

spool rebuild_indexes.sql
select 'alter index ' || index_name || ' rebuild tablespace ' || tablespace || chr(10) || '/'
from user_indexes
/
spool off

the run rebuild_indexes.sql

This will obviously invalidate all your stored proc's, so you'll need to recompile them again (easy to do in TOAD).

All the best

Steve

AlTER TABLE x MOVE TABLESA

[TheExcession]

Firstly a big thank you to anyone postin suggestions on this thread - I owe you guys big time!

fatsteve said:

1. What sort of transaction profile is it. Is it just a series of selects or are you inserting, updating and deleting.

In order to set up a sattelite call we need t oanswer four RADIUS messages, 2 authorisation and two accounting
In my testing I'm only setting up one call and the messages arrive in quick succession once a response has been sent.

The First message is an Authorisation Request and requires checking of about 15 parameters and then the creation of a Active Call Data Record. The Active CDR Table is empty at this time and has about 50 paramters inserted.

The response time I posted above are vor the very first lookup to obtain the RADIUS Shared Secret that allows decoding of a password in the RASIUS message.

getSANSharedKey.sql said:

CREATE OR REPLACE FUNCTION getSANSHAREDKey( V_SANID SAN.ID%type, V_SANIPADDRESS SAN.IPADDRESS%type) RETURN SAN.SHAREDKEY%type AS V_SHAREDKEY SAN.SHAREDKEY%type; I NUMBER := 0; TEMP_IPADDRESS SAN.IPADDRESS%type; BEGIN IF V_SANIPAddress IS NULL THEN SELECT MAX(SharedKey) INTO V_SHAREDKEY FROM SAN WHERE ID = V_SANID; RETURN V_SHAREDKEY; END IF; -- V_SANIPAddress IS NULL END IF. IF V_SANID IS NULL THEN SELECT SharedKey INTO V_SHAREDKEY FROM SAN WHERE IPAddress = V_SANIPAddress; RETURN V_SHAREDKEY; END IF; -- V_SANID = -1 END IF IF V_SANID IS NOT NULL AND V_SANIPAddress IS NOT NULL THEN SELECT SharedKey INTO V_SHAREDKEY FROM SAN WHERE IPAddress = V_SANIPAddress AND ID = V_SANID; RETURN V_SHAREDKEY; END IF; -- NOT NULL END IF. EXCEPTION WHEN OTHERS THEN Raise; END; --END OF FUNCTION. / show errors;

So if we just concentrate on this one Stored Proc - its just a look up.

fatsteve said:

2. How many insert/delete transactions are there (if any)

During the entire call setup there are lots - probable nearing 100 calls into the DB.

fatsteve said:

3. Are you using locally managed tablespaces and more importantly, uniform size extents? It sounds a bit like your data is fragemented all over the place (hence the variation in the fetch times). If you have access (and are allowed to), it may be worth rebuilding the tables and indexes, then doing a re-analyze:

Re: managed tablespaces and uniform size extents? I don't know (gets coat and leaves the country)

I'm inclined to believe that this could be a fragementation issue.

One thing that has come to light is the Data Dictionery Cache stats - they suck - well according to ORASNAP.
All my other buffer hits are up above 99.6%

orasnap said:

Data Dictionary Cache Statistics Parameter Gets GetMisses % Cache Misses (1) Count Usage dc_used_extents 1,623 1,623 100.00 1,559 1,547 dc_synonyms 313 73 23.00 75 72 dc_objects 7,420 1,536 21.00 1,594 1,585 dc_histogram_defs 12,920 1,457 11.00 1,466 1,457 dc_segments 6,320 466 7.00 469 466 dc_free_extents 26,408 1,669 6.00 87 49 dc_global_oids 163 9 6.00 23 9 dc_object_ids 8,125 354 4.00 383 381 dc_tablespace_quotas 228 4 2.00 26 4 dc_sequences 345 2 1.00 3 2 dc_tablespaces 3,389 5 0.00 8 5 dc_usernames 5,959 7 0.00 23 7 dc_profiles 6,336 6 0.00 9 1 dc_rollback_segments 9,973 9 0.00 16 10 dc_user_grants 207,039 16 0.00 23 16 dc_users 238,793 17 0.00 18 17 dc_database_links 2,771,606 3 0.00 4 3

Now, one conern I have is that I don't know how fresh this stats are and don't know how to reset them. This system has been lying idle for a long time and has had over 150,000 calls put through it at verious times - howver over the last 4 days I've put about 50,000 requests through the system so I'm assuming they are believeable.

I have full access rights on the system so can do what ever I want. I just don't know what I should be doing!

If anyone would mind taking a quick look over the orasnap output it's only 150K zipped and comprises a bunch of html files as shown above.

I'm pretty certain this is just a fundamental issue with the oracle setup.

best
Ex


Sorry bout the formatting of the orasnap output

>> Edited by TheExcession on Friday 10th September 14:00

[fatsteve]

Hmm data dic miss ratio can somtimes be easily cured by uping the shared pool size (init.ora para).

PLSQ doesn't appear too bad, although you will always perform a FTS on the SAN table (since it's got a MAX function). However, this can be cured easily by creating a functional index

CREATE INDEX i_san_func_max ON SAN(MAX(sharedkey))

However, I'd always be cautious at creating indexes willy-nilly since you could shaft other indexes on the same table.

Is there any chance you could drive the sharedkey from a sequence?, thus avoiding a SELECT MAX(x) FROM Y.

Try re-analyzing the entire schema

begin
dbms_utility.analyze_schema('<schema_name>','COMPUTE');
end;

This may take some time depending on the size of your schema and grunt of the db server.

Steve

[TheExcession]

fatsteve said:

Hmm data dic miss ratio can somtimes be easily cured by uping the shared pool size (init.ora para). PLSQ doesn't appear too bad, although you will always perform a FTS on the SAN table (since it's got a MAX function). However, this can be cured easily by creating a functional index CREATE INDEX i_san_func_max ON SAN(MAX(sharedkey)) However, I'd always be cautious at creating indexes willy-nilly since you could shaft other indexes on the same table. Is there any chance you could drive the sharedkey from a sequence?, thus avoiding a SELECT MAX(x) FROM Y. Try re-analyzing the entire schema begin dbms_utility.analyze_schema('<schema_name>','COMPUTE'); end; This may take some time depending on the size of your schema and grunt of the db server. Steve

thanks Steve,

I'll look into all this ASAP - unfortunately the whole LAN is down for a Firewall upgrade at the moment so I won't be able to get near it till this evening.

I've run the analyze schema a few times in the last few days.

The shared pool stuff looks like a good start - I've double checked and some objects aren't being kept.- s oI@ll fix that.

I'll look into dropping the MAX func on the sql - can't understand why its there to tell you the truth!

I guess this is gonna be along tortuous process - there are nearly 700 stroed procedures defined for this system - admittedly not all of them related to the processing of these RADIUS messages.

One last thing I restarted the db in order to clear a lot of these stats, so now will be a good time to build the sql procs to pin and perform all these analyzes.

Thanks for you help - I'll pop up again and monday and let know how its going!

best
Ex

[3200ac]

"Is there any chance you could drive the sharedkey from a sequence?, thus avoiding a SELECT MAX(x) FROM Y"
would look to be the culprit, I don't know if you've seen SQL*Navigator (a sister product to TOAD), it includes a pertty Explain Plan tool. The MAX(...) function will be performing full table scans, and I think the function-based index on max is not in the spirit of function-based indexes, which I think are intended to live on a per-row basis?? Using a Primary Key on the sequence-generated column will provide fast and consistent access, which you can confirm with Explain Plan

hope that helps
Mark