Our system is slow as hell at 10-11 time.

How is my report, could somebody help me to diasnotic the problem?
Thanks very much for your help.

Snap Id Snap Time Sessions Curs/Sess Comment
--------- ------------------ -------- ---------
-------------------
Begin Snap: 25 13-Dec-06 10:00:03 94 20.0
End Snap: 26 13-Dec-06 11:00:06 112 20.1
Elapsed: 60.05 (mins)

Cache Sizes (end)
~~~~~~~~~~~~~~~~~
Buffer Cache: 344M Std Block Size:
8K
Shared Pool Size: 352M Log Buffer:
1,024K

Load Profile
~~~~~~~~~~~~ Per Second Per
Transaction
---------------
---------------
Redo size: 21,327.92
4,135.43
Logical reads: 22,301.97
4,324.29
Block changes: 167.93
32.56
Physical reads: 601.19
116.57
Physical writes: 8.31
1.61
User calls: 191.58
37.15
Parses: 78.20
15.16
Hard parses: 15.28
2.96
Sorts: 23.45
4.55
Logons: 0.23
0.04
Executes: 334.39
64.84
Transactions: 5.16

% Blocks changed per Read: 0.75 Recursive Call %: 65.29
Rollback per transaction %: 4.27 Rows per Sort: 4280.83

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 97.33 In-memory Sort %: 100.00
Library Hit %: 95.32 Soft Parse %: 80.46
Execute to Parse %: 76.61 Latch Hit %: 99.49
Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 94.04 94.02
% SQL with executions>1: 28.31 26.99
% Memory for SQL w/exec>1: 26.11 25.70

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~
% Total
Event Waits Time (s)
Ela Time
-------------------------------------------- ------------ -----------
--------
CPU time 5,177
84.22
db file scattered read 182,425 595
9.69
db file sequential read 104,046 212
3.45
log file sync 18,224 77
1.25
latch free 2,531 20
.32
-------------------------------------------------------------
Statistic Total per Second
per Trans
--------------------------------- ------------------ --------------
------------
CPU used by this session 517,708 143.7
27.9
CPU used when call started 517,574 143.7
27.9
CR blocks created 2,461 0.7
0.1
DBWR buffers scanned 9,577 2.7
0.5
DBWR checkpoint buffers written 7,706 2.1
0.4
DBWR checkpoints 2 0.0
0.0
DBWR free buffers found 9,560 2.7
0.5
DBWR lru scans 8 0.0
0.0
DBWR make free requests 8 0.0
0.0
DBWR summed scan depth 9,577 2.7
0.5
DBWR transaction table writes 20 0.0
0.0
DBWR undo block writes 2,700 0.8
0.2
SQL*Net roundtrips to/from client 475,115 131.9
25.6
SQL*Net roundtrips to/from dblink 0 0.0
0.0
active txn count during cleanout 1,034 0.3
0.1
background checkpoints completed 1 0.0
0.0
background checkpoints started 2 0.0
0.0
background timeouts 4,389 1.2
0.2
branch node splits 1 0.0
0.0
buffer is not pinned count 65,452,475 18,166.1
3,522.4
buffer is pinned count 125,721,967 34,893.7
6,765.8
index fetch by key 113,983,237 31,635.7
6,134.1
index scans kdiixs1 4,294,754 1,192.0
231.1
session logical reads 80,354,005 22,302.0
4,324.3
session pga memory 80,554,320 22,357.6
4,335.1
session pga memory max 240,183,028 66,662.0
12,925.6
session uga memory 4,377,641,540 1,214,999.0
235,585.1
session uga memory max 885,522,568 245,773.7
47,654.9
shared hash latch upgrades - no w 4,020,072 1,115.8
216.3
shared hash latch upgrades - wait 1,830 0.5
0.1
sorts (memory) 84,508 23.5
4.6
sorts (rows) 361,764,006 100,406.3
19,468.5
switch current to new buffer 23,142 6.4
1.3
table fetch by rowid 5,500,640 1,526.7
296.0
table fetch continued row 517,704 143.7
27.9
table scan blocks gotten 61,677,018 17,118.2
3,319.2
table scan rows gotten 8,963,725,778 2,487,850.6
482,387.6
table scans (long tables) 2,592 0.7
0.1
table scans (short tables) 2,231,741 619.4
120.1

