opinions on statspack

Hi all

below is results from my statspack and I would like get some opinion from yous guys to be sure that my analysis is correct:

Code:

---


Load Profile
~~~~~~~~~~~~                            Per Second      Per Transaction
                                  ---------------      ---------------
                  Redo size:              1,137.20            566,328.00
              Logical reads:              5,048.43          2,514,118.00
              Block changes:                  2.22              1,105.00
            Physical reads:              3,500.12          1,743,061.00
            Physical writes:                  9.47              4,718.00
                User calls:                  1.41                702.00
                    Parses:                  1.20                600.00
                Hard parses:                  0.03                15.00
                      Sorts:                  0.91                451.00
                    Logons:                  0.00                  0.00
                  Executes:                  1.91                951.00
              Transactions:                  0.00

  % Blocks changed per Read:    0.04    Recursive Call %:                89.55
 Rollback per transaction %:    0.00      Rows per Sort:              640.81

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00      Redo NoWait %:              100.00
            Buffer  Hit  %:  30.84    In-memory Sort %:              99.11
            Library Hit  %:  88.40        Soft Parse %:              97.50
        Execute to Parse %:  36.91        Latch Hit %:              99.99
Parse CPU to Parse Elapsd %:  82.61    % Non-Parse CPU:              99.80

 Shared Pool Statistics        Begin  End
                              ------  ------
            Memory Usage %:  93.86  93.88
    % SQL with executions>1:  60.98  62.99
  % Memory for SQL w/exec>1:  32.95  35.39

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                    % Total
Event                                              Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                          97    75.94
db file sequential read                        1,532,454          28    22.23
db file scattered read                            23,868          2    1.61
control file parallel write                          162          0      .15
db file parallel read                                626          0      .03
          -------------------------------------------------------------
Wait Events for DB: TEST  Instance: TEST  Snaps: 36 -37
-> s  - second
-> cs - centisecond -    100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                                                  Avg
                                                    Total Wait  wait    Waits
Event                              Waits  Timeouts  Time (s)  (ms)    /txn
---------------------------- ------------ ---------- ---------- ------ --------
db file sequential read        1,532,454          0        28      0 ########
db file scattered read            23,868          0          2      0 ########
control file parallel write          162          0          0      1    162.0
db file parallel read                626          0          0      0    626.0
latch free                              7          2          0      3      7.0
log file sync                          2          0          0      8      2.0
SQL*Net more data to client          101          0          0      0    101.0
control file sequential read          122          0          0      0    122.0
direct path read                      420          0          0      0    420.0
direct path write                    260          0          0      0    260.0
log file parallel write                31        31          0      0    31.0
db file parallel write                  6          0          0      0      6.0
LGWR wait for redo copy                2          0          0      0      2.0
SQL*Net message from client          641          0      1,733  2704    641.0
SQL*Net message to client            641          0          0      0    641.0
          -------------------------------------------------------------

---

I think I have problem in I/O but there is nothing much I can do b/c this server only have one RAId controller and it runs on RAID 5. If I have more than RAID array that would give me option to balance out the loads. Basically, this report was captured only during the READ period from the map. Other things I want to ask is the buffer hit ratio is faily low. Any other comment you can see or advises????

thanks and have a great weekend everyone.

but db file sequential read was only 22% of the total wait.

CPU time was your biggest problem

Thanks Davey,

what could cause CPU high???? but when the user perform the operation from the map and I look at the the amount of CPU on the server it's used no more than 50% at the given time.

Please give me more input.

thanks,

Hi,
Check for queries doing high buffer read,disk reads. There must be queires doing lot of HOT BLOCK READS.

Your queries must be reading too much of data.

regards
anandkl

With high "CPU time" and high "db file sequential read" I'd probably start looking for queries that had excessive LIOs from misused indexes.

first of all, thanks for the value advises.



the SQL statement was issued directly from the third party tool (ESRI, if anyone is familiar with GIS), any way, on STATSPACK, it gave me the incomplete query so you think I should set the SQL trace so I can get the SQL statement???

unless you know the query plan, I don't know how you would diagnose it.

Hi Hannah

Davey and Jeff are both correct in thier analysis..

However what type of quesries do you run..mostly read only ? then raid 5 is good elese you should be looking raid 1+0

Did you take the snap when the period of activity was high ?

You can upload your statspack repotrt here and have it analyzed for free

regards
Hrishy

Quote:

---

Originally posted by hannah00
. . . . I look at the the amount of CPU on the server it's used no more than 50% at the given time.

---

Is this a dual-processor machine? That's pretty much what you'd expect if one processor was running near 100% most of the time.

(I'll join the others in saying you need at least an explain plan on the (or a typical) query - if you can't do that, set trace or event 10046 and tkprof or trace-analyze the output).

First you should not post incomplete statspack report, and start asking questions.

Tamil

Hanna,
We run ESRI and it produces some nasty code specifically adding hints to use unique key indexes and does not let the Oracle optimizer do its thing. I hope with its next release ESRI wakes up and stops adding hints to its code.

