AWR Sample Report
raja
I have a small part ( output ) of AWR Report. Can anyone help me on
this, to interpret the AWR Output...
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 8193 17-Oct-08 16:00:54 90 62.7
End Snap: 8194 17-Oct-08 16:01:26 89 63.4
Elapsed: 0.52 (mins)
DB Time: 1.63 (mins)
Report Summary
Cache Sizes
Begin End
Buffer Cache: 6,832M 6,832M Std Block Size: 8K
Shared Pool Size: 1,264M 1,264M Log Buffer: 14,344K
Load Profile
Per Second Per Transaction
Redo size: 42,200.64 120,268.00
Logical reads: 2,312.58 6,590.64
Block changes: 133.69 381.00
Physical reads: 359.82 1,025.45
Physical writes:540.97 1,541.73
User calls: 20.45 58.27
Parses: 8.93 25.45
Hard parses: 0.19 0.55
Sorts: 4.27 12.18
Logons: 0.03 0.09
Executes: 16.27 46.36
Transactions: 0.35
% Blocks changed per Read: 5.78 Recursive Call %: 67.11
Rollback per transaction %: 0.00 Rows per Sort: 2095.84
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 84.50 In-memory Sort %: 100.00
Library Hit %: 97.78 Soft Parse %: 97.86
Execute to Parse %: 45.10 Latch Hit %: 100.00
Parse CPU to Parse Elapsd %: 72.41 % Non-Parse CPU: 99.11
Shared Pool Statistics
Begin End
Memory Usage %: 92.02 92.04
% SQL with executions>1: 99.23 99.08
% Memory for SQL w/exec>1: 99.18 99.24
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
db file sequential read 11,529 32 3 32.6 User I/O
CPU time 23 24.0
Log archive I/O 411 17 42 17.5 System I/O
db file parallel write 674 12 18 12.6 System I/O
Backup: sbtwrite2 491 8 15 7.7 Administrative
Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms)
Waits /txn
db file sequential read 11,529 0.00 32 3 1,048.09
Log archive I/O 411 0.00 17 42 37.36
db file parallel write 674 0.00 12 18 61.27
Backup: sbtwrite2 491 0.00 8 15 44.64
log file sequential read 342 0.00 2 5 31.09
RMAN backup & recovery I/O 46 0.00 0 4 4.18
control file parallel write 30 0.00 0 5 2.73
log file parallel write 22 0.00 0 6 2.00
control file sequential read 19,914 0.00 0 0 1,810.36
log file sync 3 0.00 0 11 0.27
Backup: sbtbackup 1 0.00 0 22 0.09
direct path read 40 0.00 0 0 3.64
direct path write 40 0.00 0 0 3.64
SQL*Net more data to client 71 0.00 0 0 6.45
SQL*Net message to client 517 0.00 0 0 47.00
SQL*Net more data from client 8 0.00 0 0 0.73
direct path write temp 9 0.00 0 0 0.82
SQL*Net message from client 517 0.00 4,112 7954 47.00
Streams AQ: qmn slave idle wait 1 0.00 27 27344 0.09
Streams AQ: qmn coordinator idle wait 2 50.00 27 13672 0.18
jobq slave wait 3 100.00 9 2930 0.27
Background Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /
txn
db file parallel write 667 0.00 12 18 60.64
log file parallel write 22 0.00 0 6 2.00
control file parallel write 22 0.00 0 5 2.00
direct path read 40 0.00 0 0 3.64
direct path write 40 0.00 0 0 3.64
control file sequential read 17 0.00 0 0 1.55
rdbms ipc message 174 90.23 408 2347 15.82
pmon timer 10 100.00 29 2930 0.91
Streams AQ: qmn slave idle wait 1 0.00 27 27344 0.09
Streams AQ: qmn coordinator idle wait 2 50.00 27 13672 0.18
Operating System Statistics
Statistic Total
NUM_LCPUS 0
NUM_VCPUS 0
AVG_BUSY_TIME 808
AVG_IDLE_TIME 2,298
AVG_IOWAIT_TIME 556
AVG_SYS_TIME 154
AVG_USER_TIME 652
BUSY_TIME 11,330
IDLE_TIME 32,202
IOWAIT_TIME 7,812
SYS_TIME 2,178
USER_TIME 9,152
LOAD 0
OS_CPU_WAIT_TIME 12,600
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 82,678,116,352
NUM_CPUS 14
NUM_CPU_CORES 7
Instance Activity Stats
Statistic Total per Second per Trans
CPU used by this session 691 22.04 62.82
CPU used when call started 874 27.88 79.45
CR blocks created 5 0.16 0.45
Cached Commit SCN referenced 39,329 1,254.55 3,575.36
Commit SCN cached 3 0.10 0.27
DB time 11,961 381.54 1,087.36
DBWR checkpoint buffers written 9,285 296.18 844.09
DBWR checkpoints 0 0.00 0.00
DBWR object drop buffers written 0 0.00 0.00
DBWR parallel query checkpoint buffers written 0 0.00 0.00
DBWR revisited being-written buffer 0 0.00 0.00
DBWR tablespace checkpoint buffers written 0 0.00 0.00
DBWR thread checkpoint buffers written 0 0.00 0.00
DBWR transaction table writes 0 0.00 0.00
DBWR undo block writes 3,343 106.64 303.91
DFO trees parallelized 0 0.00 0.00
IMU CR rollbacks 0 0.00 0.00
IMU Flushes 3 0.10 0.27
IMU Redo allocation size 30,844 983.89 2,804.00
IMU commits 8 0.26 0.73
IMU contention 0 0.00 0.00
IMU ktichg flush 0 0.00 0.00
IMU pool not allocated 0 0.00 0.00
IMU recursive-transaction flush 0 0.00 0.00
IMU undo allocation size 61,992 1,977.48 5,635.64
IMU- failed to get a private strand 0 0.00 0.00
Misses for writing mapping 0 0.00 0.00
PX local messages recv'd 0 0.00 0.00
PX local messages sent 0 0.00 0.00
Parallel operations not downgraded 0 0.00 0.00
SMON posted for undo segment shrink 0 0.00 0.00
SQL*Net roundtrips to/from client 503 16.05 45.73
SQL*Net roundtrips to/from dblink 0 0.00 0.00
active txn count during cleanout 35 1.12 3.18
application wait time 0 0.00 0.00
background checkpoints completed 1 0.03 0.09
background checkpoints started 0 0.00 0.00
background timeouts 160 5.10 14.55
branch node splits 0 0.00 0.00
buffer is not pinned count 45,762 1,459.76 4,160.18
buffer is pinned count 418,313 13,343.74 38,028.45
bytes received via SQL*Net from client 82,383 2,627.93 7,489.36
bytes received via SQL*Net from dblink 0 0.00 0.00
bytes sent via SQL*Net to client 271,245 8,652.43 24,658.64
bytes sent via SQL*Net to dblink 0 0.00 0.00
calls to get snapshot scn: kcmgss 847 27.02 77.00
calls to kcmgas 106 3.38 9.64
calls to kcmgcs 58 1.85 5.27
change write time 5 0.16 0.45
cleanout - number of ktugct calls 300 9.57 27.27
cleanouts and rollbacks - consistent read gets 0 0.00 0.00
cleanouts only - consistent read gets 264 8.42 24.00
cluster key scan block gets 125 3.99 11.36
cluster key scans 63 2.01 5.73
commit batch performed 0 0.00 0.00
commit batch requested 0 0.00 0.00
commit batch/immediate performed 0 0.00 0.00
commit batch/immediate requested 0 0.00 0.00
commit cleanout failures: block lost 0 0.00 0.00
commit cleanout failures: buffer being written 0 0.00 0.00
commit cleanout failures: callback failure 2 0.06 0.18
commit cleanout failures: cannot pin 0 0.00 0.00
commit cleanouts 331 10.56 30.09
commit cleanouts successfully completed 329 10.49 29.91
commit immediate performed 0 0.00 0.00
commit immediate requested 0 0.00 0.00
commit txn count during cleanout 303 9.67 27.55
concurrency wait time 0 0.00 0.00
consistent changes 9 0.29 0.82
consistent gets 69,089 2,203.87 6,280.82
consistent gets - examination 3,549 113.21 322.64
consistent gets direct 0 0.00 0.00
consistent gets from cache 69,089 2,203.87 6,280.82
current blocks converted for CR 0 0.00 0.00
cursor authentications 4 0.13 0.36
data blocks consistent reads - undo records applied 5 0.16 0.45
db block changes 4,191 133.69 381.00
db block gets 3,357 107.08 305.18
db block gets direct 0 0.00 0.00
db block gets from cache 3,357 107.08 305.18
deferred (CURRENT) block cleanout applications 250 7.97 22.73
dirty buffers inspected 3,050 97.29 277.27
enqueue conversions 9 0.29 0.82
enqueue releases 474 15.12 43.09
enqueue requests 477 15.22 43.36
enqueue timeouts 0 0.00 0.00
enqueue waits 0 0.00 0.00
execute count 510 16.27 46.36
failed probes on index block reclamation 0 0.00 0.00
free buffer inspected 13,135 418.99 1,194.09
free buffer requested 11,327 361.32 1,029.73
heap block compress 24 0.77 2.18
hot buffers moved to head of LRU 4,565 145.62 415.00
immediate (CR) block cleanout applications 264 8.42 24.00
immediate (CURRENT) block cleanout applications 59 1.88 5.36
index crx upgrade (found) 0 0.00 0.00
index crx upgrade (positioned) 35 1.12 3.18
index fast full scans (full) 2 0.06 0.18
index fast full scans (rowid ranges) 0 0.00 0.00
index fetch by key 1,416 45.17 128.73
index scans kdiixs1 528 16.84 48.00
java call heap collected bytes 0 0.00 0.00
java call heap collected count 0 0.00 0.00
java call heap gc count 0 0.00 0.00
java call heap live object count 0 0.00 0.00
java call heap live object count max 0 0.00 0.00
java call heap live size 0 0.00 0.00
java call heap live size max 0 0.00 0.00
java call heap object count 0 0.00 0.00
java call heap object count max 0 0.00 0.00
java call heap total size 0 0.00 0.00
java call heap total size max 0 0.00 0.00
java call heap used size 0 0.00 0.00
java call heap used size max 0 0.00 0.00
leaf node 90-10 splits 6 0.19 0.55
leaf node splits 9 0.29 0.82
lob reads 1 0.03 0.09
lob writes 75 2.39 6.82
lob writes unaligned 75 2.39 6.82
logons cumulative 1 0.03 0.09
messages received 706 22.52 64.18
messages sent 706 22.52 64.18
no buffer to keep pinned count 0 0.00 0.00
no work - consistent read gets 64,846 2,068.52 5,895.09
opened cursors cumulative 269 8.58 24.45
parse count (failures) 0 0.00 0.00
parse count (hard) 6 0.19 0.55
parse count (total) 280 8.93 25.45
parse time cpu 21 0.67 1.91
parse time elapsed 29 0.93 2.64
physical read IO requests 11,280 359.82 1,025.45
physical read bytes 92,405,760 2,947,646.18 8,400,523.64
physical read total IO requests 31,707 1,011.42 2,882.45
physical read total bytes 755,145,216 24,088,335.07 68,649,565.09
physical read total multi block requests 482 15.38 43.82
physical reads 11,280 359.82 1,025.45
physical reads cache 11,240 358.54 1,021.82
physical reads cache prefetch 0 0.00 0.00
physical reads direct 40 1.28 3.64
physical reads direct (lob) 0 0.00 0.00
physical reads direct temporary tablespace 0 0.00 0.00
physical reads prefetch warmup 0 0.00 0.00
physical write IO requests 3,598 114.77 327.09
physical write bytes 138,928,128 4,431,660.60 12,629,829.82
physical write total IO requests 3,942 125.75 358.36
physical write total bytes 472,314,368 15,066,329.64 42,937,669.82
physical write total multi block requests 1,960 62.52 178.18
physical writes 16,959 540.97 1,541.73
physical writes direct 190 6.06 17.27
physical writes direct (lob) 0 0.00 0.00
physical writes direct temporary tablespace 150 4.78 13.64
physical writes from cache 16,769 534.91 1,524.45
physical writes non checkpoint 12,468 397.72 1,133.45
pinned buffers inspected 0 0.00 0.00
prefetch warmup blocks aged out before use 0 0.00 0.00
prefetched blocks aged out before use 0 0.00 0.00
process last non-idle time 17 0.54 1.55
queries parallelized 0 0.00 0.00
recursive aborts on index block reclamation 0 0.00 0.00
recursive calls 1,308 41.72 118.91
recursive cpu usage 364 11.61 33.09
redo blocks written 2,778 88.62 252.55
redo buffer allocation retries 0 0.00 0.00
redo entries 2,947 94.01 267.91
redo log space requests 0 0.00 0.00
redo log space wait time 0 0.00 0.00
redo ordering marks 55 1.75 5.00
redo size 1,322,948 42,200.64 120,268.00
redo subscn max counts 414 13.21 37.64
redo synch time 6 0.19 0.55
redo synch writes 104 3.32 9.45
redo wastage 6,808 217.17 618.91
redo write time 18 0.57 1.64
redo writer latching time 0 0.00 0.00
redo writes 25 0.80 2.27
rollback changes - undo records applied 0 0.00 0.00
rollbacks only - consistent read gets 5 0.16 0.45
rows fetched via callback 1,087 34.67 98.82
session connect time 0 0.00 0.00
session cursor cache hits 173 5.52 15.73
session logical reads 72,497 2,312.58 6,590.64
session pga memory 66,216,800 2,112,246.00 6,019,709.09
session pga memory max 33,121,120 1,056,528.76 3,011,010.91
session uga memory 82,856,048 2,643,020.45 7,532,368.00
session uga memory max 87,060,448 2,777,136.37 7,914,586.18
shared hash latch upgrades - no wait 139 4.43 12.64
shared hash latch upgrades - wait 0 0.00 0.00
sorts (disk) 0 0.00 0.00
sorts (memory) 134 4.27 12.18
sorts (rows) 280,843 8,958.60 25,531.18
sql area evicted 0 0.00 0.00
sql area purged 0 0.00 0.00
summed dirty queue length 4,669 148.94 424.45
switch current to new buffer 2 0.06 0.18
table fetch by rowid 231,204 7,375.16 21,018.55
table fetch continued row 3 0.10 0.27
table scan blocks gotten 18,943 604.26 1,722.09
table scan rows gotten 1,789,586 57,085.90 162,689.64
table scans (cache partitions) 0 0.00 0.00
table scans (direct read) 0 0.00 0.00
table scans (long tables) 0 0.00 0.00
table scans (rowid ranges) 0 0.00 0.00
table scans (short tables) 53 1.69 4.82
total number of times SMON posted 0 0.00 0.00
transaction rollbacks 0 0.00 0.00
transaction tables consistent read rollbacks 0 0.00 0.00
transaction tables consistent reads - undo records applied 0 0.00
0.00
undo change vector size 285,652 9,112.00 25,968.36
user I/O wait time 3,105 99.05 282.27
user calls 641 20.45 58.27
user commits 11 0.35 1.00
user rollbacks 0 0.00 0.00
workarea executions - multipass 0 0.00 0.00
workarea executions - onepass 0 0.00 0.00
workarea executions - optimal 117 3.73 10.64
write clones created in background 0 0.00 0.00
write clones created in foreground 0 0.00 0.00
Buffer Pool Statistics
P Number of Buffers Pool Hit% Buffer Gets Physical Reads Physical
Writes Free Buff Wait Writ Comp Wait Buffer Busy Waits
D 845,033 85 75,249 11,310 16,769 0 0 0
PGA Aggr Summary
PGA Cache Hit % W/A MB Processed Extra W/A MB Read/Written
100.00 28 0
Please explain me the AWR Report.
Thanks in Advance.
With Regards,
Raja.
sybrandb
> Hi,
>
> I have a small part ( output ) of AWR Report. Can anyone help me on
> this, to interpret the AWR Output...
>
> Snap Id Snap Time Sessions Cursors/Session
> Begin Snap: 8193 17-Oct-08 16:00:54 90 62.7
> End Snap: 8194 17-Oct-08 16:01:26 89 63.4
> Elapsed: 0.52 (mins)
> DB Time: 1.63 (mins)
>
> Report Summary
> Cache Sizes
> Begin End
> Buffer Cache: 6,832M 6,832M Std Block Size: 8K
> Shared Pool Size: 1,264M 1,264M Log Buffer: 14,344K
>
> Load Profile
>
> Per Second Per Transaction
> Redo size: 42,200.64 120,268.00
> Logical reads: 2,312.58 6,590.64
> Block changes: 133.69 381.00
I don't think this is 'part' of an AWR report, it is almost all. Even
worse: it is unformatted and barely legible.
Even worse: it is yet another attempt of you in this and various other
forums to request others to abstract the online documentation.
If you are not prepared to read the online documentation, Oracle is
not for you. You can not expect volunteers to do for free what you can
do easily on your own.
I would thank you in advance for not posting any RTFM questions in the
furture or better still staying away here.
With regards,
--
Sybrand Bakker
Senior Oracle DBA
Charles Hooper
> Hi,
>
> I have a small part ( output ) of AWR Report. Can anyone help me on
> this, to interpret the AWR Output...
>
> Snap Id Snap Time Sessions Cursors/Session
> Begin Snap: 8193 17-Oct-08 16:00:54 90 62.7
> End Snap: 8194 17-Oct-08 16:01:26 89 63.4
> Elapsed: 0.52 (mins)
> DB Time: 1.63 (mins)
>
> Load Profile
>
> Per Second Per Transaction
> Redo size: 42,200.64 120,268.00
> Logical reads: 2,312.58 6,590.64
> Block changes: 133.69 381.00
> Physical reads: 359.82 1,025.45Physical writes:540.97 1,541.73
> Top 5 Timed Events
>
> Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
> db file sequential read 11,529 32 3 32.6 User I/O
> CPU time 23 24.0
> Log archive I/O 411 17 42 17.5 System I/O
> db file parallel write 674 12 18 12.6 System I/O
> Backup: sbtwrite2 491 8 15 7.7 Administrative
>
> Wait Events
>
> Event Waits %Time -outs Total Wait Time (s) Avg wait (ms)
> Waits /txn
> db file sequential read 11,529 0.00 32 3 1,048.09
> Log archive I/O 411 0.00 17 42 37.36
> db file parallel write 674 0.00 12 18 61.27
> Backup: sbtwrite2 491 0.00 8 15 44.64
> log file sequential read 342 0.00 2 5 31.09
> RMAN backup & recovery I/O 46 0.00 0 4 4.18
> control file parallel write 30 0.00 0 5 2.73
> log file parallel write 22 0.00 0 6 2.00
> control file sequential read 19,914 0.00 0 0 1,810.36
> log file sync 3 0.00 0 11 0.27
> Backup: sbtbackup 1 0.00 0 22 0.09
> Operating System Statistics
>
> Statistic Total
> NUM_LCPUS 0
> NUM_VCPUS 0
> AVG_BUSY_TIME 808
> AVG_IDLE_TIME 2,298
> AVG_IOWAIT_TIME 556
> AVG_SYS_TIME 154
> AVG_USER_TIME 652
> BUSY_TIME 11,330
> IDLE_TIME 32,202
> IOWAIT_TIME 7,812
> SYS_TIME 2,178
> USER_TIME 9,152
> LOAD 0
> OS_CPU_WAIT_TIME 12,600
> RSRC_MGR_CPU_WAIT_TIME 0
> PHYSICAL_MEMORY_BYTES 82,678,116,352
> NUM_CPUS 14
> NUM_CPU_CORES 7
(Snip)
> Please explain me the AWR Report.
>
> Thanks in Advance.
>
> With Regards,
> Raja.
Raja, do you feel that the database instance is slow, or is this just
a general request of how to read an AWR/Statspack report?
If you are trying to learn how to read a statspack report, there are
several examples on the Internet, for example this series:
http://jonathanlewis.wordpress.com/category/statspack/
The duration of your AWR report is about 31 seconds, which leads me to
believe that you have isolated the problem to a specific time, or to a
specific process. If the problem has been isolated to a specific
process, I suggest using a 10046 trace at level 8 or 12 for that
process, rather than an extremely short duration AWR report.
There are a couple interesting items in the section of the AWR report
which you posted:
Waits:
Backup: sbtwrite2 (related to an RMAN backup to tape, see Metalink
Note:311068.1)
RMAN backup & recovery I/O (see Metalink Note:311068.1)
db file sequential read, at 32 seconds
So, in this 31 second AWR report, we may have identified a case where
an RMAN backup is slowing some other process. I did not spend much
time looking at the other statistics, as I do not know the intention
of your post.
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
raja
>
> - Show quoted text -
Hi,
Thanks for ur immediate reply.
I want to learn how to interpret the AWR Report.
I was not able to find any docs regarding this in google.
Also, i wanted to have some suggestions regarding the AWR report that
i have posted.
Any docs or URL related to Interpretation of AWR/Statspack report,
Please send them.
Also, any suggestions regarding the AWR Report Output that i have
given, Please provide them too.
With Regards,
Raja.
Charles Hooper
> Hi,
>
> Thanks for ur immediate reply.
>
> I want to learn how to interpret the AWR Report.
> I was not able to find any docs regarding this in google.
> Also, i wanted to have some suggestions regarding the AWR report that
> i have posted.
>
> Any docs or URL related to Interpretation of AWR/Statspack report,
> Please send them.
> Also, any suggestions regarding the AWR Report Output that i have
> given, Please provide them too.
>
> With Regards,
> Raja.
Raja, it is good that you want to understand how to read AWR/Statspack
reports. I highly recommend reading the blog entries at the link that
I previously posted in this thread.
If you have access to Metalink, try a search for the term statspack
With the above search, currently the seventh item returned is
"Systemwide Tuning using STATSPACK Reports" and the tenth item in the
list is "Oracle Performance Diagnostic Guide (OPDG)". Both of those
are very good resources. Somewhere I posted a list of six or more
resources for understanding Statspack reports, but I currently cannot
locate that list.
In my previous post in this thread, I mentioned that I found a couple
interesting wait events, which seem to indicate that an RMAN backup to
tape was in process during the 31 second AWR report, which may be
contributing to a performance problem. I spent a little time looking
at the statistics section of the AWR report:
physical read total bytes 24,088,335.07 per second
physical write total bytes 15,066,329.64 per second
So a question for you to think about when you try to understand your
AWR report: if the disk subsystem is reading on average about 24MB per
second and writing on average about 15MB per second, what happens when
the 11,529 (roughly 370 per second) single block 8KB reads occur
during query execution? Do those 11,529 single block reads occur
immediately, or must they queue behind other read and write requests
as well as wait for the drive heads to relocate over the correct
location on the physical disk?
Steve Howard
Hi Raja,
How big is the database? You full scanned almost 2,000,000 rows in 32
seconds? Granted, you could have a 2,000 row table that was scanned
1000 times in that period, but compared to 231,0000 gets by rowid
(probably index) that seems really high for that period of time.
What does the SQL look like?
HTH,
Steve
sybr...@hccnet.nl
<hoope...@yahoo.com> wrote:
>Raja, it is good that you want to understand how to read AWR/Statspack
>reports. I highly recommend reading the blog entries at the link that
>I previously posted in this thread.
Charles, please do not respond to this person. The only thing he wants
is
- avoid reading the documentatioin
- free abstracts from the documentation as he can't be bothered to
search for it
- you doing HIS work for free.
He is asking similar questions in various newsgroups, all of them boil
down to him getting free consultancy.
Regards,
Charles Hooper
> On Thu, 6 Nov 2008 04:59:04 -0800 (PST), Charles Hooper
>
Sybrand,
I understand your point. It appears that Raja missed most of the
clues I provided to him in my intial post. He did take the time to
visit the link that I provided to him, where he posted the same AWR
report to Jonathan's blog. If nothing else, I wonder how close my
*guess* is to what is really happening in the 31 second time period on
his system. While Raja might not benefit from the clues which have
been provided to him in this thread, there is a chance that the clues
might provide an opportunity to spark performance tuning curiosity in
other readers. Out of personal curiosity, it might be interesting to
see if there are any clues to point the possible cause of an apparent
performance problem in a different direction.
Raja, if you really want to understand what the AWR report is showing,
take a look at the clues provided by Steve Howard, Sybrand, and me in
this thread. Ask yourself why those clues were pointed out in
response to the section of the AWR which you provided, and whether or
not other clues exist in the full AWR report which agree with or
refute the suggestions which were provided. Search the Internet for
the meaning of the various wait events and statistics which have large
values. Take this as an opportunity to learn about AWR/statspack
reports.
raja
Thanks for all your comments / suggestions.
Charles / Steve,
Thanks for ur guidance.
I am just starting / want to interpret the statspack / AWR Report.
So, Please check whether my observations are correct, regarding the
AWR Report.
1. I tried to guess with the "11,529", what you have mentioned.
It is one of the 'Top 5 Timed Events' and its the first one, 'db
file sequential read'.
Is the problem with the index ?
Should i increase the value of PGA AGGREGATE TARGET parameter ?.
2. Also, one of the other 'Top 5 Timed Events' is, 'Backup:
sbtwrite2', which you have mentioned.
Though it is one of the performance degrade, i think it cant be the
actual problem, as it is listed last and any backup process will take
time.
Also, comparitively, 'db file sequential read' looks to be high.
Comparing the above 2 values, Is this due more full table scans /
proper indexes are not created ?
3. Execute to Parse %: 45.10
Parses: 8.93 25.45
Hard parses: 0.19 0.55
Comparing, Looks to be very less.
Does this mean that, many sql are used, which are not used
frequently ?
4. Looking at the data present in IO Status (Tablespace IO Stats and
File IO Stats ), looks like there are more reads on Materialized
Views.
Should we try to tune those Materialized Views ?
Tablespace IO Stats - ordered by IOs (Reads + Writes) desc
Tablespace Reads Av Reads/s Av Rd(ms) Av Blks/Rd Writes Av Writes/s
Buffer Waits Av Buf Wt(ms)
REPADMIN_MVIEWS 10,396 332 2.64 1.00 26 1 0 0.00
UNDO 8 0 2.50 1.00 1,530 49 0 0.00
PWMWI_IND 11 0 1.82 1.00 994 32 0 0.00
PWMWI_TAB 92 3 7.39 1.00 910 29 0 0.00
REPADMIN_IND 830 26 3.04 1.00 54 2 0 0.00
SYSAUX 189 6 7.35 1.00 1 0 0 0.00
TEMP 0 0 0.00 10 0 0 0.00
SYSTEM 4 0 7.50 1.00 1 0 0 0.00
PWM2FA_TAB 1 0 0.00 1.00 3 0 0 0.00
MVIEW_LOGS 1 0 0.00 1.00 1 0 0 0.00
PAMM42M_TAB 1 0 0.00 1.00 1 0 0 0.00
PAMSDFT01 1 0 0.00 1.00 1 0 0 0.00
PWM2FA_IND 1 0 0.00 1.00 1 0 0 0.00
REORG 1 0 0.00 1.00 1 0 0 0.00
TOOLS 1 0 0.00 1.00 1 0 0 0.00
File IO Stats
ordered by Tablespace, File
Tablespace Filename Reads Av Reads/s Av Rd(ms) Av Blks/Rd Writes
Av Writes/s Buffer Waits Av Buf Wt(ms)
MVIEW_LOGS /pamprd4_dbf/mview_logs_f01.dbf 1 0 0.00 1.00 1 0 0 0.00
PAMM42M_TAB /pamprd4_dbf/pamm42m_tab_f01.dbf 1 0 0.00 1.00 1 0 0
0.00
PAMSDFT01 /pamprd4_dbf/pamsdft01_f01.dbf 1 0 0.00 1.00 1 0 0 0.00
PWM2FA_IND /pamprd4_dbf/pwm2fa_ind_f01.dbf 1 0 0.00 1.00 1 0 0 0.00
PWM2FA_TAB /pamprd4_dbf/pwm2fa_tab_f01.dbf 1 0 0.00 1.00 3 0 0 0.00
PWMWI_IND /pamprd4_dbf/pwmwi_ind_f01.dbf 6 0 3.33 1.00 641 20 0 0.00
PWMWI_IND /pamprd4_dbf/pwmwi_ind_f02.dbf 5 0 0.00 1.00 353 11 0 0.00
PWMWI_TAB /pamprd4_dbf/pwmwi_tab_f01.dbf 22 1 5.00 1.00 451 14 0
0.00
PWMWI_TAB /pamprd4_dbf/pwmwi_tab_f02.dbf 70 2 8.14 1.00 459 15 0
0.00
REORG /pamprd4_dbf/reorg.dbf 1 0 0.00 1.00 1 0 0 0.00
REPADMIN_IND /pamprd4_dbf/repadmin_ind_f01.dbf 191 6 4.03 1.00 7
0 0 0.00
REPADMIN_IND /pamprd4_dbf/repadmin_ind_f02.dbf 551 18 1.72 1.00
32 1 0 0.00
REPADMIN_IND /pamprd4_dbf/repadmin_ind_f03.dbf 86 3 9.19 1.00 9
0 0 0.00
REPADMIN_IND /pamprd4_dbf/repadmin_ind_f04.dbf 2 0 5.00 1.00 6 0
0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f01.dbf 754 24 3.26 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f02.dbf 646 21 2.60 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f03.dbf 1,121 36 2.52
1.00 7 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f04.dbf 616 20 2.31 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f05.dbf 457 15 3.79 1.00
4 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f06.dbf 1,096 35 2.27
1.00 1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f07.dbf 260 8 2.92 1.00 1
0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f08.dbf 737 24 3.15 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f09.dbf 1,209 39 2.74
1.00 1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f10.dbf 767 24 2.28 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f11.dbf 836 27 3.18 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f12.dbf 1,019 33 1.72
1.00 2 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f13.dbf 369 12 2.76 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f14.dbf 398 13 2.21 1.00
1 0 0 0.00
REPADMIN_MVIEWS /pamprd4_dbf/repadmin_mviews_f15.dbf 111 4 3.60 1.00 2
0 0 0.00
SYSAUX /pamprd4_dbf/sysaux01.dbf 189 6 7.35 1.00 1 0 0 0.00
SYSTEM /pamprd4_dbf/system_f01.dbf 4 0 7.50 1.00 1 0 0 0.00
TEMP /pamprd4_dbf/temp_f01.dbf 0 0 10 0 0
TOOLS /pamprd4_dbf/tools_f01.dbf 1 0 0.00 1.00 1 0 0 0.00
UNDO /pamprd4_dbf/undo_f01.dbf 1 0 0.00 1.00 28 1 0 0.00
UNDO /pamprd4_dbf/undo_f02.dbf 1 0 0.00 1.00 36 1 0 0.00
UNDO /pamprd4_dbf/undo_f03.dbf 1 0 0.00 1.00 20 1 0 0.00
UNDO /pamprd4_dbf/undo_f04.dbf 1 0 0.00 1.00 40 1 0 0.00
UNDO /pamprd4_dbf/undo_f05.dbf 1 0 0.00 1.00 88 3 0 0.00
UNDO /pamprd4_dbf/undo_f06.dbf 1 0 20.00 1.00 1,276 41 0 0.00
UNDO /pamprd4_dbf/undo_f07.dbf 1 0 0.00 1.00 41 1 0 0.00
UNDO /pamprd4_dbf/undo_f08.dbf 1 0 0.00 1.00 1 0 0 0.00
5. While seeing the init.ora Parameters, the parameters here are not
according to 10g defaults, it looks like they are according to 9i
defaults ( recently
migrated from 9i to 10g ).
I. I found one parameter that needs to be changed -
a. optimizer_mode : should be changed from 'choose' to 'all_rows',
correct ?
b. db_file_multiblock_read_count : i came to know that, this value
should not be set in oracle 10g, i.e., remove this parameter from
init.ora file.
correct ?
II. Any other parameters that are needed to be changed ?
init.ora Parameters
Parameter Name Begin value End value (if different)
_newsort_enabled FALSE
_optim_peek_user_binds FALSE
compatible 10.2.0.3
cursor_space_for_time TRUE
db_block_size 8192
db_cache_advice on
db_file_multiblock_read_count 8
db_files 1024
db_writer_processes 7
job_queue_processes 6
log_buffer 14242816
max_dump_file_size 16384
open_cursors 1024
optimizer_index_caching 90
optimizer_index_cost_adj 5
optimizer_mode choose
pga_aggregate_target 4294967296
processes 300
recovery_parallelism 4
resource_limit TRUE
session_cached_cursors 256
session_max_open_files 128
sga_target 8589934592
statistics_level typical
timed_statistics TRUE
undo_management AUTO
undo_retention 6000
undo_tablespace UNDO
6. Charles Question : if the disk subsystem is reading on average
about 24MB per second and writing on average about 15MB per second,
what happens when the
11,529 (roughly 370 per second) single block 8KB reads occur during
query execution? Do those 11,529 single block reads occur
immediately, or must they
queue behind other read and write requests as well as wait for the
drive heads to relocate over the correct location on the physical
disk?
My Guess : Those 11,529 single block reads will wait requesting for
next read/write, since block size is 8KB ( db_block_size : 8192 )
Correct ?
With Regards,
Raja.
Charles Hooper
> Hi,
>
> Thanks for all your comments / suggestions.
>
> Charles / Steve,
>
> Thanks for ur guidance.
>
> I am just starting / want to interpret the statspack / AWR Report.
> So, Please check whether my observations are correct, regarding the
> AWR Report.
>
It appears that you have spent some time investigating these items.
You probably do not want to have the optimizer mode set to choose. A
while ago I was testing Oracle 11.1.0.6 and found when looking at DBMS
Xplans (which show the expected execution order and method for
retrieving data) that the rule based optimizer was used for some SQL
statements - I thought that was an odd comment to appear in a 11.1.0.6
DBMS Xplan as I was under the impression that the rule based optimizer
was obsolete as of Oracle 10g. ALL_ROWS is probably a better
parameter value to use, as FIRST_ROWS (and its variants) may cause odd
performance problems as this value tends to cause Oracle to use
indexes excessively (in testing that optimizer mode, I recall having
significant performance problems when querying the data dictionary).
There are a couple articles describing the Oracle 10g R2 change in the
default behavior of db_file_multiblock_read_count in the website that
I provided in my first response in this thread, and I believe that the
change in default behavior is also mentioned in the Oracle
documentation (possibly the Performance Tuning Guide). There is a
right way and a wrong way to reset the parameter - if the database
instance is only using a pfile (init.ora) and not a spfile, removing
the db_file_multiblock_read_count from the pfile is the proper way to
reset this parameter. With an 8KB block size, you will likely find
that Oracle will auto-set this parameter to 128. It is hard to say
whether or not changing this parameter will improve overall
performance. During testing here, I changed the parameter from 32 to
a value auto-tuned by Oracle and found that full tablescans required
roughly 1/8 as much time as before, but those results are likely not
typical.
I would recommend determining why _newsort_enabled is set to FALSE,
why _optim_peek_user_binds is set to FALSE (there may be a very good
reason), why cursor_space_for_time is set to TRUE, why
db_writer_processes is set to 7 (there may be a very good reason for
not doing this), why optimizer_index_cost_adj is set to 5 (there is a
very good reason for not doing this), and why resource_limit is set to
TRUE. Please post your analysis of why those parameters are set to
those values.
Regarding your guess about the single block reads, assume that during
the 31 second time interval, an application was submitting a couple
queries to the database, and Oracle needed to read a couple (11,529 in
31 seconds) 8KB blocks from disk to supply an answer to the
application. If the disk subsystem (or the connection between the
server and the disk subsystem) was running near or at maximum capacity
(possibly maximum number of random access IOs) due to a concurrent
backup job, what happens to the performance of the application?
On this forum, as you show that you are making an effort to understand
what is happening, and show the work that you have performed when
analyzing a problem, you will find that more people will be willing to
offer assistance. I have seen some of Sybrand's responses when people
have demonstrated that they have attempted to work through their
problem - and I have been impressed with the quality of those
answers. Sybrand is providing a hint to you that you should show your
work and show that you made an effort to solve the problem.
raja
I have some details regarding the parameters that you have told to
look into.
1. _newsort_enabled is set to FALSE
- Activates new sorting algorithm in 10gR2, which is more efficient on
memory and CPU
- Default: TRUE
- Its set to FALSE, may be due to one of the following reasons :
a. due to the side effect of this new parameter, which causes again
a sort by row id eventhough the rows are in order.
b. due to the use of the materialized views, which may use the row
id. and to avoid this extra sort
I feel that this new sort method still has some problem ( like beta
version ) due to its side effects and hence they might have been
avoided.
2. _optim_peek_user_binds is set to FALSE (there may be a very good
reason),
- enable peeking of user binds
- Default value: TRUE
- There are three things that might put you at risk of unstable plans
due to bind variable peeking. Those are histograms, partitions, and
range-based predicates.
- Its set to FALSE, may be due to one of the following reasons :
a. not mess with the CBO explain plans
b. to make CBO create proper plans with respect to bind variables
3. cursor_space_for_time is set to TRUE,
- This parameter specifies whether a cursor can be deallocated from
the library cache to make room for a new SQL statement.
- Lets you use more space for cursors in order to save time. It
affects both the shared SQL area and the client's private SQL area.
Then a cursor can be deallocated only when all application cursors
associated with its statement are closed.
In this case, Oracle need not verify that a cursor is in the cache,
because it cannot be deallocated while an application cursor
associated with it is open.
- Default value: FALSE
- I found that it is recommended by many people to have the value of
this parameter as default ( FALSE ), since this has some side effects.
4. db_writer_processes is set to 7 (there may be a very good reason
for not doing this),
- Default value : 1 or CPU_COUNT / 8, whichever is greater. Range of
values 1 to 20
- It specifies the initial number of database writer processes for an
instance.
- db_writer_processes will help only if you have multiple
processors... else try setting dbwr_io_slaves
- Multiple DBWn is useful for systems that modify data heavily.
It specifies the initial number of database writer processes for an
instance.
Set automatically based on cpu_count. One DBWn for every eight
CPU's.
- With Oracle8 db_writer_processes, each writer process is assigned to
a LRU latch set.
Thus, it is recommended to set db_writer_processes equal to the
number of LRU latches (db_block_lru_latches) and not exceed the number
of CPUs on the system.
5. optimizer_index_cost_adj is set to 5 (there is a very good reason
for not doing this)
- Default value : 100, Range of values zero to 10,000
- This parameter alters the costing algorithm for access paths
involving indexes. The smaller the value, the cheaper the cost of
index access.
- For some OLTP systems, re-setting this parameter to a smaller value
(between 10- to 30) may result in huge performance gains!
- Oracle support(without knowing anything about my system) is telling
to use the following settings:
OPTIMIZER_INDEX_CACHING = 50
OPTIMIZER_INDEX_COST_ADJ = 5
6. resource_limit is set to TRUE.
- Default value : false
- determines whether resource limits are enforced in database
profiles.
- resource_limit = TRUE, Enables the enforcement of resource limits.
I think that this would allow to control the resource limits for a
particular user using profiles
( limits can be like max no of sessions used, max amt of SGA used, max
connection time, max block read/session, CPU time limit/call,..).
From the above analysis, I feel that the parameter values that are
required to be changed are as follows :
I. cursor_space_for_time, should be set to FALSE from the current
value TRUE
II. multi block read parameter has to be removed from init.ora, if we
are using only init.ora file alone.
III. change the optimizer mode from CHOOSE to the 10g default value
ALL_ROWS
Please check whether the details of these parameters are correct,
including the final analysis/conclusion regarding the parameters.
Your Question :
Regarding your guess about the single block reads, assume that during
the 31 second time interval, an application was submitting a couple of
queries to the database, and Oracle needed to read a couple (11,529
in
31 seconds) 8KB blocks from disk to supply an answer to the
application. If the disk subsystem (or the connection between the
server and the disk subsystem) was running near or at maximum
capacity
(possibly maximum number of random access IOs) due to a concurrent
backup job, what happens to the performance of the application?
Performance of the system will decrease.
Also, please check whether the analysis that i have made in my
previous mail are correct or not.
With Regards,
Raja.
Charles Hooper
of the parameters, but for the most part did not indicate why the
current parameters are set. Comments inline:
On Nov 9, 12:26 pm, raja <dextersu...@gmail.com> wrote:
> Hi,
>
> I have some details regarding the parameters that you have told to
> look into.
>
> 1. _newsort_enabled is set to FALSE
> - Activates new sorting algorithm in 10gR2, which is more efficient on
> memory and CPU
> - Default: TRUE
> - Its set to FALSE, may be due to one of the following reasons :
> a. due to the side effect of this new parameter, which causes again
> a sort by row id eventhough the rows are in order.
(snip)
You might see if you are able to find a specific example in your
database why this is disabled. Possible resource:
http://jonathanlewis.wordpress.com/2007/06/03/sorting/
> 2. _optim_peek_user_binds is set to FALSE (there may be a very good
> reason),
> - Its set to FALSE, may be due to one of the following reasons :
> a. not mess with the CBO explain plans
> b. to make CBO create proper plans with respect to bind variables
Did you find that when it was set to TRUE Oracle was generating bad
plans?
> 3. cursor_space_for_time is set to TRUE,
(snip)
> - I found that it is recommended by many people to have the value of
> this parameter as default ( FALSE ), since this has some side effects.
That seems to be the general rule, and I believe that I saw that this
parameter would be depreciated in a future version of Oracle (Oracle
11g R2?).
> 4. db_writer_processes is set to 7 (there may be a very good reason
> for not doing this),
> - Default value : 1 or CPU_COUNT / 8, whichever is greater. Range of
> values 1 to 20
(snip)
> Thus, it is recommended to set db_writer_processes equal to the
> number of LRU latches (db_block_lru_latches) and not exceed the number
> of CPUs on the system.
I was hoping that you would find the following article. After
reading, you may consider significantly decreasing the value of
db_writer_processes:
http://kevinclosson.wordpress.com/2007/08/10/learn-how-to-obliterate-processor-caches-configure-lots-and-lots-of-dbwr-processes/
> 5. optimizer_index_cost_adj is set to 5 (there is a very good reason
> for not doing this)
> - Default value : 100, Range of values zero to 10,000
> - This parameter alters the costing algorithm for access paths
> involving indexes. The smaller the value, the cheaper the cost of
> index access.
> - For some OLTP systems, re-setting this parameter to a smaller value
> (between 10- to 30) may result in huge performance gains!
> - Oracle support(without knowing anything about my system) is telling
> to use the following settings:
> OPTIMIZER_INDEX_CACHING = 50
> OPTIMIZER_INDEX_COST_ADJ = 5
Those appear to be suggestions that might be more appropriate prior to
the introduction of CPU costing, which is enabled by default on Oracle
10g. OPTIMIZER_INDEX_COST_ADJ = 5 is far too low of a value, which
basically tells Oracle to multiply the current index type access cost
by 0.05. Not only does this have a significant chance of forcing
unnecessary index scans when full table scans might be more
appropriate, but it also increases the chances that the wrong index
will be used for data retrieval due to rounding errors during cost
calculations. References:
http://books.google.com/books?id=w8qzDTUVHSQC&pg=PA185&lpg=PA185&dq=troubleshooting+oracle+performance++OPTIMIZER_INDEX_COST_ADJ&source=web&ots=_eoA6x-X2H&sig=GndPn0-bZrVWfuMSStzqsxJ05wU&hl=en&sa=X&oi=book_result&resnum=4&ct=result
http://jonathanlewis.wordpress.com/2006/10/24/optimizer_index_cost_adj/
> 6. resource_limit is set to TRUE.
> - Default value : false
> - determines whether resource limits are enforced in database
> profiles.
> - resource_limit = TRUE, Enables the enforcement of resource limits.
> I think that this would allow to control the resource limits for a
> particular user using profiles
> ( limits can be like max no of sessions used, max amt of SGA used, max
> connection time, max block read/session, CPU time limit/call,..).
What I was hoping that you would determine by looking at
resource_limit is that potentially someone enabled a resource limit
which is artifically causing an apparent performance problem. There
is not enough evidence to suggest that this is the case, but you may
want to take a look at that as a possibility.
> From the above analysis, I feel that the parameter values that are
> required to be changed are as follows :
> I. cursor_space_for_time, should be set to FALSE from the current
> value TRUE
> II. multi block read parameter has to be removed from init.ora, if we
> are using only init.ora file alone.
> III. change the optimizer mode from CHOOSE to the 10g default value
> ALL_ROWS
>
> Please check whether the details of these parameters are correct,
> including the final analysis/conclusion regarding the parameters.
The above seem to be logical conclusions to your research.
> Your Question :
> Regarding your guess about the single block reads, assume that during
> the 31 second time interval, an application was submitting a couple of
> queries to the database, and Oracle needed to read a couple (11,529
> in
> 31 seconds) 8KB blocks from disk to supply an answer to the
> application. If the disk subsystem (or the connection between the
> server and the disk subsystem) was running near or at maximum
> capacity
> (possibly maximum number of random access IOs) due to a concurrent
> backup job, what happens to the performance of the application?
>
> Performance of the system will decrease.
Yes, that was exactly what I had hoped you would see as a possibility,
although looking at an AWR report for a 31.2 second time period might
be a bit misleading.
> Also, please check whether the analysis that i have made in my
> previous mail are correct or not.
I only commented on those items where it was easy to see that you had
worked to find the solution and showed your analysis. I might have
overlooked a couple items in your posts. I would suggest collecting
an AWR report for 10 to 15 minutes, unless the performance problem is
only present in this 31 second time period.
raja
Thanks Charles, for ur detailed comments.
I will check and get back to you regarding the links that you have
provided.
With Regards,
Raja.
raja
I have learned some ( basic level ) init.ora parameters from the home
work that you gave to me.
I am still not clear with some details.
1. why oracle should create parameter that have side effects ( may be
thats y they are created as hidden parameters ) ?
2. setting the values are still not clear, because some have
dependancy, some are system specific,....
From the above discussions / analysis,
No changes to the following parameter values are to be made :
1. _newsort_enabled is set to FALSE
2. _optim_peek_user_binds is set to FALSE
3. resource_limit is set to TRUE
Changes to the parameter values to be made are as follows :
1. cursor_space_for_time, should be set to FALSE from the current
value TRUE
2. db_file_multiblock_read_count - has to be removed from init.ora, if
we are using only init.ora file alone.
3. optimizer mode - set the value as ALL_ROWS, from the current value
CHOOSE
4. optimizer_index_cost_adj - should increase the value from the
existing value 5.
Current values : optimizer_index_caching 90 ;
optimizer_index_cost_adj 5.
I hope i can set optimizer_index_cost_adj to 10, considering not
to have too low value ( 5 ).
5. db_writer_processes - The value should be decreased from current
value 7. Let me check on what value should be set and get back to you.
Please check, whether the conclusions are right/wrong.
I will also try to get another AWR Report for about 10-15 minutes.
Hope i can learn better using that.
With Regards,
Raja.
Charles Hooper
On Nov 10, 6:07 am, raja <dextersu...@gmail.com> wrote:
> I am still not clear with some details.
> 1. why oracle should create parameter that have side effects ( may be
> thats y they are created as hidden parameters ) ?
Hidden parameters (those which begin with _ ) should only be changed
after consulting Oracle Support, regardless of what some websites
suggest to use in order to "super-size" a parameter to improve
performance - chances are, there is another website which suggests
that changing that hidden parameter has undesirable side effects. It
is important to understand the undesirable side effects for all
parameter values, especially if those parameters are hidden
parameters.
Oracle databases must work efficiently with many different types of
applications (online transaction processing [OLTP], batch processing,
data warehouse, etc.), and when you consider that versions of Oracle
databases exist (or have existed) for somewhere around 100 different
operating systems, there needs to be flexibility in the database
instance, which is controlled through the use of different parameter
values. Parameters (and features) which have no visible side effects
in an OLTP database may have severe side effects in a data warehouse
database, and the various parameter values help eliminate the side
effects.
It would be nice if there were a checklist built into the database
software that someone could complete, which would then suggest the
optimal parameters for the database instance, the suggested size and
number of redo logs, the most appropriate location of the data files,
the number and speed of the CPUs, the amount of memory, the optimal
operating system, PCTFREE values for tables, etc. To my knowledge,
that checklist does not exist. Thus, the DBA must be willing to
investigate the optimal settings for the specific database instances,
and the applications that those database instances serve. An optimal
parameter value for an Oracle 8.1.7.3 database instance may not be an
optimal value for an Oracle 11.1.0.7 database instance due to
improvements/changes in optimizer features.
> 2. setting the values are still not clear, because some have
> dependancy, some are system specific,....
>
> From the above discussions / analysis,
>
> No changes to the following parameter values are to be made :
>
> 1. _newsort_enabled is set to FALSE
> 2. _optim_peek_user_binds is set to FALSE
> 3. resource_limit is set to TRUE
>
> Changes to the parameter values to be made are as follows :
>
> 1. cursor_space_for_time, should be set to FALSE from the current
> value TRUE
> 2. db_file_multiblock_read_count - has to be removed from init.ora, if
> we are using only init.ora file alone.
> 3. optimizer mode - set the value as ALL_ROWS, from the current value
> CHOOSE
> 4. optimizer_index_cost_adj - should increase the value from the
> existing value 5.
> Current values : optimizer_index_caching 90 ;
> optimizer_index_cost_adj 5.
> I hope i can set optimizer_index_cost_adj to 10, considering not
> to have too low value ( 5 ).
> 5. db_writer_processes - The value should be decreased from current
> value 7. Let me check on what value should be set and get back to you.
>
> Please check, whether the conclusions are right/wrong.
I believe that the above values for optimizer_index_caching and
optimizer_index_cost_adj still need a little more adjustment to avoid
an over-dependence on nested loop joins and to avoid utilizing index
based access (possibly with the wrong index) when a full tablescan
might be more efficient.
Paraphrased from "Cost-Based Oracle Fundamentals":
"OPTIMIZER_INDEX_CACHING helps correct the optimizer’s assumption that
all reads are physical reads. This has an effect when multiple tables
are joined using nested loops with index access for the inner (second)
table, but also has an effect for cost calculation of in-list
iteration. This parameter does not affect the cost of a single table
indexed access path. A starting value of 75 is a reasonable starting
guess."
Paraphrased from "Cost-Based Oracle Fundamentals":
"OPTIMIZER_INDEX_COST_ADJ reduces the cost of single block reads,
which tends to reduce the tendency of excessive tablescans. The
downside is that due to rounding errors, the optimizer may decide to
use the wrong index."
Paraphrased from "Troubleshooting Oracle Performance":
"Oracle 8i and earlier use the I/O cost model, which by default costs
single block and multi-block reads the same. OPTIMIZER_INDEX_COST_ADJ
and OPTIMIZER_INDEX_CACHING help to correct this issue by making index
access (single block access) appear to be less expensive. CPU cost
model (system statistics), used by default with Oracle 10g, takes into
account the performance of the CPU and the I/O subsystem." The CPU
cost model nearly eliminates the need to change
OPTIMIZER_INDEX_COST_ADJ and OPTIMIZER_INDEX_CACHING from their
defaults. CPU cost model statistics are stored in SYS.AUX_STATS$ .
Based on the above, you might want to consider setting (test the
effects of changes):
* OPTIMIZER_INDEX_COST_ADJ close to 100
* OPTIMIZER_INDEX_CACHING close to 0
* Values in SYS.AUX_STATS$ to appropriate values
The following SQL*Plus command will automatically calculate the values
in SYS.AUX_STATS$ based on a 60 minute time interval (starting
immediately after you execute this statement):
EXEC DBMS_STATS.GATHER_SYSTEM_STATS('interval',interval=>60)
While you are checking SYS.AUX_STATS$, you may also want to verify
that fixed object statistics have been gathered by querying
SYS.TAB_STATS$ - if no rows are returned, then fixed object statistics
have not been gathered and poor performance or session crashes may
result, see:
http://groups.google.com/group/comp.databases.oracle.server/browse_thread/thread/e0599d3e043fc199
> I will also try to get another AWR Report for about 10-15 minutes.
That would be a good idea. Keep in mind that the above suggestions
are very general in nature, and may not exactly apply to your database
instance. The AWR report for 10-15 minutes will allow for more
specific/relevant suggestions.
raja
I have another AWR Report generated with 1hr interval.
I dont know how to approach this. Please help on this...
AWR Report :
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 10739 13-Nov-08 09:00:45 105 58.2
End Snap: 10763 13-Nov-08 15:00:12 91 75.2
Elapsed: 359.46 (mins)
DB Time: 1,723.72 (mins)
Cache Sizes
Begin End
Buffer Cache: 6,832M 6,832M Std Block Size: 8K
Shared Pool Size: 1,264M 1,264M Log Buffer: 14,344K
Load Profile
Per Second Per Transaction
Redo size: 594,828.36 528,401.03
Logical reads: 393,203.94 349,292.97
Block changes: 3,687.61 3,275.79
Physical reads: 532.23 472.79
Physical writes: 341.38 303.25
User calls: 224.24 199.20
Parses: 14.60 12.97
Hard parses: 0.32 0.29
Sorts: 3.20 2.85
Logons: 0.26 0.23
Executes: 541.25 480.80
Transactions: 1.13
% Blocks changed per Read: 0.94 Recursive Call %: 72.78
Rollback per transaction %: 0.08 Rows per Sort: 6101.47
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.89 In-memory Sort %: 100.00
Library Hit %: 97.45 Soft Parse %: 97.79
Execute to Parse %: 97.30 Latch Hit %: 95.31
Parse CPU to Parse Elapsd %: 79.21 % Non-Parse CPU: 99.10
Shared Pool Statistics
Begin End
Memory Usage %: 89.36 92.12
% SQL with executions>1: 95.58 97.42
% Memory for SQL w/exec>1: 95.17 97.31
Top 5 Timed Events
Event Waits Time(s) Avg Wait(ms) % Total Call
Time Wait Class
CPU time 56,931 55.0
db file sequential read 4,036,055 13,310 3 12.9 User I/
O
db file parallel write 567,009 6,515 11 6.3 System
I/O
db file scattered read 934,341 1,383 1 1.3 User I/
O
log file parallel write 38,621 1,019 26 1.0 System
I/O
Time Model Statistics
Statistic Name Time (s) % of DB Time
sql execute elapsed time 102,885.27 99.48
DB CPU 56,931.50 55.05
Java execution elapsed time 18,173.85 17.57
PL/SQL execution elapsed time 1,146.88 1.11
RMAN cpu time (backup/restore) 782.75 0.76
parse time elapsed 649.38 0.63
hard parse elapsed time 619.03 0.60
failed parse elapsed time 13.16 0.01
connection management call elapsed time 10.55 0.01
inbound PL/SQL rpc elapsed time 7.46 0.01
hard parse (sharing criteria) elapsed time 7.30 0.01
PL/SQL compilation elapsed time 1.10 0.00
repeated bind elapsed time 0.34 0.00
sequence load elapsed time 0.03 0.00
hard parse (bind mismatch) elapsed time 0.02 0.00
DB time 103,423.35
background elapsed time 9,817.43
background cpu time 1,169.73
Wait Class
Wait Class Waits %Time-outs Total Wait Time (s) Avg wait (ms)
Waits /txn
User I/O 5,383,928 0.00 15,139 3 221.75
System I/O 1,606,400 0.00 8,442 5 66.16
Administrative 51,609 0.00 901 17 2.13
Commit 17,706 0.10 387 22 0.73
Network 9,640,482 0.00 165 0 397.07
Application 2,045 2.30 140 68 0.08
Concurrency 366,686 0.10 65 0 15.10
Configuration 257 0.00 53 206 0.01
Other 2,147 38.33 47 22 0.09
Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
db file sequential read 4,036,055 0.00 13,310 3 166.24
db file parallel write 567,009 0.00 6,515 11 23.35
db file scattered read 934,341 0.00 1,383 1 38.48
log file parallel write 38,621 0.00 1,019 26 1.59
Backup: sbtwrite2 51,438 0.00 896 17 2.12
Log archive I/O 15,175 0.00 658 43 0.63
log file sync 17,706 0.10 387 22 0.73
direct path write temp 98,515 0.00 313 3 4.06
SQL*Net more data to client 4,642,420 0.00 154 0 191.21
enq: TX - row lock contention 1,475 3.19 138 94 0.06
control file parallel write 10,484 0.00 107 10 0.43
log file sequential read 12,839 0.00 87 7 0.53
read by other session 40,059 0.00 79 2 1.65
direct path read 272,647 0.00 54 0 11.23
log buffer space 181 0.00 46 256 0.01
enq: WL - contention 16 87.50 44 2742 0.00
latch: cache buffers chains 363,571 0.00 37 0 14.97
control file single write 448 0.00 28 63 0.02
os thread startup 424 0.00 23 55 0.02
RMAN backup & recovery I/O 6,130 0.00 18 3 0.25
control file sequential read 955,614 0.00 9 0 39.36
log file switch completion 75 0.00 7 89 0.00
SQL*Net more data from dblink 127,162 0.00 6 0 5.24
cursor: pin S wait on X 365 100.00 4 10 0.02
SQL*Net message to client 4,819,165 0.00 4 0 198.49
switch logfile command 7 0.00 2 268 0.00
Backup: sbtinfo2 41 0.00 2 37 0.00
enq: CF - contention 14 0.00 1 89 0.00
latch free 181 0.00 1 6 0.01
enq: KO - fast object checkpoint 47 0.00 1 21 0.00
Backup: sbtremove2 30 0.00 1 30 0.00
buffer busy waits 2,272 0.00 1 0 0.09
Backup: sbtclose2 22 0.00 1 29 0.00
Backup: sbtbackup 22 0.00 1 24 0.00
rdbms ipc reply 12 0.00 1 43 0.00
SQL*Net more data from client 5,009 0.00 0 0 0.21
log file single write 80 0.00 0 4 0.00
enq: RO - fast object reuse 15 0.00 0 19 0.00
db file parallel read 14 0.00 0 17 0.00
PX Deq: Signal ACK 28 21.43 0 8 0.00
direct path write 1,712 0.00 0 0 0.07
latch: shared pool 24 0.00 0 9 0.00
Backup: sbtinit 16 0.00 0 9 0.00
enq: PR - contention 3 0.00 0 42 0.00
SQL*Net more data to dblink 3,080 0.00 0 0 0.13
SQL*Net break/reset to client 508 0.00 0 0 0.02
kksfbc child completion 2 100.00 0 49 0.00
SQL*Net message to dblink 43,646 0.00 0 0 1.80
local write wait 6 0.00 0 12 0.00
LGWR wait for redo copy 936 0.00 0 0 0.04
jobq slave TJ process wait 5 100.00 0 10 0.00
latch: cache buffers lru chain 25 0.00 0 2 0.00
direct path read temp 579 0.00 0 0 0.02
latch: object queue header operation 44 0.00 0 1 0.00
reliable message 61 0.00 0 0 0.00
latch: library cache 11 0.00 0 2 0.00
Backup: sbtend 17 0.00 0 1 0.00
latch: session allocation 6 0.00 0 2 0.00
PX Deq Credit: send blkd 10 0.00 0 0 0.00
latch: redo allocation 3 0.00 0 1 0.00
latch: library cache lock 3 0.00 0 1 0.00
latch: row cache objects 1 0.00 0 3 0.00
PX qref latch 797 99.87 0 0 0.03
enq: PS - contention 2 0.00 0 0 0.00
Backup: sbtinit2 16 0.00 0 0 0.00
latch: redo writing 1 0.00 0 0 0.00
cursor: mutex S 15 0.00 0 0 0.00
cursor: pin S 2 0.00 0 0 0.00
SQL*Net message from client 4,819,163 0.00 552,203 115 198.49
jobq slave wait 25,556 86.15 69,777 2730 1.05
Streams AQ: qmn slave idle wait 766 0.00 21,012 27431 0.03
Streams AQ: qmn coordinator idle wait 1,583 51.61 21,012 13273 0.07
PX Idle Wait 4,235 98.70 8,209 1938 0.17
Streams AQ: waiting for time management or cleanup tasks 5 100.00
5,361 1072103 0.00
SQL*Net message from dblink 43,646 0.00 2,188 50 1.80
single-task message 3,080 0.00 533 173 0.13
PX Deq: Execution Msg 237 0.00 9 39 0.01
PX Deq: Msg Fragment 42 0.00 0 3 0.00
PX Deq: Parse Reply 31 0.00 0 3 0.00
PX Deq: Execute Reply 19 0.00 0 2 0.00
PX Deq: Join ACK 26 0.00 0 1 0.00
class slave wait 46 0.00 0 0 0.00
Background Wait Events
Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
db file parallel write 567,009 0.00 6,515 11 23.35
log file parallel write 38,621 0.00 1,019 26 1.59
Log archive I/O 13,753 0.00 574 42 0.57
control file parallel write 9,060 0.00 90 10 0.37
log file sequential read 11,638 0.00 69 6 0.48
os thread startup 396 0.00 22 55 0.02
db file sequential read 552 0.00 2 4 0.02
log file sync 31 0.00 1 45 0.00
events in waitclass Other 1,025 0.00 1 1 0.04
db file scattered read 178 0.00 1 4 0.01
direct path read 840 0.00 1 1 0.03
control file sequential read 10,683 0.00 0 0 0.44
log file single write 80 0.00 0 4 0.00
direct path write 840 0.00 0 0 0.03
log buffer space 14 0.00 0 2 0.00
latch: library cache 1 0.00 0 5 0.00
latch: cache buffers chains 2 0.00 0 0 0.00
latch: redo writing 1 0.00 0 0 0.00
rdbms ipc message 152,029 73.00 344,964 2269 6.26
Streams AQ: qmn slave idle wait 766 0.00 21,012 27431 0.03
Streams AQ: qmn coordinator idle wait 1,583 51.61 21,012 13273 0.07
pmon timer 7,148 100.00 20,935 2929 0.29
smon timer 111 53.15 20,131 181360 0.00
Streams AQ: waiting for time management or cleanup tasks 5 100.00
5,361 1072103 0.00
Operating System Statistics
Statistic Total
NUM_LCPUS 0
NUM_VCPUS 0
AVG_BUSY_TIME 773,431
AVG_IDLE_TIME 1,382,735
AVG_IOWAIT_TIME 198,722
AVG_SYS_TIME 112,958
AVG_USER_TIME 659,771
BUSY_TIME 10,837,634
IDLE_TIME 19,367,934
IOWAIT_TIME 2,791,750
SYS_TIME 1,591,031
USER_TIME 9,246,603
LOAD 0
OS_CPU_WAIT_TIME 11,375,200
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 82,678,112,256
NUM_CPUS 14
NUM_CPU_CORES 7
Instance Activity Stats
Statistic Total per Second per Trans
CPU used by this session 2,760,501 127.99 113.70
CPU used when call started 2,065,134 95.75 85.06
CR blocks created 116,826 5.42 4.81
Cached Commit SCN referenced 35,858,913 1,662.63 1,476.95
Commit SCN cached 1,088 0.05 0.04
DB time 14,230,583 659.81 586.13
DBWR checkpoint buffers written 2,786,759 129.21 114.78
DBWR checkpoints 82 0.00 0.00
DBWR object drop buffers written 28 0.00 0.00
DBWR parallel query checkpoint buffers written 0 0.00 0.00
DBWR revisited being-written buffer 4 0.00 0.00
DBWR tablespace checkpoint buffers written 579 0.03 0.02
DBWR thread checkpoint buffers written 0 0.00 0.00
DBWR transaction table writes 665 0.03 0.03
DBWR undo block writes 879,979 40.80 36.24
DFO trees parallelized 2 0.00 0.00
IMU CR rollbacks 1,266 0.06 0.05
IMU Flushes 6,465 0.30 0.27
IMU Redo allocation size 11,813,948 547.76 486.59
IMU commits 17,702 0.82 0.73
IMU contention 1,089 0.05 0.04
IMU ktichg flush 1,657 0.08 0.07
IMU pool not allocated 112 0.01 0.00
IMU recursive-transaction flush 3 0.00 0.00
IMU undo allocation size 65,066,320 3,016.85 2,679.94
IMU- failed to get a private strand 112 0.01 0.00
Misses for writing mapping 0 0.00 0.00
PX local messages recv'd 368 0.02 0.02
PX local messages sent 368 0.02 0.02
Parallel operations not downgraded 2 0.00 0.00
SMON posted for undo segment shrink 0 0.00 0.00
SQL*Net roundtrips to/from client 4,813,090 223.16 198.24
SQL*Net roundtrips to/from dblink 43,646 2.02 1.80
active txn count during cleanout 211,905 9.83 8.73
application wait time 13,949 0.65 0.57
background checkpoints completed 21 0.00 0.00
background checkpoints started 20 0.00 0.00
background timeouts 111,870 5.19 4.61
branch node splits 19 0.00 0.00
buffer is not pinned count 7,406,205,468 343,394.21 305,045.74
buffer is pinned count 1,342,723,816 62,256.39 55,303.92
bytes received via SQL*Net from client 606,443,091 28,118.18
24,978.09
bytes received via SQL*Net from dblink 265,807,835 12,324.38
10,948.06
bytes sent via SQL*Net to client 18,910,995,749 876,822.35 778,903.40
bytes sent via SQL*Net to dblink 25,547,081 1,184.51 1,052.23
calls to get snapshot scn: kcmgss 11,936,890 553.46 491.65
calls to kcmgas 1,248,240 57.88 51.41
calls to kcmgcs 106,173 4.92 4.37
change write time 44,255 2.05 1.82
cleanout - number of ktugct calls 547,076 25.37 22.53
cleanouts and rollbacks - consistent read gets 111,031 5.15 4.57
cleanouts only - consistent read gets 136,836 6.34 5.64
cluster key scan block gets 382,786 17.75 15.77
cluster key scans 278,819 12.93 11.48
commit batch performed 3,080 0.14 0.13
commit batch requested 3,080 0.14 0.13
commit batch/immediate performed 3,083 0.14 0.13
commit batch/immediate requested 3,083 0.14 0.13
commit cleanout failures: block lost 41,023 1.90 1.69
commit cleanout failures: buffer being written 4 0.00 0.00
commit cleanout failures: callback failure 157 0.01 0.01
commit cleanout failures: cannot pin 231 0.01 0.01
commit cleanouts 749,666 34.76 30.88
commit cleanouts successfully completed 708,251 32.84 29.17
commit immediate performed 3 0.00 0.00
commit immediate requested 3 0.00 0.00
commit txn count during cleanout 351,189 16.28 14.46
concurrency wait time 6,507 0.30 0.27
consistent changes 5,328,067 247.04 219.45
consistent gets 8,341,439,937 386,757.05 343,566.04
consistent gets - examination 3,757,741,068 174,230.45 154,773.30
consistent gets direct 6,617,029 306.80 272.54
consistent gets from cache 8,334,822,915 386,450.25 343,293.50
current blocks converted for CR 887 0.04 0.04
cursor authentications 5,542 0.26 0.23
data blocks consistent reads - undo records applied 5,319,562 246.65
219.10
db block changes 79,532,990 3,687.61 3,275.79
db block gets 139,044,324 6,446.89 5,726.94
db block gets direct 1,283 0.06 0.05
db block gets from cache 139,043,041 6,446.83 5,726.89
deferred (CURRENT) block cleanout applications 297,057 13.77 12.24
dirty buffers inspected 833,757 38.66 34.34
enqueue conversions 26,766 1.24 1.10
enqueue releases 379,365 17.59 15.63
enqueue requests 381,254 17.68 15.70
enqueue timeouts 1,886 0.09 0.08
enqueue waits 1,397 0.06 0.06
execute count 11,673,423 541.25 480.80
failed probes on index block reclamation 714 0.03 0.03
free buffer inspected 11,179,231 518.33 460.45
free buffer requested 10,381,781 481.36 427.60
heap block compress 164,584 7.63 6.78
hot buffers moved to head of LRU 5,449,531 252.67 224.45
immediate (CR) block cleanout applications 247,867 11.49 10.21
immediate (CURRENT) block cleanout applications 385,730 17.88 15.89
index crx upgrade (found) 452 0.02 0.02
index crx upgrade (positioned) 62,987 2.92 2.59
index fast full scans (full) 2,384 0.11 0.10
index fast full scans (rowid ranges) 0 0.00 0.00
index fetch by key 2,698,249,086 125,106.32 111,135.10
index scans kdiixs1 141,091,704 6,541.82 5,811.27
java call heap collected bytes 807,424 37.44 33.26
java call heap collected count 12,592 0.58 0.52
java call heap gc count 48 0.00 0.00
java call heap live object count 12,880 0.60 0.53
java call heap live object count max 12,880 0.60 0.53
java call heap live size 4,392,064 203.64 180.90
java call heap live size max 4,392,064 203.64 180.90
java call heap object count 14,736 0.68 0.61
java call heap object count max 22,560 1.05 0.93
java call heap total size 8,409,088 389.89 346.35
java call heap total size max 8,409,088 389.89 346.35
java call heap used size 4,607,488 213.63 189.77
java call heap used size max 4,607,488 213.63 189.77
leaf node 90-10 splits 271 0.01 0.01
leaf node splits 1,553 0.07 0.06
lob reads 2,540 0.12 0.10
lob writes 3,993 0.19 0.16
lob writes unaligned 3,993 0.19 0.16
logons cumulative 5,645 0.26 0.23
messages received 709,812 32.91 29.24
messages sent 709,812 32.91 29.24
no buffer to keep pinned count 0 0.00 0.00
no work - consistent read gets 4,583,137,118 212,500.55 188,769.60
opened cursors cumulative 306,678 14.22 12.63
parse count (failures) 719 0.03 0.03
parse count (hard) 6,958 0.32 0.29
parse count (total) 314,916 14.60 12.97
parse time cpu 51,060 2.37 2.10
parse time elapsed 64,460 2.99 2.65
physical read IO requests 5,242,302 243.06 215.92
physical read bytes 94,035,378,176 4,360,020.07 3,873,115.79
physical read total IO requests 6,234,776 289.08 256.80
physical read total bytes ############### 6,008,005.33 5,337,062.65
physical read total multi block requests 1,241,703 57.57 51.14
physical reads 11,478,928 532.23 472.79
physical reads cache 9,309,733 431.65 383.45
physical reads cache prefetch 4,341,654 201.30 178.82
physical reads direct 2,169,195 100.58 89.34
physical reads direct (lob) 289 0.01 0.01
physical reads direct temporary tablespace 8,813 0.41 0.36
physical reads prefetch warmup 0 0.00 0.00
physical write IO requests 1,774,921 82.30 73.11
physical write bytes 60,315,189,248 2,796,558.50 2,484,253.44
physical write total IO requests 1,919,227 88.99 79.05
physical write total bytes ############### 4,671,166.82 4,149,515.29
physical write total multi block requests 828,012 38.39 34.10
physical writes 7,362,694 341.38 303.25
physical writes direct 3,046,704 141.26 125.49
physical writes direct (lob) 900 0.04 0.04
physical writes direct temporary tablespace 3,044,692 141.17 125.40
physical writes from cache 4,315,990 200.11 177.77
physical writes non checkpoint 5,207,133 241.43 214.47
pinned buffers inspected 764 0.04 0.03
prefetch warmup blocks aged out before use 0 0.00 0.00
prefetched blocks aged out before use 1 0.00 0.00
process last non-idle time 19,633 0.91 0.81
queries parallelized 2 0.00 0.00
recursive aborts on index block reclamation 0 0.00 0.00
recursive calls 12,928,244 599.43 532.49
recursive cpu usage 788,961 36.58 32.50
redo blocks written 25,938,241 1,202.65 1,068.34
redo buffer allocation retries 509 0.02 0.02
redo entries 40,749,357 1,889.37 1,678.38
redo log space requests 162 0.01 0.01
redo log space wait time 688 0.03 0.03
redo ordering marks 872,628 40.46 35.94
redo size 12,829,048,628 594,828.36 528,401.03
redo subscn max counts 1,425,256 66.08 58.70
redo synch time 39,573 1.83 1.63
redo synch writes 57,879 2.68 2.38
redo wastage 13,394,880 621.06 551.71
redo write time 105,026 4.87 4.33
redo writer latching time 6 0.00 0.00
redo writes 38,622 1.79 1.59
rollback changes - undo records applied 177 0.01 0.01
rollbacks only - consistent read gets 7,194 0.33 0.30
rows fetched via callback 997,973,536 46,271.78 41,104.39
session connect time 0 0.00 0.00
session cursor cache hits 87,057 4.04 3.59
session logical reads 8,480,484,110 393,203.94 349,292.97
session pga memory 7,148,528,160 331,446.81 294,432.56
session pga memory max 18,255,207,648 846,416.25 751,892.90
session uga memory ############### 669,514,241.36 594,746,385.30
session uga memory max 7,658,125,248 355,074.66 315,421.77
shared hash latch upgrades - no wait 6,882,720 319.12 283.48
shared hash latch upgrades - wait 582 0.03 0.02
sorts (disk) 0 0.00 0.00
sorts (memory) 69,110 3.20 2.85
sorts (rows) 421,672,915 19,551.18 17,367.80
sql area evicted 2,528 0.12 0.10
sql area purged 785 0.04 0.03
summed dirty queue length 2,721,198 126.17 112.08
switch current to new buffer 71,026 3.29 2.93
table fetch by rowid 2,954,474,371 136,986.40 121,688.47
table fetch continued row 21,150 0.98 0.87
table scan blocks gotten 44,917,305 2,082.62 1,850.05
table scan rows gotten 2,282,015,917 105,807.36 93,991.35
table scans (cache partitions) 1 0.00 0.00
table scans (direct read) 48 0.00 0.00
table scans (long tables) 73 0.00 0.00
table scans (rowid ranges) 0 0.00 0.00
table scans (short tables) 53,427 2.48 2.20
total number of times SMON posted 52 0.00 0.00
transaction rollbacks 3,083 0.14 0.13
transaction tables consistent read rollbacks 13 0.00 0.00
transaction tables consistent reads - undo records applied 636 0.03
0.03
undo change vector size 6,943,980,192 321,962.79 286,007.67
user I/O wait time 1,513,678 70.18 62.35
user calls 4,836,293 224.24 199.20
user commits 24,259 1.12 1.00
user rollbacks 20 0.00 0.00
workarea executions - onepass 29 0.00 0.00
workarea executions - optimal 58,361 2.71 2.40
write clones created in background 6 0.00 0.00
write clones created in foreground 1,658 0.08 0.07
Instance Activity Stats - Absolute Values
Statistic Begin Value End Value
session cursor cache count 9,385,330 9,602,685
opened cursors current 6,109 6,840
workarea memory allocated 7,708 9,606
logons current 105 91
Instance Activity Stats - Thread Activity
Statistic Total per Hour
log switches (derived) 20 3.34
Buffer Pool Statistics
P Number of Buffers Pool Hit% Buffer Gets Physical Reads Physical
Writes Free Buff Wait Writ Comp Wait Buffer Busy Waits
D 845,033 108 -122,414,827 9,309,740 4,315,984 0 0 42,331
PGA Aggr Summary
PGA Cache Hit % W/A MB Processed Extra W/A MB Read/Written
87.75 16,383 2,288
Buffer Wait Statistics
Class Waits Total Wait Time (s) Avg Time (ms)
data block 41,790 81 2
undo header 517 0 1
1st level bmb 3 0 3
2nd level bmb 1 0 10
segment header 6 0 0
undo block 3 0 0
Enqueue Activity
Enqueue Type (Request Reason) Requests Succ Gets Failed Gets Waits Wt
Time (s) Av Wt Time(ms)
TX-Transaction (row lock contention) 1,322 1,322 0 1,315 141 107.60
WL-Being Written Redo Log 39 22 17 2 45 22,459.00
CF-Controlfile Transaction 12,219 12,217 2 14 1 91.36
KO-Multiple Object Checkpoint (fast object checkpoint) 432 432 0 47 1
21.47
RO-Multiple Object Reuse (fast object reuse) 126 126 0 14 0 20.29
PR-Process Startup 424 424 0 3 0 43.00
PS-PX Process Reservation 252 251 0 2 0 0.00
Undo Segment Summary
Undo TS# Num Undo Blocks (K) Number of Transactions Max Qry Len (s)
Max Tx Concurcy Min/Max TR (mins) STO/ OOS uS/uR/uU/ eS/eR/eU
1 879.58 49,869 192,545 9
2862.38333333333333333333333333333333333/3223.0666666666666666666666666666666666
0/0 0/0/0/0/0/0
Latch Activity
Latch Name Get Requests Pct Get Miss Avg Slps /Miss Wait Time (s)
NoWait Requests Pct NoWait Miss
ASM db client latch 14,472 0.00 0 0
AWR Alerted Metric Element list 111,345 0.00 0 0
Consistent RBA 38,650 0.02 0.00 0 0
FAL request queue 470 0.00 0 0
FAL subheap alocation 470 0.00 0 0
FIB s.o chain latch 737 0.00 0 0
FOB s.o list latch 12,527 0.03 0.00 0 0
In memory undo latch 4,290,987 0.04 0.00 0 29,423 1.67
JOX SGA heap latch 941 0.00 0 0
JS queue state obj latch 129,240 0.00 0 0
JS slv state obj latch 1,044 0.00 0 0
KMG MMAN ready and startup request latch 7,189 0.00 0 0
KTF sga latch 1,282 0.00 0 6,066 0.00
KWQMN job cache list latch 6 0.00 0 0
MQL Tracking Latch 0 0 429 0.00
Memory Management Latch 0 0 7,189 0.00
OS process 9,351 0.00 0 0
OS process allocation 13,409 0.52 0.00 0 0
OS process: request allocation 4,524 0.24 0.00 0 0
PL/SQL warning settings 19,858 0.00 0 0
SGA IO buffer pool latch 11,021 0.00 0 11,146 0.01
SQL memory manager latch 24 0.00 0 7,151 0.00
SQL memory manager workarea list latch 826,430 0.00 0 0
Shared B-Tree 766 0.00 0 0
X$KSFQP 154 0.00 0 0
active checkpoint queue latch 719,515 1.58 0.00 0 0
active service list 62,196 0.22 0.00 0 7,148 0.00
archive control 1,874 0.00 0 0
archive process latch 7,621 0.00 0 0
begin backup scn array 940 0.00 0 0
cache buffer handles 819,812 0.00 0.00 0 0
cache buffers chains 5,280,355,952 5.32 0.00 37 21,935,227 0.00
cache buffers lru chain 8,818,130 0.11 0.00 0 25,512,853 0.04
cache table scan latch 0 0 934,249 0.01
channel handle pool latch 4,635 0.47 0.00 0 0
channel operations parent latch 109,742 0.01 0.00 0 0
checkpoint queue latch 8,494,017 0.01 0.00 0 4,298,746 0.01
client/application info 33,016 0.00 0 0
commit callback allocation 6,476 0.26 0.00 0 0
compile environment latch 59,891 0.00 0 0
constraint object allocation 6,448 4.23 0.00 0 0
dictionary lookup 18 0.00 0 0
dml lock allocation 122,190 1.68 0.00 0 0
dummy allocation 11,360 0.40 0.00 0 0
enqueue hash chains 789,439 0.26 0.00 0 1,605 0.00
enqueues 585,379 0.23 0.00 0 0
error message lists 114 1.75 0.00 0 0
event group latch 2,255 0.00 0 0
file cache latch 2,148 0.00 0 0
global KZLD latch for mem in SGA 1,644 0.00 0 0
global ctx hash table latch 1 0.00 0 0
global tx hash mapping 41,173 0.01 0.00 0 0
hash table column usage latch 1,511 0.07 0.00 0 5,245,016 0.00
hash table modification latch 189 0.00 0 0
internal temp table object number allocation latc 1,221 0.00 0 0
job workq parent latch 15 100.00 0.00 0 5,952 6.03
job_queue_processes parameter latch 1,736 0.00 0 0
kks stats 33,820 0.00 0 0
krbmrosl 4,485 0.00 0 0
ksuosstats global area 1,486 0.00 0 0
ktm global data 112 0.00 0 0
kwqbsn:qsga 766 0.00 0 0
lgwr LWN SCN 39,301 0.16 0.00 0 0
library cache 2,288,082 1.90 0.00 0 21,060 0.00
library cache load lock 990 0.00 0 0
library cache lock 1,526,021 0.99 0.00 0 0
library cache lock allocation 121,627 0.01 0.00 0 0
library cache pin 604,460 0.90 0.00 0 0
library cache pin allocation 35,107 0.09 0.00 0 0
list of block allocation 87,703 0.52 0.00 0 0
loader state object freelist 4,281 0.00 0 0
longop free list parent 1,334 0.00 0 71 0.00
message pool operations parent latch 292 0.00 0 0
messages 1,694,814 1.06 0.00 0 0
mostly latch-free SCN 39,725 0.98 0.00 0 0
multiblock read objects 3,291,270 0.00 0.00 0 0
ncodef allocation latch 340 0.00 0 0
object queue header heap 654,313 0.00 0 22,441 0.00
object queue header operation 34,346,629 0.02 0.01 0 0
object stats modification 73 0.00 0 0
parallel query alloc buffer 3,420 0.18 0.00 0 0
parallel query stats 62 14.52 0.00 0 0
parameter table allocation management 12,199 1.34 0.00 0 0
post/wait queue 45,298 0.23 0.00 0 17,968 0.00
process allocation 4,526 0.00 0 2,255 0.00
process group creation 4,524 1.17 0.00 0 0
process queue 396 1.01 0.00 0 0
process queue reference 13,762 0.00 0 671 118.78
qmn task queue latch 3,064 0.20 0.00 0 0
query server freelists 286 3.50 0.00 0 0
query server process 28 0.00 0 28 0.00
redo allocation 196,729 0.43 0.00 0 40,747,233 0.05
redo copy 0 0 40,749,514 0.00
redo writing 867,413 1.06 0.00 0 0
resmgr group change latch 7,573 0.00 0 0
resmgr:actses active list 11,288 0.00 0 0
resmgr:actses change group 5,248 0.00 0 0
resmgr:free threads list 11,264 0.49 0.00 0 0
resmgr:schema config 24 0.00 0 0
row cache objects 9,463,000 0.18 0.00 0 818 0.00
rules engine aggregate statistics 2 0.00 0 0
rules engine rule set statistics 4 0.00 0 0
sequence cache 11,055 0.00 0 0
session allocation 23,149,602 0.30 0.00 0 0
session idle bit 9,769,326 0.00 0.00 0 0
session state list latch 24,658 9.81 0.00 0 0
session switching 340 0.00 0 0
session timer 7,148 0.00 0 0
shared pool 790,880 0.19 0.02 0 0
shared pool sim alloc 3 0.00 0 0
shared pool simulator 366,162 0.00 0 0
simulator hash latch 295,089,755 0.00 0.00 0 0
simulator lru latch 290,100,417 0.33 0.00 0 3,683,779 0.00
slave class 48 0.00 0 0
slave class create 192 7.81 1.07 1 0
sort extent pool 25,433 0.00 0 0
state object free list 48 0.00 0 0
statistics aggregation 2,688 0.00 0 0
temp lob duration state obj allocation 36 0.00 0 0
temporary table state object allocation 13 0.00 0 0
threshold alerts latch 1,575 0.00 0 0
transaction allocation 14,048 0.31 0.00 0 0
transaction branch allocation 13,685 0.31 0.00 0 0
undo global data 35,333,792 0.01 0.00 0 0
user lock 13,415 5.65 0.01 0 0
Latch Sleep Breakdown
Latch Name Get Requests Misses Sleeps Spin Gets Sleep1 Sleep2 Sleep3
cache buffers chains 5,280,355,952 280,822,854 363,585 280,494,637 0 0
0
simulator lru latch 290,100,417 965,004 154 964,866 0 0 0
session allocation 23,149,602 68,947 6 68,941 0 0 0
library cache 2,288,082 43,386 11 43,375 0 0 0
row cache objects 9,463,000 16,632 1 16,631 0 0 0
library cache lock 1,526,021 15,074 3 15,071 0 0 0
active checkpoint queue latch 719,515 11,386 4 11,382 0 0 0
simulator hash latch 295,089,755 11,102 2 11,100 0 0 0
cache buffers lru chain 8,818,130 9,639 25 9,614 0 0 0
redo writing 867,413 9,177 1 9,176 0 0 0
object queue header operation 34,346,629 7,960 44 7,917 0 0 0
shared pool 790,880 1,520 24 1,496 0 0 0
redo allocation 196,729 855 3 852 0 0 0
user lock 13,415 758 5 753 0 0 0
slave class create 192 15 16 0 0 0 0
Dictionary Cache Stats
Cache Get Requests Pct Miss Scan Reqs Pct Miss Mod Reqs
Final Usage
dc_awr_control 442 0.00 0 48 1
dc_database_links 9,562 0.02 0 0 3
dc_files 80 0.00 0 0 40
dc_global_oids 571 0.88 0 0 55
dc_histogram_data 93,357 0.10 0 0 1,379
dc_histogram_defs 210,451 0.37 0 162 4,934
dc_object_grants 1,005 10.85 0 0 630
dc_object_ids 698,144 0.02 0 6 1,142
dc_objects 90,831 0.26 0 140 1,761
dc_profiles 5,065 0.00 0 0 3
dc_rollback_segments 7,045 0.00 0 0 31
dc_segments 178,048 0.04 0 134 1,008
dc_sequences 156 1.92 0 156 14
dc_table_scns 2,804 0.00 0 74 10
dc_tablespace_quotas 88 0.00 0 0 12
dc_tablespaces 904,886 0.00 0 0 17
dc_usernames 30,976 0.02 0 0 41
dc_users 993,615 0.00 0 6 139
global database name 6,451 0.00 0 0 1
outstanding_alerts 577 0.00 0 2 14
Library Cache Activity
Namespace Get Requests Pct Miss Pin Requests Pct Miss Reloads
Invali-dations
BODY 61,206 0.01 88,056 0.01 3 0
CLUSTER 92 0.00 261 0.00 0 0
INDEX 26 0.00 249 0.00 0 0
JAVA DATA 37 0.00 0 0 0
JAVA SOURCE 57 0.00 114 1.75 1 0
SQL AREA 4,394 95.97 430,992 4.60 2,542 784
TABLE/PROCEDURE 15,299 0.73 276,194 0.17 170 0
TRIGGER 109 1.83 512 0.59 1 0
SGA Memory Summary
SGA regions Begin Size (Bytes)
Database Buffers 7,163,871,232
Fixed Size 2,086,552
Redo Buffers 14,688,256
Variable Size 1,409,288,552
init.ora Parameters
Parameter Name value
Thanks in Advance.
With Regards,
Raja.
Steve Howard
> Hi,
>
> I have another AWR Report generated with 1hr interval.
???
>
> AWR Report :
> Snap Id Snap Time Sessions Cursors/Session
> Begin Snap: 10739 13-Nov-08 09:00:45 105 58.2
> End Snap: 10763 13-Nov-08 15:00:12 91 75.2
???
Steve Howard
What is the issue with all of this, any way?
It looks like you had an average of 30% USER CPU for the duration of
the snap (92,000 seconds of USER CPU, with 14 CPU's over six hours of
available CPU to be used). That's not too bad? Is an SLA not being
met?
Also, why did you set these ?
joel garry
> Also, why did you set these ?
>
> init.ora Parameters
> Parameter Name value
>
>
>
> >> _newsort_enabled FALSE
> >> _optim_peek_user_binds FALSE
Can't speak for the OP, but at least one vendor of mine is magic-
bulleting _optim_peek_user_binds
jg
--
@home.com is bogus.
http://www.rottenneighbors.com
Steve Howard
We actually used it once for Oracle Text queries that would
misbehave. We *always* wanted to use the Text index, but sometimes
the optimizer would build a different cursor based on the bind that
was peeked. We literally had over 10,000 child cursors for a given
statement. The soft parsing killed us. We turned off bind peeking,
and the problem went away.
Six months later, it bit us in the rear for something else, though.
Regardless, that would still be the first question I would ask, though.
raja
Thanks for ur comments.
I trying to learn, how to interpret AWR Report.
Previously i had an awr report here ( pls see the previous posts of
this thread ), which charles, steve and sybrand helped to give me some
tips so that i can investigate more on it.
Similarly i have another AWR Report here with 1 hr interval ( having
this, as a place to make a study/analysis of awr report )
Just want to study this report too.
I dont know where to start from / where to look into first ( hot spots
in awr report to look into ), thats y pasted the awr report here for
discussion.
Still cant understand what steve Howard and joel garry, try to comment
on ? Please explain.
Steve Howard,
May i know how you calculated the below ones ...
"It looks like you had an average of 30% USER CPU for the duration of
the snap (92,000 seconds of USER CPU, with 14 CPU's over six hours of
available CPU to be used)."
Joel Garry,
Can you explain again on what you said ?
Steve Howard
>
> Steve Howard,
> May i know how you calculated the below ones ...
> "It looks like you had an average of 30% USER CPU for the duration of
> the snap (92,000 seconds of USER CPU, with 14 CPU's over six hours of
> available CPU to be used)."
>
Hi Raja,
The OS STAT piece of your AWR said you used...
Operating System Statistics
Statistic Total
<<snip>>
USER_TIME 9,246,603
NUM_CPUS 14
NUM_CPU_CORES 7
The USER_TIME is quoted in centiseconds, so 9,246,603 / 100 = ~ 92,000
seconds of user CPU over the six hour window.
You have 14 CPU's of time available to you, so...
6 hours * 14 CPU's = 302,400 seconds (14 * 6 hours * 60 minutes * 60
seconds)
92,000 used / 302400 available = ~30% utilized
That's an average over 6 hours, and I once saw Jonathan Lewis write
that if your head is on fire and your feet are are in a bucket of ice
water, on average you should be pretty comfortable :)
YMMV
HTH,
Steve
joel garry
> Joel Garry,
> Can you explain again on what you said ?
>
> Thanks in Advance.
>
> With Regards,
> Raja.
A magic bullet (synonym for silver bullet) is a magical simple answer
to a complex problem. In Oracle performance tuning, it refers to
setting a parameter or performing some process to fix a problem,
without properly defining the problem or solution. There has been
some controversy over this (that's an understatement!) in the Oracle
world. In general, a proper methodology for tuning will have ways to
define problems and solutions. Unfortunately, using magic works often
enough that some people consider it proper business practice. It
becomes difficult to distinguish it from best practices and reasonable
cookbooking (the latter would be making stuff work just by following
directions, without thinking about it - like Oracle installs, ignoring
configuration issues - XE is a good thing for a certain solution set,
for example). As Arthur Clarke (IIRC) put it, sufficiently advanced
technology is indistinguishable from magic. The problem with magic
bullets is they overstate how advanced the technology is, so Oracle
tuning is distinguishable from magic, as you hopefully will discover
as you learn AWR and statspack.
Bind peeking was kind of an overreach in the technology on Oracle's
part, in my opinion. Fortunately, when Oracle adds a feature like
this they usually leave in some way to turn it off, often using a
mystical incantation called an underscore init parameter. The problem
they were addressing was apparently increasing performance by putting
in some code to decide whether or not to make the optimizer have to
come up with a new plan. This created a new problem, which is that it
decides wrong, under some fairly common conditions - this is where I
thought they overreached, it should have been obvious - but I don't
know all the ins and outs of it, and don't know what they were
intending, this is just my opinion. Since optimization is potentially
done with any sql, and servers tend to not just do one thing, I think
the goof was missing the same sql could do quite different things -
getting a list of all product numbers for a drop down list of values,
versus just a few for a report, for example. So is there no
deterministic way to figure out whether bind peeking is a good idea?
As Steve said, setting the underscore variable had helped a problem -
only to bite them later. This is a general problem of
oversimplification, solving problems with magic bullets.
So I ran into a performance problem with some app code, where it is
not even asking Oracle to do anything. Some customers of the vendor
had discovered setting the underscore variable helped their vague
performance problem (which for all I know was another problem I had
run into, solved by adding an index). So when I tell the vendor about
the performance problem, they tell me to set the underscore variable.
I then laugh about it on usenet.
jg
--
@home.com is bogus.
"This site is intended solely for use by Oracle's authorized users.
Use of this site is subject to the Legal Notices, Terms for Use and
Privacy Statement located on this site. Use of the site by customers
and partners, if authorized, is also subject to the terms of your
contract(s) with Oracle. Use of this site by Oracle employees is also
subject to company policies, including the Code of Conduct.
Unauthorized access or breach of these terms may result in termination
of your authorization to use this site and/or civil and criminal
penalties. " Ahh, so that's how I terminate civial and criminal
penalties.
raja
Steve Howard,
So the CPU still has 30% available for resources and the system is not
overloaded. Then its good.
Joel Garry,
On web search i found that mostly these underscore init.ora parameters
( hidden parameters, should be used only if oracle support suggests to
us ) are creating problems ( side effects ).
I asked Charles, then why oracle has created them. Charles said
( please see previous posts ) its for flexibility ( depends upon the
application/system that we use ).
In the AWR Report that i have pasted, i hope those underscore init.ora
parameters are set to FALSE, so i hope there should not be any
problem.
In AWR Report, SQL Statistics, there are many parts like :
SQL ordered by Elapsed Time
SQL ordered by CPU Time
SQL ordered by Gets
SQL ordered by Reads
SQL ordered by Executions
SQL ordered by Parse Calls
SQL ordered by Sharable Memory
SQL ordered by Version Count
Which i should look into first ? why ?
Any other places that i have to check in the AWR Report ?
If you tell me some hot spots to look into, I will try and get back to
you with results, so that you people can correct me.
With Regards,
Raja.
Shakespeare
Try that same case with a light bulb and voltages. Metafores are
wonderful things....
Shakespeare
Charles Hooper
>
> I have another AWR Report generated with 1hr interval.
> I dont know how to approach this. Please help on this...
>
> AWR Report :
> Snap Id Snap Time Sessions Cursors/Session
> Begin Snap: 10739 13-Nov-08 09:00:45 105 58.2
> End Snap: 10763 13-Nov-08 15:00:12 91 75.2
> Elapsed: 359.46 (mins)
> DB Time: 1,723.72 (mins)
Raja,
One of my previous comments in this thread to you: "I would suggest
collecting an AWR report for 10 to 15 minutes, unless the performance
problem is only present in this 31 second time period." The first AWR
report was of such a short duration that it is possible to obtain
false positives (misleading information) about what is happening in
the system - it is quite possible that some event started in that
short time interval and ended just after the AWR snap ended, and it is
also possible that an event started long before the AWR snap started
and ended during the 31.2 second time interval. Some of the
statistics reported in the AWR report are updated in the database
immediately as they happen, and others are only updated in the
database at the end of the event (the completion of a SQL statement,
for instance). This inconsistency in the statistics may be very
misleading, and that is why I recommended running an AWR report for
10-15 minutes, as the longer duration allows a greater percentage of
events to start and end in the time interval. The latest version of
your AWR report goes to the other extreme, with a six hour duration.
The database server may have had severe performance problems for 30
minutes, yet when the statistics are averaged over six hours, the
system might appear to be only 10% busy _on average_ (0.5 hours / 6
hours = 8.3%), which is likely an acceptable value, and the severe
performance problem would be completely missed. That is what is meant
by the phrase "if your head is on fire and your feet are are in a
bucket of ice water, on average you should be pretty comfortable."
I will spend a couple minutes looking at the latest AWR report that
you posted, but I still suggest collecting an AWR report for 10 to 15
minutes (and only 10 to 15 minutes).
raja
I will try to get a AWR Report which has an interval of 10-15 minutes
interval.
Currently i have only this report and i am trying to analyze it.
In AWR Report, SQL Statistics, there are many parts like :
SQL ordered by Elapsed Time
SQL ordered by CPU Time
SQL ordered by Gets
SQL ordered by Reads
SQL ordered by Executions
SQL ordered by Parse Calls
SQL ordered by Sharable Memory
SQL ordered by Version Count
Which i should look into first ? why ?
With Regards,
Raja.
Charles Hooper
On first examination, I see:
Buffer Hit %: 99.89
One might say, that is a near perfect buffer cache hit ratio, move on
to the next report. But I have an example which shows a 100% buffer
cache hit ratio and the performance of the database
instance was terrible, so maybe we should permanently ignore this
statistic.
Watch for line wrapping (word wrapping) in the following:
Just a couple statistics to frame the rest of the report:
Elapsed: 359.46 (mins) (21,567.6 seconds)
DB Time: 1,723.72 (mins) {DB Time includes CPU time and wait events
for all sessions}
One approach to looking at the AWR/Statspack reports might be to start
with the CPU usage and the wait events, and see if any further
investigation is needed.
NUM_CPUS 14
NUM_CPU_CORES 7
Total CPU Time Possible: 14 * 359.46 * 60 seconds = 301,946.4 seconds
- note that it is unlikely that processes will jump from one CPU to
another CPU, although if parallel processing is in
use, more than one CPU might be used to retrieve the data for SQL
statements. It is quite possible that one CPU might become nearly
100% busy, yet the average CPU busy calculation might
might indicate that the CPUs are only 7% busy.
CPU time: 56,931 seconds
Percentage of total possible CPU Time that was consumed by Oracle:
56,931/301,946 = 18.9%
The above is not conclusive, digging deeper...
What is happening at the system level:
OS Statistics
Statistic Total
AVG_BUSY_TIME 773,431/100= 7,734.31s (total divided by # CPUs)
AVG_IDLE_TIME 1,382,735/100= 13,827.35s
AVG_IOWAIT_TIME 198,722/100= 1,987.22s
AVG_SYS_TIME 112,958/100= 1,129.58s
AVG_USER_TIME 659,771/100= 6,597.71s
OS_CPU_WAIT_TIME 11,375,200/100=113,752.00s
OS_CPU_WAIT_TIME is defined as: Total number of seconds that processes
have been in a ready state, waiting to be selected by the operating
system scheduler to run. This seems to indicate
that there was significant waiting for CPU time slices (competition
for the same CPU), even though the average CPU utilization at the
operating system level is 35.9%
[7,734.31/(7,734.31+13,827.35)]. Several processes are apparently
fighting for time on the same CPU.
You could look at the Time Model Statistics, but they may not be
telling much other than there may be a lot of context switches, and
more than half of the total SQL execution time was spent
on the CPUs (rather than waiting for disk or other wait events):
Statistic Name Time (s) % of DB Time
sql execute elapsed time 102,885.27 99.48
DB CPU 56,931.50 55.05
Java execution elapsed time 18,173.85 17.57
PL/SQL execution elapsed time 1,146.88 1.11
...
DB time 103,423.35
background elapsed time 9,817.43
background cpu time 1,169.73
The hierarchy of the above Time Model Statistics should be read like
this:
1) background elapsed time 9,817.43
2) background cpu time 1,169.73 (of the 9,817.43)
1) DB time 103,423.35
2) DB CPU 56,931.50 (of the 103,423.35)
2) connection management call elapsed time
2) sequence load elapsed time
2) sql execute elapsed time
2) parse time elapsed
3) hard parse elapsed time
4) hard parse (sharing criteria) elapsed time
5) hard parse (bind mismatch) elapsed time
3) failed parse elapsed time
4) failed parse (out of shared memory) elapsed time
2) PL/SQL execution elapsed time 1,146.88
2) inbound PL/SQL rpc elapsed time
2) PL/SQL compilation elapsed time
2) Java execution elapsed time 18,173.85 (of the 103,423.35)
Let's switch our attention to the wait events, but first a couple
statistics to provide a frame of reference:
SQL*Net roundtrips to/from client 4,813,090
SQL*Net roundtrips to/from dblink 43,646
user calls 4,836,293
user commits 24,259
user rollbacks 20
...
According to the number of waits for the SQL*Net events, on average,
just about every request for data from the server requires two sends
as the data returned is too large to fit into the SDU
(defaults to 2,000 bytes) - this is based on comparing the value of
"SQL*Net message to client" to the value of "SQL*Net more data to
client". This indicates that network latency, if
significant, could have a significant impact on apparent database
performance.
There are timeouts reported for some of the wait events - this may be
a critical indicator. If the timeout for a paricular wait event
happens to be 3 seconds, and 88% of the waits for an
event happen to result in time outs, that means on average 88% of the
time the event happens, it will last 3 seconds in duration. However,
the wait count increases by 1 every time a time-out
occurs, thus it might be a single session waiting non-stop for 42
seconds (16 * 87.50 * 3 seconds) = 42 seconds.
"db file sequential read" indicates that Oracle is reading one block
from disk - this usually indicates that Oracle is reading from an
index, but might also happen rarely during a tablescan
(if the other blocks needed are already in the buffer cache), or when
reading the undo blocks to provide a consistent read. "db file
scattered read" indicates that Oracle is reading more
than one block at a time from disk - this usually indicates that
Oracle is reading from a table during a full table scan.
"db file parallel write" indicates waits related to the DBWR process,
and may be related to the number of DBWR processes or DBWR I/O
slaves. May also indicate slow or high contention devices. I believe
that I previously commented on the value of the parameter
db_writer_processes, and suggested that you take a look at an article
on Kevin Closson's website related to what happens when that parameter
is set to a high value - that article talks about the impact on CPU
queuing, which seems to be a problem in this AWR report.
"log file parallel write" indicates Writing redo records to the redo
log files from the log buffer. This usually indicates slow devices or
contention where the online redo logs are located.
Take a look at the definitions for the other wait events.
Use the CPU utilization and wait events to determine what other
sections of the AWR report need to be examined. Post the results of
your findings.
joel garry
The why relates to why you are looking at this report in the first
place. You should be familiar with the system and how it is running,
and have some idea of what is wrong. It's easy to fall into the trap
of tuning for tuning's sake, also wittily referred to as OTD -
Obsessive Tuning Disorder. It's also easy to fall into the trap of
saying "no one is complaining, so therefore nothing is wrong."
Personally, I think there is value in checking a system to be sure
nothing is about to become a problem, or become a problem when two not-
problems run concurrently. Also, when a bottleneck is created, things
can go downhill in a hurry, one wants to be aware of what to watch
for. This falls under the part of a DBA's job called "knowing your
system."
Tuning is an iterative process, too. You need to order the importance
of what is wrong, and from there decide which to look for first. Once
you've fixed it, something else may show up. It is even possible the
fix may make things worse. For example, you may discover lots of
context switching due to unnecessary PL calls by a major app, and
decide to fix it by converting a particular bit of code to SQL. Then
the processor is free to do everything faster, overwhelming the I/O
system with calls.
So, it depends. That's why you follow a particular methodology,
preferably based on rational inquiry like Charles is demonstrating,
rather than just twiddling with ratios or expecting some cookbook
scheme to help. The trick is to tease out the clues that send you in
the right direction, and ignore the red herrings. So what is the
database waiting for? Are the waits what you would expect given what
your application is doing? Charles' SDU comment is certainly worth
investigating further.
You might want to briefly look at top sql by parse calls if you are
using a packaged app, some vendors write poor code (ie, without bind
variables) and it becomes painfully obvious when your most-used code
suffers from excessive parsing. Also compare the top executed with
all the others, at least to be sure your most executed code is working
as it should. Sometimes some blatant easily fixable errors pop out
there. But then again, the same applies to all those top sql lists.
jg
--
@home.com is bogus.
raja
I will check with the definitions of wait events and get back to you.
Thanks.
With Regards,
Raja.
raja
I have also another information which would help to solve the problem
along with the AWR Report.
From the advisor tables, i got the following information ( these were
the findings made by oracle ) :
Application Analysis :
-----------------------
Wait event "Backup: sbtwrite2" in wait class "Administrative"
Wait event "Data file init write" in wait class "User I/O"
Wait event "enq: CF - contention" in wait class "Other"
Wait event "enq: JI - contention" in wait class "Other"
Wait event "enq: TC - contention" in wait class "Other"
Wait event "inactive session" in wait class "Other"
Wait event "SQL*Net more data from dblink" in wait class "Network"
Wait event "wait for a undo record" in wait class "Other"
Waits on event "log file sync" while performing COMMIT and ROLLBACK
operations
I will check over the above wait events also and get back to you.
Waits on event "log file sync" while performing COMMIT and ROLLBACK
operations - i think we should not use more commits in the
application, to solve this problem.
I hope most of the above mentioned wait events were due to the Backup
activity that has been taken place ( This was also present in the AWR
Report).
I have consolidated the above wait events ( data was taken for 2
months )
So the problem with the database should be mostly with the backup
activity only.
Charles Hooper
While the Application Analysis information that you provided may be
helpful, it is probably best to focus on a specific time interval in
which you know that a performance problem is affecting *important
business critical* activities. Is the backup requiring an extra 15
minutes to complete an *important business critical* activity (it
might be), or is a repeated (user interactive) process which should
take 10 seconds to execute that now takes takes 2 minutes to execute a
greater *important business critical* activity. If you determine that
it is a specify user activity which is more important, look at an AWR
report for the time interval when the user activity is happening. If
there is a specific user involved in the performance problem, switch
to a 10046 trace at level 8 or 12 for just that user.
The excessive wait time for "log file sync" could possibly be
minimized/reduced by allocating a greater percentage of the *battery
back* RAID cache to write back caching, if that is an option in your
environment. When a commit is executed, the session must wait on this
event until Oracle receives confirmation from the operating system
that the write to disk completed. With write back caching, the write
confirmation is returned immediately, and the data in the cache is
later flushed to disk.
When investigating the wait events, do not just find the definitions
of those wait events. Dig deeper into the meaning of the wait events
by seeing if those wait events are discussed by Tom Kyte, Cary
Millsap, Jonathan Lewis, Richard Foote, Kevin Closson, etc.
Steve Howard
Raja,
It sounds like you are interested in knowing how to read an AWR
report, without any real problem currently at hand. That's OK,
because that is the best time to learn (when you are not on fire).
I would suggest you do some time series analysis of your AWR to get a
feel for what types of "stuff" you see and when you see them. You can
then begin to model your application and know when something is in
fact, "wrong".
Try something like what is below to get you started. You can graph
the output in Excel to see what the trend is in your database, in this
case of single block reads. You can then apply this type of query to
other events in dba_hist_system_event, as well as other AWR views,
such as dba_hist_systat...
select to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
dhse.instance_number,
time_waited_micro - lag(time_waited_micro, 1, 0) over (order by
dhse.instance_number, dhse.snap_id) as time_waited,
total_waits - lag(total_waits, 1, 0) over (order by
dhse.instance_number, dhse.snap_id) as total_waits
from dba_hist_snapshot dhs,
dba_hist_system_event dhse
where dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
and event_name = 'db file sequential read'
order by 1,2;
If you see db file sequential read is always at the top of the list
every reporting period, then an AWR that shows this was the top event
is probably not a real problem.
If you run an analysis against other items in AWR and one bubbles to
the top between 2AM and 4AM every Wednesday morning that you never see
otherwise, that may be something to investigate more in the AWR report
during the periods of the bubble. I find that to be absolutely
indispensable when trying to uncover "un-reported" performance
problems.
HTH,
Steve
joel garry
While it has a great danger of chasing after wild geese, I've found EM
in the form of dbconsole does have some informative charts, in a gross
sense. I see a cute little blue i/o pyramid every half hour, a known
stupid update routine. When there is a solid bar of green on the cpu
chart, I know to look for a couple of certain programs - if it is any
other, definitely a warning of phone calls to come. The screen about
top memory consumption can be an eye opener. The [PS]GA advisors
turn that stuff into a few minutes of surfing (until I hit a Jonathan
Lewis post...). And after all, it's just another way to look at the
same tuning information.. Sometimes you can even look at the sql ADDM
is running.
Then as soon as I think "hey this is a cool tool," it does some stupid
thing that makes me glad I can figure out how to look under the
covers. But this one is new to me, thanks Steve (if I ever have time
to try it :-) .
jg
--
@home.com is bogus.
I wish someone would develop excelbane.
http://www.theregister.co.uk/2008/10/15/lehman_buyout_excel_confusion/
raja
I took the output of the query which you have given in the previous
post.
I am not able to post the output file here. So i am sending you and
charles.
The file contains the output that was taken from 25/11/2008 -
03/12/2008
In average, it looks like ordering the output by total waits, shows
"PX qref latch" as the priority.
I searched regarding this and found that it is related to parallel
processing.
( I also feel that they might have used parallel hint to make the
queries faster. Let me check out on these. )
Please check the file that i have sent to ur mail id and provide me ur
suggestions.
With Regards,
Raja.
Charles Hooper
Raja,
I examined the spreadsheet - negative numbers should not appear when
subtracting the old values from the new values. You may need to make
an adjustment to the SQL statement if you plan to look at more than
one wait event at a time, or if there are more than one database
instances.
The SQL statement might need to be modified like this (I do not have
an AWR license, so this might not work as written):
select
to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
dhse.instance_number,
time_waited_micro - nvl(lag(time_waited_micro, 1, 0) over (partition
by dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
time_waited,
total_waits - nvl(lag(total_waits, 1, 0) over (partition by
dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
total_waits
from
dba_hist_snapshot dhs,
dba_hist_system_event dhse
where
dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
order by
1,
2;
Just out of curiosity, I would like to see an updated version of the
spreadsheet using the new SQL statement.
In short, the "PX qref latch" wait event may not be the problem.
raja
Query 1 ( Query given by charles ) :
select
to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
dhse.instance_number,
time_waited_micro - nvl(lag(time_waited_micro, 1, 0) over (partition
by dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
time_waited,
total_waits - nvl(lag(total_waits, 1, 0) over (partition by
dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
total_waits
from dba_hist_snapshot dhs,
dba_hist_system_event dhse
where dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
order by 1, 2;
The output of your query is present in excel file named as : wait1
Query 2 ( Query given by steeve ) :
select * from (
select event_name, wait_class,to_char(begin_interval_time,'YYYY_MM_DD
HH24:MI'),
dhse.instance_number,
time_waited_micro - lag(time_waited_micro, 1, 0) over (order by
dhse.instance_number, dhse.snap_id) as time_waited,
total_waits - lag(total_waits, 1, 0) over (order by
dhse.instance_number, dhse.snap_id) as total_waits
from dba_hist_snapshot dhs,
dba_hist_system_event dhse
where dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
and begin_interval_time > sysdate - num_of_days_to_analyze
order by 5 desc)
where rownum < 10000;
The output of your query is present in excel file named as : wait2
Here, the wait event : "PX qref latch" tops the list
Since i am not able to post those files in our group's thread, i am
sending those files to ur mail ids.
Please check these 2 files and tell me your observations.
Also, another doubt is : whether should be neglect the idle events
always ? then why are they notified to us...
With Regards,
Raja.
Charles Hooper
> Hi Charles/ Steeve,
>
> Query 1 ( Query given by charles ) :
> select
> to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
> dhse.instance_number,
> time_waited_micro - nvl(lag(time_waited_micro, 1, 0) over (partition
> by dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
> time_waited,
> total_waits - nvl(lag(total_waits, 1, 0) over (partition by
> dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
> total_waits
> from dba_hist_snapshot dhs,
> dba_hist_system_event dhse
> where dhs.snap_id = dhse.snap_id
> and dhs.instance_number = dhse.instance_number
> order by 1, 2;
>
> sending those files to ur mail ids.
> Please check these 2 files and tell me your observations.
> Also, another doubt is : whether should be neglect the idle events
> always ? then why are they notified to us...
>
> With Regards,
> Raja.
Raja,
Now that I am able to see the output of the query that I suggested
that you run, I see that I did not tell you to select the
dhse.event_name column, so I am not able to see the wait event names
associated with the various waits, also the sort order probably needs
to be improved. The fixed query should look something like this:
select
dhse.event_name,
to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
dhse.instance_number,
time_waited_micro - nvl(lag(time_waited_micro, 1, 0) over
(partition
by dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
time_waited,
total_waits - nvl(lag(total_waits, 1, 0) over (partition by
dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
total_waits
from dba_hist_snapshot dhs,
dba_hist_system_event dhse
where dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
order by 2, 4;
The idle wait events do have value, as they tell you to what degree
the database server is not causing performance problems (the user took
a 2 hour nap, resulting in a SQL*Net Message from Client exceeding 2
hours). Idle waits have a limited value in Statspack and AWR reports
(for instance "SQL*Net more data to client" shows 4,642,420 waits,
possibly indicating that the clients are requesting a lot of data to
be returned which will not fit into a single SDU size per request).
However, the idle wait events are very important wait events when
examining 10046 traces for sessions, as a 10046 trace is time scoped
for a single session.
raja
Kindly check the attached excel sheet.
Since i am not able to post here, i am sending the output to your mail
id.
Query :
select
dhse.event_name,
to_char(begin_interval_time,'YYYY_MM_DD HH24:MI'),
dhse.instance_number,
time_waited_micro - nvl(lag(time_waited_micro, 1, 0) over (partition
by dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
time_waited,
total_waits - nvl(lag(total_waits, 1, 0) over (partition by
dhse.instance_number, dhse.event_name order by dhse.snap_id),0) as
total_waits
from dba_hist_snapshot dhs, dba_hist_system_event dhse
where dhs.snap_id = dhse.snap_id
and dhs.instance_number = dhse.instance_number
order by 2, 4;
Kindly provide me your suggestions.
With Regards,
Raja.
Charles Hooper
As an experiment, I examined four time intervals for a single day, and
posted those numbers below. "Wait/Sec" is a calculation where I
divided the original TIME_WAITED value by 1,000,000 so that the wait
time was stated in seconds, and then divided that value by 3,600
(there are 3,600 seconds in an hour, as the totals were over the
course of an hour). The number calculated is the number of seconds
waited per second, accumulated for all sessions/processes waiting on
that event (that would explain the value of 9.52 below).
Between 2008_12_16 02:00 and 2008_12_16 03:00
EVENT_NAME TOTAL_WAITS Wait/Sec
jobq slave wait 1,394 1.05
db file sequential read 469,456 0.59
SQL*Net break/reset to client 9,236,797 0.35
SQL*Net more data from dblink 220,844 0.28
db file parallel write 260,297 0.17
Backup: sbtwrite2 36,033 0.10
log file parallel write 8,771 0.06
log file sequential read 6,602 0.02
single-task message 489 0.01
log file sync 2,238 0.01
Log archive I/O 7,783 0.00
RMAN backup & recovery I/O 5,302 0.00
Between 2008_12_16 07:00 and 2008_12_16 08:00
EVENT_NAME TOTAL_WAITS Wait/Sec
PX Deq: Execution Msg 97,375 9.52
PX Idle Wait 14,453 6.52
PX Deq Credit: send blkd 3,162,989 5.72
PX Deq: Table Q Normal 17,889,617 4.82
jobq slave wait 4,112 3.20
db file scattered read 435,471 1.61
db file sequential read 881,400 0.69
PX Deq: Execute Reply 17,145 0.58
SQL*Net break/reset to client 7,065,596 0.37
direct path write temp 10,411 0.33
read by other session 705,527 0.26
Backup: sbtwrite2 40,263 0.24
PX Deq Credit: need buffer 287,494 0.22
direct path read 1,363,276 0.16
db file parallel write 20,396 0.13
PX qref latch 204,808,981 0.10
direct path read temp 36,759 0.07
log file parallel write 9,155 0.04
single-task message 516 0.01
log file sequential read 3,559 0.01
log file sync 3,387 0.01
optimizer stats update retry 130 0.01
PX Deq: Msg Fragment 21,945 0.01
enq: TX - row lock contention 233 0.00
enq: MS - contention 3 0.00
Between 2008_12_16 14:00 and 2008_12_16 15:00
EVENT_NAME TOTAL_WAITS Wait/Sec
jobq slave wait 3,792 2.95
db file sequential read 1,044,182 0.49
SQL*Net break/reset to client 9,797,440 0.33
Backup: sbtwrite2 13,535 0.04
db file scattered read 152,387 0.03
read by other session 30,474 0.02
single-task message 516 0.01
db file parallel write 3,351 0.00
log file parallel write 5,155 0.00
log file sync 2,678 0.00
Between 2008_12_16 19:00 and 2008_12_16 20:00
EVENT_NAME TOTAL_WAITS Wait/Sec
Backup: sbtwrite2 352,599 3.74
jobq slave wait 3,709 2.89
SQL*Net break/reset to client 8,473,325 0.36
db file sequential read 161,017 0.21
RMAN backup & recovery I/O 13,208 0.11
log file parallel write 7,232 0.03
db file parallel write 13,223 0.03
single-task message 511 0.01
log file sequential read 3,066 0.01
log file sync 2,695 0.00
read by other session 972 0.00
The above may contain some "idle" wait events. What is possibly
interesting is the consistently high number of waits on the event
"SQL*Net break/reset to client", indicating that the client is
submitting something, possibly a badly formed SQL statement, and the
database instance is rejecting the message sent by the client. The
time consumed seems to be a faily consistent 1/3 of a second per
second in all four of the time intervals. You might check the per
session statistics to see which sessions are involved.
I will delay my analysis of the above until you have had an
opportunity to research and report your findings regarding what the
above may be showing. I would encourage others viewing this thread to
offer suggestions or an analysis of the above in the context of this
thread.
raja
Thanks for guiding me Charles and Steve.
From the wait list given by Charles, i have tried to look into the
wait event descriptions and made my following observations.
In general the wait list has been split into 4 parts :
Part 1 -> 2am to 3am ; Part 2 -> 7am to 8am ; Part 3 -> 2pm to 3pm ;
Part 4 -> 7pm to 8pm
First let us Neglect following the idle events from the wait list :
jobq slave wait
PX Deq Credit: need buffer
PX Deq: Execute Reply
PX Deq: Execution Msg
PX Deq: Msg Fragment
PX Deq: Table Q Normal
PX Idle Wait
single-task message
In general - about the application analysis - the following 2
observations are :
a. if we see the no.of wait events, it looks like they are at : Part
2 -> 7am to 8am, which should be the peak hour of the transaction.
b. the jobs, backup and recovery, archiving should be run when it is
in less peak hour : Part 1 -> 2am to 3am,
since there are the following events :
Backup: sbtwrite2 - ( Administrative - Wait class )
Log archive I/O
RMAN backup & recovery I/O.
With respect to wait events, the observations are as follows :
c. The following wait events are due to parallel process - it is like
running parallel queries, using parallel hints.
PX Deq Credit: send blkd
PX qref latch
solution to solve this problem is (from web) : increasing the value of
parallel_execution_message_size parameter.
But I feel that reducing the usage of parallel hints will reduce this
problem. but this would either cause not the efficient usage of the
CPU or not finishing the query execution faster !!!
d. read by other session :
In previous versions this wait was classified under the "buffer busy
waits" event. However, in Oracle 10.1 and higher this wait time is now
broken out into the "read by other session" wait event. Excessive
waits for this event are typically due to several processes repeatedly
reading the same blocks, e.g. many sessions scanning the same index or
performing full table scans on the same table.
solution to solve this problem is (from web) :
->buffer busy waits / read by other session: Increase DB_CACHE_SIZE
(DB_BLOCK_BUFFERS prior to 9i)/ Analyze contention from SYS.V$BH
But going through the link : http://www.confio.com/English/Tips/Read_By_Other_Session.php,
i feel that tuning the queries would be the option to reduce this
wait. Have to check for hot blocks/objects too ?
e.
In Oracle, we see two types of data block access - db file sequential
read and db file scattered read :
->db file sequential read — A single-block read (i.e., index fetch by
ROWID).
A large number of waits here could indicate poor joining orders of
tables, or unselective indexing. It is normal for this number to be
large for a high-transaction, well-tuned system, but it can indicate
problems in some circumstances.
They can also show up as direct path read/write waits.
->db file scattered read — A multiblock read (a full-table scan, OPQ,
sorting)
A large number here indicates that your table may have missing or
suppressed indexes. Although it may be more efficient in your
situation to perform a full table scan than an index scan, check to
ensure that full table scans are necessary when you see these waits.
Try to cache small tables to avoid reading them in over and over
again
solution to solve this problem is (from web) : increase the RAM size
of the db_cache_size to reduce disk I/O, tune the SQL to reduce disk I/
O, or invest in a faster disk I/O subsystem.
->log file sequential read - indicates that the process is waiting for
blocks to be read from the online redo log into memory. This primarily
occurs at instance startup and when the ARCH process archives filled
online redo logs.
->db file parallel write - occurs when the process, typically DBWR,
has issued multiple I/O requests in parallel to write dirty blocks
from the buffer cache to disk, and is waiting for all requests to
complete.
( dont know much - have to check regarding DBWR )
Looks like this is mostly due to i/o issue.
The direct path read, direct path write wait events are also
associated with the data block access (db file sequential read and db
file scattered read ) - dont know about these wait events, have to
check regarding these.
Info : Starting in Oracle 10g release2, Oracle recommends not setting
the db_file_multiblock_read_count parameter.
solution to solve these problem are (from web) :
->db file sequential read: Tune SQL to do less I/O. Make sure all
objects are analyzed. Redistribute I/O across disks.
So, in general to reduce the following waits, we have to tune the sql
queries (checking the indexes and joins) may give improvement in
performance :
db file sequential read,
db file scattered read,
log file sequential read,
db file parallel write,
direct path read, and
direct path write
f. The following 3 wait events comes together, since they are related
to LGWR/redo log ( dont know much - have to check regarding LGWR/redo
log )
->log file sequential read - LGWR background process waits for this
event while it is copying redo records from the memory Log Buffer
cache to the current redo group's member logfiles on disk.
->log file sync - User session waits on this wait event while waiting
for LGWR to post after commit write of dirty blocks
->log file parallel write - Waiting for the writes of redo records to
the redo log files
solution to solve these problem are (from web) :
->log file sync: If this event is in the top 5, you are committing too
often (talk to your developers)
->log file parallel write: deals with flushing out the redo log buffer
to disk. Your disks may be too slow or you have an I/O bottleneck.
Conclusion from the above wait event list given by you :
More waits are seen (db file sequential read, db file scattered
read ), which are due to i/o's.
To reduce these wait events, have to tune the sql ( check index and
joins).
Thanks. I have learnt something about the wait events.
Please check whether the above observations are correct ?
Also, Please provide your suggestions too...
With Regards,
Raja.
Charles Hooper
On Dec 23, 11:21 am, raja <dextersu...@gmail.com> wrote:
> In general the wait list has been split into 4 parts :
> Part 1 -> 2am to 3am ; Part 2 -> 7am to 8am ; Part 3 -> 2pm to 3pm ;
> Part 4 -> 7pm to 8pm
>
> First let us Neglect following the idle events from the wait list :
> jobq slave wait
> PX Deq Credit: need buffer
> PX Deq: Execute Reply
> PX Deq: Execution Msg
> PX Deq: Msg Fragment
> PX Deq: Table Q Normal
> PX Idle Wait
> single-task message
You might need to decide whether or not these "idle" events should be
ignored, especially those related to parallel query. For the 7 AM to 8
AM time period the "PX Deq: Execution Msg" wait event is the top wait
event, with an average of 9.52 processes in this wait event. You
might take a look at this and similar links:
http://www.orafaq.com/maillist/oracle-l/2002/05/18/1618.htm
The third highest wait event with an average of 5.72 processes in this
wait event during this time interval is "PX Deq Credit: send blkd" -
read all replies in this thread to see if there is a reason not to
ignore this event:
http://forums.oracle.com/forums/message.jspa?messageID=2521467
You might want to check a couple of the other "idle" wait events here:
http://oracledoug.com/px8.html
Another good link:
http://jonathanlewis.wordpress.com/2006/12/28/parallel-execution/
> In general - about the application analysis - the following 2
> observations are :
> a. if we see the no.of wait events, it looks like they are at : Part
> 2 -> 7am to 8am, which should be the peak hour of the transaction.
> b. the jobs, backup and recovery, archiving should be run when it is
> in less peak hour : Part 1 -> 2am to 3am,
> since there are the following events :
> Backup: sbtwrite2 - ( Administrative - Wait class )
> Log archive I/O
> RMAN backup & recovery I/O.
Yes, it looks like the backups were started around 7 PM and were
possibly still running at 7 AM, but I may not be fully understanding
the "Backup: sbtwrite2" wait event - are the archived redo logs
written to tape as they are created?
> With respect to wait events, the observations are as follows :
> c. The following wait events are due to parallel process - it is like
> running parallel queries, using parallel hints.
> PX Deq Credit: send blkd
> PX qref latch
> solution to solve this problem is (from web) : increasing the value of
> parallel_execution_message_size parameter.
> But I feel that reducing the usage of parallel hints will reduce this
> problem. but this would either cause not the efficient usage of the
> CPU or not finishing the query execution faster !!!
This link suggests that the change to the parameter might make matters
worse:
http://oracledoug.com/px8.html
> d. read by other session :
> In previous versions this wait was classified under the "buffer busy
> waits" event. However, in Oracle 10.1 and higher this wait time is now
> broken out into the "read by other session" wait event. Excessive
> waits for this event are typically due to several processes repeatedly
> reading the same blocks, e.g. many sessions scanning the same index or
> performing full table scans on the same table.
> solution to solve this problem is (from web) :
> ->buffer busy waits / read by other session: Increase DB_CACHE_SIZE
> (DB_BLOCK_BUFFERS prior to 9i)/ Analyze contention from SYS.V$BH
> But going through the link :http://www.confio.com/English/Tips/Read_By_Other_Session.php,
> i feel that tuning the queries would be the option to reduce this
> wait. Have to check for hot blocks/objects too ?
"read by other session" is related to buffer busy waits, but it is a
very specific type of buffer busy wait in older versions of Oracle, it
appears that you need to be a little careful trying to rely too much
on some websites. From the Oracle documentation:
http://download.oracle.com/docs/cd/B28359_01/server.111/b28320/waitevents003.htm#insertedID107
"This event occurs when a session requests a buffer that is currently
being read into the buffer cache by another session. Prior to release
10.1, waits for this event were grouped with the other reasons for
waiting for buffers under the 'buffer busy wait' event"
My notes on this wait event are the following: "This event indicates
that multiple processes are attempting to read a block from disk
concurrently, while one session is reading the block from disk, the
other sessions wait on this event. Determine if there are too many
active files on the same file system exhausting IO bandwidth. If
parallel execution (PX) is being used, determine if the IO subsystem
is saturated by having too many slaves in use. This event likely
indicates disk contention."
Parallel query is a bit unique, as it requires dirty (previously
changed) blocks in the buffer cache to be written to the data files
before the parallel operation may start. The parallel slaves then
bypass the buffer cache when executing, so increasing the
DB_CACHE_SIZE may make the problem worse as more dirty buffers may
need to be flushed to disk before the parallel operation begins.
There are certainly better descriptions of how parallel query is a bit
unique, but I was unable to quickly locate a reference to provide.
> e.
> In Oracle, we see two types of data block access - db file sequential
> read and db file scattered read :
> ->db file sequential read — A single-block read (i.e., index fetch by
> ROWID).
> A large number of waits here could indicate poor joining orders of
> tables, or unselective indexing. It is normal for this number to be
> large for a high-transaction, well-tuned system, but it can indicate
> problems in some circumstances.
> They can also show up as direct path read/write waits.
Mostly true, but could also be reported during a full tablescan if
adjacent table blocks are already in the buffer cache, or for reading
the undo tablespace to provide a consistent read. I am fairly certain
that this wait event is not related to direct path read/write waits.
> ->db file scattered read — A multiblock read (a full-table scan, OPQ,
> sorting)
> A large number here indicates that your table may have missing or
> suppressed indexes. Although it may be more efficient in your
> situation to perform a full table scan than an index scan, check to
> ensure that full table scans are necessary when you see these waits.
> Try to cache small tables to avoid reading them in over and over
> again
> solution to solve this problem is (from web) : increase the RAM size
> of the db_cache_size to reduce disk I/O, tune the SQL to reduce disk I/
> O, or invest in a faster disk I/O subsystem.
Note that these waits may also appear during index fast full scans. I
am not so certain that db file scattered read would be reported for
Oracle Parallel Query ("direct path read" is more likely) or for
sorting ("direct path read temp" is more likely). Due to the caching
algorithm used by Oracle when performing a full table scan (blocks
read are placed on the LRU end), unless the table has been assigned to
the KEEP buffer pool, increasing the size of the buffer cache (or the
keep buffer cache) probably will not help much, unless the table is
small (number of blocks below the high water mark) in comparison to
the size of the buffer cache.
> ->log file sequential read - indicates that the process is waiting for
> blocks to be read from the online redo log into memory. This primarily
> occurs at instance startup and when the ARCH process archives filled
> online redo logs.
>
> ->db file parallel write - occurs when the process, typically DBWR,
> has issued multiple I/O requests in parallel to write dirty blocks
> from the buffer cache to disk, and is waiting for all requests to
> complete.
> ( dont know much - have to check regarding DBWR )
> Looks like this is mostly due to i/o issue.
> The direct path read, direct path write wait events are also
> associated with the data block access (db file sequential read and db
> file scattered read ) - dont know about these wait events, have to
> check regarding these.
Probably associated with parallel query.
> Info : Starting in Oracle 10g release2, Oracle recommends not setting
> the db_file_multiblock_read_count parameter.
> solution to solve these problem are (from web) :
> ->db file sequential read: Tune SQL to do less I/O. Make sure all
> objects are analyzed. Redistribute I/O across disks.
If on Oracle 10.2.0.1 or above you allow Oracle to auto-tune the
db_file_multiblock_read_count parameter, the parameter will likely be
set to achieve a 1MB multiblock read size (a value of 128 will be set
for a database with an 8KB block size). This could have no effect or
it could have a significant effect on performance.
> So, in general to reduce the following waits, we have to tune the sql
> queries (checking the indexes and joins) may give improvement in
> performance :
> db file sequential read,
> db file scattered read,
> log file sequential read,
> db file parallel write,
> direct path read, and
> direct path write
I think that you may remove "log file sequential read" from the above
list, and possibly "db file parallel write".
> f. The following 3 wait events comes together, since they are related
> to LGWR/redo log ( dont know much - have to check regarding LGWR/redo
> log )
> ->log file sequential read - LGWR background process waits for this
> event while it is copying redo records from the memory Log Buffer
> cache to the current redo group's member logfiles on disk.
I am not sure that the above is correct. See:
http://download.oracle.com/docs/cd/B19306_01/server.102/b14237/waitevents003.htm
"Waiting for the read from this logfile to return. This is used to
read redo records from the log file."
> ->log file sync - User session waits on this wait event while waiting
> for LGWR to post after commit write of dirty blocks
The wait for the log file sync is very small compared to the other
events, maybe it should be ignored for now.
> ->log file parallel write - Waiting for the writes of redo records to
> the redo log files
The wait for log file parallel write is fairly small, maybe it should
be ignored for now.
In the 7 AM to 8 AM time interval, do not forget the more than
7,000,000 waits for "SQL*Net break/reset to client" - this could be
very important from a performance standpoint.
> Conclusion from the above wait event list given by you :
> More waits are seen (db file sequential read, db file scattered
> read ), which are due to i/o's.
> To reduce these wait events, have to tune the sql ( check index and
> joins).
>
> Thanks. I have learnt something about the wait events.
>
> Please check whether the above observations are correct ?
>
> Also, Please provide your suggestions too...
>
> With Regards,
> Raja.
You are trying very hard to understand the contents of an AWR/
Statspack report - you are using the right steps to understand the
problems. I am not an expert on parallel queries, so I may have made
a couple small mistakes in the above information.
raja
"You are trying very hard to understand the contents of an AWR/
Statspack report" - Its not me who is trying hard to learn, but its
people like you who make others to understand things, creating
interest in oracle and make us learn ourself by guiding us in the
right path.
Thanks for poeple like you.
Let me check over the things that you have discussed over the previous
post and get back to you.
With Regards,
Raja.