Tablespace
------------------------------
Av Av Av Av Buffer
Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits
Wt(ms)
-------------- ------- ------ ------- ------------ -------- ----------
------
USERS
240,076 67 2.5 7.5 225 0 661
1.4
DOC
22,986 6 3.6 8.8 267 0 0
0.0
ADT
9,981 3 4.3 8.1 1,470 0 4
0.0
FCB
8,275 2 4.2 7.6 118 0 3
0.0
DOCIDX
2,419 1 5.3 1.0 1,481 0 2
0.0
TEMP
1,351 0 4.2 15.0 1,479 0 0
0.0
UNDOTBS1
1 0 20.0 1.0 2,723 1 10
0.0
FCBIDX
419 0 21.3 1.0 453 0 81
2.2
PAGEIDX
407 0 16.3 1.0 359 0 0
0.0

On Dec 14, 10:05 am, emdproduct...@hotmail.com wrote:
> Our system is slow as hell at 10-11 time.
>
> How is my report, could somebody help me to diasnotic the problem?
> Thanks very much for your help.
>
> Snap Id Snap Time Sessions Curs/Sess Comment
> --------- ------------------ -------- ---------
> -------------------
> Begin Snap: 25 13-Dec-06 10:00:03 94 20.0
> End Snap: 26 13-Dec-06 11:00:06 112 20.1
> Elapsed: 60.05 (mins)
>
> Cache Sizes (end)
> ~~~~~~~~~~~~~~~~~
> Buffer Cache: 344M Std Block Size:
> 8K
> Shared Pool Size: 352M Log Buffer:
> 1,024K
>
> Load Profile
> ~~~~~~~~~~~~ Per Second Per
> Transaction
> ---------------
> ---------------
> Redo size: 21,327.92
> 4,135.43
> Logical reads: 22,301.97
> 4,324.29
> Block changes: 167.93
> 32.56
> Physical reads: 601.19
> 116.57
> Physical writes: 8.31
> 1.61
> User calls: 191.58
> 37.15
> Parses: 78.20
> 15.16
> Hard parses: 15.28
> 2.96
> Sorts: 23.45
> 4.55
> Logons: 0.23
> 0.04
> Executes: 334.39
> 64.84
> Transactions: 5.16
>
> % Blocks changed per Read: 0.75 Recursive Call %: 65.29
> Rollback per transaction %: 4.27 Rows per Sort: 4280.83
>
> Instance Efficiency Percentages (Target 100%)
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> Buffer Nowait %: 100.00 Redo NoWait %: 100.00
> Buffer Hit %: 97.33 In-memory Sort %: 100.00
> Library Hit %: 95.32 Soft Parse %: 80.46
> Execute to Parse %: 76.61 Latch Hit %: 99.49
> Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36
>
> Shared Pool Statistics Begin End
> ------ ------
> Memory Usage %: 94.04 94.02
> % SQL with executions>1: 28.31 26.99
> % Memory for SQL w/exec>1: 26.11 25.70
>
> Top 5 Timed Events
> ~~~~~~~~~~~~~~~~~~
> % Total
> Event Waits Time (s)
> Ela Time
> -------------------------------------------- ------------ -----------
> --------
> CPU time 5,177
> 84.22
> db file scattered read 182,425 595
> 9.69
> db file sequential read 104,046 212
> 3.45
> log file sync 18,224 77
> 1.25
> latch free 2,531 20
> .32
> -------------------------------------------------------------
> Statistic Total per Second
> per Trans
> --------------------------------- ------------------ --------------
> ------------
> CPU used by this session 517,708 143.7
> 27.9
> CPU used when call started 517,574 143.7
> 27.9
> CR blocks created 2,461 0.7
> 0.1
> DBWR buffers scanned 9,577 2.7
> 0.5
> DBWR checkpoint buffers written 7,706 2.1
> 0.4
> DBWR checkpoints 2 0.0
> 0.0
> DBWR free buffers found 9,560 2.7
> 0.5
> DBWR lru scans 8 0.0
> 0.0
> DBWR make free requests 8 0.0
> 0.0
> DBWR summed scan depth 9,577 2.7
> 0.5
> DBWR transaction table writes 20 0.0
> 0.0
> DBWR undo block writes 2,700 0.8
> 0.2
> SQL*Net roundtrips to/from client 475,115 131.9
> 25.6
> SQL*Net roundtrips to/from dblink 0 0.0
> 0.0
> active txn count during cleanout 1,034 0.3
> 0.1
> background checkpoints completed 1 0.0
> 0.0
> background checkpoints started 2 0.0
> 0.0
> background timeouts 4,389 1.2
> 0.2
> branch node splits 1 0.0
> 0.0
> buffer is not pinned count 65,452,475 18,166.1
> 3,522.4
> buffer is pinned count 125,721,967 34,893.7
> 6,765.8
> index fetch by key 113,983,237 31,635.7
> 6,134.1
> index scans kdiixs1 4,294,754 1,192.0
> 231.1
> session logical reads 80,354,005 22,302.0
> 4,324.3
> session pga memory 80,554,320 22,357.6
> 4,335.1
> session pga memory max 240,183,028 66,662.0
> 12,925.6
> session uga memory 4,377,641,540 1,214,999.0
> 235,585.1
> session uga memory max 885,522,568 245,773.7
> 47,654.9
> shared hash latch upgrades - no w 4,020,072 1,115.8
> 216.3
> shared hash latch upgrades - wait 1,830 0.5
> 0.1
> sorts (memory) 84,508 23.5
> 4.6
> sorts (rows) 361,764,006 100,406.3
> 19,468.5
> switch current to new buffer 23,142 6.4
> 1.3
> table fetch by rowid 5,500,640 1,526.7
> 296.0
> table fetch continued row 517,704 143.7
> 27.9
> table scan blocks gotten 61,677,018 17,118.2
> 3,319.2
> table scan rows gotten 8,963,725,778 2,487,850.6
> 482,387.6
> table scans (long tables) 2,592 0.7
> 0.1
> table scans (short tables) 2,231,741 619.4
> 120.1
>
> Tablespace
> ------------------------------
> Av Av Av Av Buffer
> Av Buf
> Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits
> Wt(ms)
> -------------- ------- ------ ------- ------------ -------- ----------
> ------
> USERS
> 240,076 67 2.5 7.5 225 0 661
> 1.4
> DOC
> 22,986 6 3.6 8.8 267 0 0
> 0.0
> ADT
> 9,981 3 4.3 8.1 1,470 0 4
> 0.0
> FCB
> 8,275 2 4.2 7.6 118 0 3
> 0.0
> DOCIDX
> 2,419 1 5.3 1.0 1,481 0 2
> 0.0
> TEMP
> 1,351 0 4.2 15.0 1,479 0 0
> 0.0
> UNDOTBS1
> 1 0 20.0 1.0 2,723 1 10
> 0.0
> FCBIDX
> 419 0 21.3 1.0 453 0 81
> 2.2
> PAGEIDX
> 407 0 16.3 1.0 359 0 0
> 0.0