About the only thing you can do to make ESRI perform any better is to cache, monitor the main objects and make sure your statistics are up todate as often as possible. Also, you can tweak the giomgr.defs file and the axle file. You'd be suprised at how making an layer use attribute first helps.

Thanks Jeff and everyone who participate to help me. Per Jeff's advises, I was able to trace the SQL which misused the index and do a FTS (I guess Oracle pick whatever lowest cost). I added Optimizer_index_cost_adj = 10 and Oracle pick up the index adn resolve my problem.

the next question I have now is "so lower cost doesn't mean your query optimize" specially in this case, could someone please tell me why???

I n t e r e s t i n g . . . .

I wouldn't have expected excessive FTS to produce this

Code:

---

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                    % Total
Event                                              Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                          97    75.94
db file sequential read                        1,532,454          28    22.23
db file scattered read                            23,868          2    1.61

---

Hannah

I think you are inviting more problem by doing this

I added Optimizer_index_cost_adj = 10 and Oracle pick up the index adn resolve my problem.


Look at your wait events ..they are mostly due to CPU and making use of the indexes .Fix the correct problem :-)

regards
Hrishy

I would guess, some of your queries going for index full scan due to hints added by the third party application..

Abhay.

thanks all again,

I thought my problem is resolved but I guess not :O(

could you please tell me why adding Optimizer_index_cost_adj = 10 weould create more problem???? does it mean it will affect other queries that already used indexes ????

I thought Jeff has mentioend earlier "high CPU and db file sequential read is the result of misused indexes"

I think you guys were right (as usual), I did run another statspack and the CPU and db file sequential read still very high, the question is how come my map was running much faster, even at the zoom in/out level.


Dapi,

if it's not FTS would produce high CPU, what causing this issue??

please advise

db file sequential read means index scans

cpu usage most of times are buffer reads and parse calls

db file sequential read + high cpu usage most of times means Nested Loop Joins when a sort or hash join is preferred

I'm not sure I can make up a totally consistant story and remember that we are talking about averages when we look at statspack:

A) If there were a lot of FTS and the Buffer Cache Hit Ratio were 30% then you would be waiting mainly on "db file scattered read" - i.e. multi-block reads from disk.
B) High CPU usage suggests that the data you need is already in buffers. Waits on "db file sequential read" are mainly single-block reads - i.e. NOT by FTS.


I could imagine that there are two types of activity going on:

A) queries using FTS like the one you isolated and "tuned"
B) queries that are thrashing CPU & Buffers using Nested Loops that might be more efficient NOT using the indexes (I think that's what Jeff meant by "misusing" an index). Optimizer_index_cost_adj = 10 could make this worse?

I find it hard to reconcile some mix of A & B that would produce the statspack report you see. :confused:

thanks Pando and Dapi,

according to you guys, Optimizer_index_cost_adj = 10 could make thing worse, but how come my map is run much faster now, PLEASE, I am not trying to be ignorant, I just want to understand what's going on and learn.


look into a few queries that were trace, you are right, the executions plan is NESTED LOOP JOINS. ESRI (third party tool) is issued these statements not from our app.

how can we force the app to use sort or hash join???

You need to think in terms of TWO questions here:

1) Are my critical business activities (queries & changes) executed with a appropriate speed? If not, why not?
2) How is my server standing up to this?

The answer to (1) is trace & tkprof. The answer to (2) is statspack.

It's not necessarily bad that the CPU is at 50% - if it were at 0.5% you'd kick yourself that you didn't buy a cheaper, slower machine!

You haven't told us under what conditions the ststapack was run: how long? how many users? (I do notice you have one transaction per 500 seconds . . . .)

BTW I'm NOT saying "Optimizer_index_cost_adj = 10" will make things worse, just that it could.
(I remember seeing someone saying that setting this to 10-30 was the only genuine "silver bullet" he'd seen - I'll post a link if ever I find it.***)

P.S.
*** OOOPS - I think it might have been from a DKB article . . . . I did set it to 30 and have had no probs.

thanks Dapi,

1) Are my critical business activities (queries & changes) executed with a appropriate speed? If not, why not?
YES, AFTER THE CHANGE I MADE BY ADDING "Optimizer_index_cost_adj = 10", THE MAP IS NOW RUNNING MUCH FASTER THAN BEFORE.

2) How is my server standing up to this?
SERVER IS FINE, I DID TRACE THE SERVER CPU AND MEMORY, IT NEVER EXCEED 50% OF THE TOTAL PHYSICAL RESOURCES THAT WERE AVAILABLE.

As I mention it before, one of my query did a FTS and I guess Oracle pick whatever plan with lower cost and ignore the index, now after making the change, the cost to execute the same query is higher but it did pick up INDEX and the app perform much better, but I run STATPACK again and CPU was still at 80% and DB SEQUENTIAL READ still somewhere at 16% and I don't undertand this.

statspack was run in about 20 min timeframe, with a few users in there.

To start with forget compare the costs, lower does not mean better

Get the TOP sql in your second statspack report and see if both reports (before modifying the parameter and after) share same TOP sql statements

Quote:

---