You are starving the CPU (see top 5 events, always start there), by
issuing way too much sorts (see 'sort (rows)'), too many chained rows
(see 'table fetch continued row') and way way too much full table scans
(see 'tablescans (short tables)' and 'tablescans (long tables)'
You must have inefficient and untuned sql. You can track down the SQL
starving your system, by running statspack(5).

--
Sybrand Bakker
Senior Oracle DBA

> You are starving the CPU (see top 5 events, always start there), by
> issuing way too much sorts (see 'sort (rows)'), too many chained rows
> (see 'table fetch continued row') and way way too much full table scans
> (see 'tablescans (short tables)' and 'tablescans (long tables)'
> You must have inefficient and untuned sql. You can track down the SQL
> starving your system, by running statspack(5).
>
> --
> Sybrand Bakker

Thanks. But I think we had too much index scan as well, did you see we
have a high logical reads?

Also, could you comment on
======
Execute to Parse %: 76.61 Latch Hit %: 99.49
Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36

Shared Pool Statistics Begin End
------ ------
Memory Usage %: 94.04 94.02
% SQL with executions>1: 28.31 26.99
% Memory for SQL w/exec>1: 26.11 25.70
==========
Does it mean bind variable is not used here?

On Dec 14, 10:24 am, emdproduct...@hotmail.com wrote:
> > You are starving the CPU (see top 5 events, always start there), by
> > issuing way too much sorts (see 'sort (rows)'), too many chained rows
> > (see 'table fetch continued row') and way way too much full table scans
> > (see 'tablescans (short tables)' and 'tablescans (long tables)'
> > You must have inefficient and untuned sql. You can track down the SQL
> > starving your system, by running statspack(5).
>
> > --
> > Sybrand BakkerThanks. But I think we had too much index scan as well, did you see we
> have a high logical reads?
>
> Also, could you comment on
> ======
> Execute to Parse %: 76.61 Latch Hit %: 99.49
> Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36
>
> Shared Pool Statistics Begin End
> ------ ------
> Memory Usage %: 94.04 94.02
> % SQL with executions>1: 28.31 26.99
> % Memory for SQL w/exec>1: 26.11 25.70
> ==========
> Does it mean bind variable is not used here?

Logical reads in itself are used for any access, so not necessarily
related to index full scans. A high number of logical reads in itself
points to inefficient and untuned SQL.
Statspack on level 5 in conjunction with spreport will dump the top 5
offenders.
I've always been bad at interpreting the parse statistics. The
percentage of sql statements with more than 1 executions seems to be
low. However: your parse cpu to parse elapsed is almost 1. Higher than
1 is good.
It more looks like your database is being hit by random adhoc SQL.
Not using bindvariables will show once you run statspack on level 5.

--
Sybrand Bakker
Senior Oracle DBA

<emdproduction@hotmail.com> wrote in message
news:1166088247.249368.171390@f1g2000cwa.googlegro ups.com...
>
>> You are starving the CPU (see top 5 events, always start there), by
>> issuing way too much sorts (see 'sort (rows)'), too many chained rows
>> (see 'table fetch continued row') and way way too much full table scans
>> (see 'tablescans (short tables)' and 'tablescans (long tables)'
>> You must have inefficient and untuned sql. You can track down the SQL
>> starving your system, by running statspack(5).
>>
>> --
>> Sybrand Bakker
>
> Thanks. But I think we had too much index scan as well, did you see we
> have a high logical reads?
>
> Also, could you comment on
> ======
> Execute to Parse %: 76.61 Latch Hit %: 99.49
> Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36
>
> Shared Pool Statistics Begin End
> ------ ------
> Memory Usage %: 94.04 94.02
> % SQL with executions>1: 28.31 26.99
> % Memory for SQL w/exec>1: 26.11 25.70
> ==========
> Does it mean bind variable is not used here?
>


If I have this correctly, you want help to diagnose the
problem, so long as the help tells you that the problem
is what you want it to be ?

Sybrand made some very sensible observations - you
are doing an extraordinary amount of tablescanning

table fetch by rowid 5,500,640
table scan rows gotten 8,963,725,778

If it takes just 500 nanoseconds to examine and discard
every row, that's 4,300 CPU seconds of the 5,200 you
report. So your first suspicion should be inefficient SQL.

Of course, it is possible that the perceived slowness has
nothing to do with the CPU burn, maybe it's wait time -
and 515 seconds of your wait time is tablescans (or
index fast full scans) so you need to check for inefficient
SQL (again) in the critical path of the jobs which are
"slow as hell"


The figures suggest that your parse costs are not
terribly significant at present (on average).

--
Regards

Jonathan Lewis
http://jonathanlewis.wordpress.com

Author: Cost Based Oracle: Fundamentals
http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html

The Co-operative Oracle Users' FAQ
http://www.jlcomp.demon.co.uk/faq/ind_faq.html

Jonathan Lewis wrote:
> <emdproduction@hotmail.com> wrote in message
> news:1166088247.249368.171390@f1g2000cwa.googlegro ups.com...
> >
> >> You are starving the CPU (see top 5 events, always start there), by
> >> issuing way too much sorts (see 'sort (rows)'), too many chained rows
> >> (see 'table fetch continued row') and way way too much full table scans
> >> (see 'tablescans (short tables)' and 'tablescans (long tables)'
> >> You must have inefficient and untuned sql. You can track down the SQL
> >> starving your system, by running statspack(5).
> >>
> >> --
> >> Sybrand Bakker
> >
> > Thanks. But I think we had too much index scan as well, did you see we
> > have a high logical reads?
> >
> > Also, could you comment on
> > ======
> > Execute to Parse %: 76.61 Latch Hit %: 99.49
> > Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36
> >
> > Shared Pool Statistics Begin End
> > ------ ------
> > Memory Usage %: 94.04 94.02
> > % SQL with executions>1: 28.31 26.99
> > % Memory for SQL w/exec>1: 26.11 25.70
> > ==========
> > Does it mean bind variable is not used here?
> >
>
>
> If I have this correctly, you want help to diagnose the
> problem, so long as the help tells you that the problem
> is what you want it to be ?
>
> Sybrand made some very sensible observations - you
> are doing an extraordinary amount of tablescanning
>
> table fetch by rowid 5,500,640
> table scan rows gotten 8,963,725,778
>
> If it takes just 500 nanoseconds to examine and discard
> every row, that's 4,300 CPU seconds of the 5,200 you
> report. So your first suspicion should be inefficient SQL.
>
> Of course, it is possible that the perceived slowness has
> nothing to do with the CPU burn, maybe it's wait time -
> and 515 seconds of your wait time is tablescans (or
> index fast full scans) so you need to check for inefficient
> SQL (again) in the critical path of the jobs which are
> "slow as hell"
>
>
> The figures suggest that your parse costs are not
> terribly significant at present (on average).
>
> --
> Regards
>
> Jonathan Lewis
> http://jonathanlewis.wordpress.com
>
> Author: Cost Based Oracle: Fundamentals
> http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html
>
> The Co-operative Oracle Users' FAQ
> http://www.jlcomp.demon.co.uk/faq/ind_faq.html

Johathan,

Thanks very much for your help. I really appreciated. I just want to
make sure my suspicion is correct or not.

In our system, we have a large "cached buffers chain" contention, I
used your method on internet, and they all points at a few DB blocks on
2 tables. I wonder is it something in the application desing that
cause the slowness, do you think we need to upgrade our hardware can
solve this problem?

archive process latch 82 0.0 0
0
cache buffer handles 212,771 0.0 0.0 0
0
cache buffers chains 162,172,226 0.7 0.0 0
4,170,498 0.0
cache buffers lru chain 30,906 0.1 0.1 0
6,132,286 0.1


Latch Name Requests Misses Sleeps
Sleeps 1->4
-------------------------- -------------- ----------- -----------
------------
cache buffers chains 162,172,226 1,075,291 2,068
0/0/0/0/0
library cache 7,413,632 44,110 130
43981/128/1/
0/0
library cache pin 4,203,089 16,818 9
16809/9/0/0/
0
row cache objects 21,365,569 16,195 2
16193/2/0/0/
0
row cache enqueue latch 21,358,822 14,016 1
14015/1/0/0/
0
shared pool 4,320,950 10,965 306
10660/304/1/
0/0

emdproduction@hotmail.com wrote:
> > You are starving the CPU (see top 5 events, always start there), by
> > issuing way too much sorts (see 'sort (rows)'), too many chained rows
> > (see 'table fetch continued row') and way way too much full table scans
> > (see 'tablescans (short tables)' and 'tablescans (long tables)'
> > You must have inefficient and untuned sql. You can track down the SQL
> > starving your system, by running statspack(5).
> >
> > --
> > Sybrand Bakker
>
> Thanks. But I think we had too much index scan as well, did you see we
> have a high logical reads?
>
> Also, could you comment on
> ======
> Execute to Parse %: 76.61 Latch Hit %: 99.49
> Parse CPU to Parse Elapsd %: 97.32 % Non-Parse CPU: 92.36
>
> Shared Pool Statistics Begin End
> ------ ------
> Memory Usage %: 94.04 94.02
> % SQL with executions>1: 28.31 26.99
> % Memory for SQL w/exec>1: 26.11 25.70
> ==========
> Does it mean bind variable is not used here?

If you have excessive table scans only from 10 to 11, it could be
something as simple as not having a needed index for something that
runs then. You should follow Jonathan and Sybrand's advice and find
out exactly which SQL are problematic, rather than try to second guess
from the summarized statistics.

As to too much index scanning, that also depends on the specific code
that is running, so that is where you need to get runtime plans for the
code, and figure out what is happening with the optimizer that it isn't
making the best decision.

If it turns out that the full scans are a correct optimization for that
particular code, consider putting those tables or indices in a recycle
pool. I've seen magical results from that (mostly due to reducing
buffer thrashing of all the other tables that don't need to go into
another pool). See v$bh in the performance tuning manual for figuring
out which objects might be appropriate (and Jonathan's site and blog
for more precise details).

More generally, sometimes badly tuned code makes everything else go
downhill fast. That is one reason why most modern tuning methodologies
show that most performance problems are due to badly tuned sql. If you
start making overgeneralizations about the problem being a system
problem, you could make it worse by incorrect system tuning.

The bind variable issue makes a difference when people issue
substantially the same code using literals to make oracle think the
code is different. Again, you would need to know the specific code and
what users do to know if this is an issue. There is a lot about this
on asktom and in Tom Kyte's books.

See the advisors (select view_name from user_views where view_name like
'%ADV%'; or OEM pga memory usage details) about too many sorts.

jg
--
@home.com is bogus.
http://lkml.org/lkml/2006/12/13/370