Originally posted by hannah00
thanks Dapi,

1) Are my critical business activities (queries & changes) executed with a appropriate speed? If not, why not?
YES, AFTER THE CHANGE I MADE BY ADDING "Optimizer_index_cost_adj = 10", THE MAP IS NOW RUNNING MUCH FASTER THAN BEFORE.

---

Hi Hannah

when you changed your optimizer_index_cost_adj to 10 you said that the map was running faster.If i were you i would have done this

1)Get the plan of the query as it is
2)alter session set Optimizer_index_cost_adj to 10 and see
whats the plan again
3)try and see how plan in 2 is more efficient dont rely on the cost alone check for response time Logical IO's
4)see why the optimizer choose plan B .

If you just Optimizer_index_cost_adj=10 i am not sure how your other queries might perform.If you think that other users are not screaming then yes go ahead and make Optimizer_index_cost_adj =10

regards
Hrishy

thanks all for the valueable advises.

I will definitely test it out and and let you know what I find.

thanks Hirshy.

here is the latest test I have.

I trace two different execution plans one with Optimizer_index_cost_adj =10 and one without Optimizer_index_cost_adj =10
and below is what I find:

on the total CPU time on the trace file on Optimizer_index_cost_adj =10 is much lowever than the one without Optimizer_index_cost_adj =10. but I what I don;t understand is the top 5 events of CPU is higher than before:

Code:

---


Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                    % Total
Event                                              Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                          21    92.13
db file sequential read                            28,842          1    5.83
control file parallel write                          497          0    1.81
SQL*Net more data to client                          325          0      .09
log file sync                                          1          0      .06

---

could you please explain to me why???

Hi Hannah

when you change that parameter Optimizer_index_cost_adj it effected the queries as that parameter tells the optimizer that indexes are cheaper to use and please go ahead and use them.That explains why your query plan changed.

But i doubt whether the Optimizer_index_cost_adj has anything to do with the CPU.(thats what dapi The cranky old philospoher said

Code:

---


I n t e r e s t i n g . . . .

I wouldn't have expected excessive FTS to produce this

code:--------------------------------------------------------------------------------Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                    % Total
Event                                              Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                          97    75.94
db file sequential read                        1,532,454          28    22.23
db file scattered read                            23,868          2    1.61--------------------------------------------------------------------------------

---

what he meant was you were trying to cure the disease of high cpu usage by trying to medicate with Optimizer_index_cost_adj .


Optimizer_index_cost_adj setting this will not solve your problem.

for advise on setting this parameter refer to this formula courtesy by Tim Gorman

Code:

---


OPTIMIZER_INDEX_COST_ADJ =
select round((select average_wait
                from v$system_event
              where event='db file sequential read')
            /
            (select average_wait
                from v$system_event
              where event='db file scattered read')
            * 100)
  from dual;

---

in 9i

Code:

---

col a1 head "avg. wait time|(db file sequential read)"
col a2 head "avg. wait time|(db file scattered read)"
col a3 head "new setting for|optimizer_index_cost_adj"

logged in as sys issue
select a.average_wait a1,
      b.average_wait a2,
      round( ((a.average_wait/b.average_wait)*100) ) a3
from
      (select d.kslednam EVENT,
              s.kslestim / (10000 * s.ksleswts) AVERAGE_WAIT
      from x$kslei s, x$ksled d
      where s.ksleswts != 0 and s.indx = d.indx) a,
      (select d.kslednam EVENT,
              s.kslestim / (10000 * s.ksleswts) AVERAGE_WAIT
      from x$kslei s, x$ksled d
      where s.ksleswts != 0 and s.indx = d.indx) b
where a.event = 'db file sequential read'
and b.event = 'db file scattered read';

---

This should give you a starting point you should up it or bring it down after testing all your crtical business scenarios as the cranky old philosopher put it ;-).

Now coming back to your problem of high cpu usage.You can

1)use os utilities to find out who is hogging the cpu
2)dig through your statspack report to find cpu intensive sql's
3)upload your statspack report to www.oraperf.com for free analysis.
4)Be happy that your cpu usage is high and you are getting all your moneys worth if nothing is a suspect ;-)

regards
Hrishy

Good call on the Oraperf Hirshy I totally forgot about that one.

Quote:

---

Originally posted by hannah00
but I what I don;t understand is the top 5 events of CPU is higher than before:

---

Two things:
- you will always have a top 5, you can't get rid of them, something has to be "top"
- the % elapsed will always add up to 100% (if you take ALL the waits)

Your CPU wait time is down from 97 to 21 seconds.
Your db file sequential read wait time is down from 28 to 1 seconds.
If you're taking the statspack over the same time period, you're winning.

92% CPU wait, might be a very good thing (or it might not) - not many Oracle servers are CPU-bound.

Quote:

---

Originally posted by pando
Get the TOP sql in your second statspack report and see if both reports (before modifying the parameter and after) share same TOP sql statements

---

To add.. check the plans before and after modifying the param..

I suspect u may see in the plan/s like 'Index Full Scan'..


Abhay.

thank you so much for help!!!

those are great advises.