Home » RDBMS Server » Performance Tuning » Reading AWR
| Reading AWR [message #547263] |
Tue, 13 March 2012 11:12  |
 |
ninan
Messages: 163
Registered: June 2011
Location: Noida
|
Senior Member |
|
|
Can you please help me to understand this report.
One of the expert advised that the problem is with the queries, so I have to tune it because elapsed time is more here. i.e, 1215 secs.
But I have a doubt on the DB CPU time and service wait class of
SYS$BACKGROUND.
Snap Id Snap Time Sessions Curs/Sess
--------- ------------------- -------- ---------
Begin Snap: 3911 13-Mar-12 17:00:28 59 2.3
End Snap: 3912 13-Mar-12 18:00:10 76 2.1
Elapsed: 59.70 (mins)
DB Time: 99.61 (mins)
Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 848M 880M Std Block Size: 8K
Shared Pool Size: 640M 608M Log Buffer: 7,240K
Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ --------------- --------------- ---------- ----------
DB Time(s): 1.7 8.0 0.63 0.33
DB CPU(s): 1.3 6.2 0.49 0.25
Redo size: 623,022.9 3,003,527.9
Logical reads: 141,129.4 680,369.8
Block changes: 4,204.0 20,267.2
Physical reads: 969.8 4,675.4
Physical writes: 45.1 217.4
User calls: 5.1 24.6
Parses: 2.2 10.7
Hard parses: 0.0 0.2
W/A MB processed: 703,738.6 3,392,649.8
Logons: 0.7 3.2
Executes: 2.6 12.7
Rollbacks: 0.2 1.0
Transactions: 0.2
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.74 In-memory Sort %: 100.00
Library Hit %: 99.33 Soft Parse %: 98.08
Execute to Parse %: 16.12 Latch Hit %: 99.99
Parse CPU to Parse Elapsd %: 0.00 % Non-Parse CPU: 99.96
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 89.21 92.15
% SQL with executions>1: 91.45 89.64
% Memory for SQL w/exec>1: 84.26 79.14
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 4,577 76.6
db file parallel read 116,151 513 4 8.6 User I/O
gc cr multi block request 132,610 376 3 6.3 Cluster
db file sequential read 128,742 239 2 4.0 User I/O
direct path read 17,412 202 12 3.4 User I/O
Host CPU (CPUs: 24 Cores: 12 Sockets: 2)
~~~~~~~~ Load Average
Begin End %User %System %WIO %Idle
--------- --------- --------- --------- --------- ---------
0.55 1.72 5.4 0.2 1.1 94.3
Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 5.4
% of busy CPU for Instance: 94.3
%DB time waiting for CPU - Resource Mgr: 0.0
-> *TIME statistic values are diffed.
All others display actual values. End Value is displayed if different
-> ordered by statistic type (CPU Use, Virtual Memory, Hardware Config), Name
Statistic Value End Value
------------------------- ---------------------- ----------------
BUSY_TIME 489,123
IDLE_TIME 8,110,649
IOWAIT_TIME 97,540
NICE_TIME 129
SYS_TIME 19,518
USER_TIME 465,472
LOAD 1 2
RSRC_MGR_CPU_WAIT_TIME 0
PHYSICAL_MEMORY_BYTES 25,133,981,696
NUM_CPUS 24
NUM_CPU_CORES 12
NUM_CPU_SOCKETS 2
GLOBAL_RECEIVE_SIZE_MAX 4,194,304
GLOBAL_SEND_SIZE_MAX 262,144
TCP_RECEIVE_SIZE_DEFAULT 87,380
TCP_RECEIVE_SIZE_MAX 4,194,304
TCP_RECEIVE_SIZE_MIN 4,096
TCP_SEND_SIZE_DEFAULT 16,384
TCP_SEND_SIZE_MAX 4,194,304
TCP_SEND_SIZE_MIN 4,096
-------------------------------------------------------------
Snaps: 3911-3912
Snap Time Load %busy %user %sys %idle %iowait
--------------- -------- -------- -------- -------- -------- --------
13-Mar 17:00:28 0.5 N/A N/A N/A N/A N/A
13-Mar 18:00:10 1.7 5.7 5.4 0.2 1.1 94.3
-------------------------------------------------------------
Foreground Wait Class
Snaps: 3911-3912
-> s - second, ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Captured Time accounts for 100.2% of Total DB time 5,976.68 (s)
-> Total FG Wait Time: 1,410.16 (s) DB CPU time: 4,576.64 (s)
Avg
%Time Total Wait wait
Wait Class Waits -outs Time (s) (ms) %DB time
-------------------- ---------------- ----- ---------------- -------- ---------
DB CPU 4,577 76.6
User I/O 269,939 0 990 4 16.6
Cluster 200,817 0 396 2 6.6
Other 99,832 87 12 0 0.2
System I/O 2,574 0 4 2 0.1
Concurrency 2,573 1 3 1 0.1
Application 916 0 2 2 0.0
Configuration 233 0 2 8 0.0
Commit 98 0 1 9 0.0
Network 5,896 0 0 0 0.0
-------------------------------------------------------------
Foreground Wait Events
Snaps: 3911-3912
-> s - second, ms - millisecond - 1000th of a second
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Avg
%Time Total Wait wait Waits % DB
Event Waits -outs Time (s) (ms) /txn time
-------------------------- ------------ ----- ---------- ------- -------- ------
db file parallel read 116,151 0 513 4 156.3 8.6
gc cr multi block request 132,610 0 376 3 178.5 6.3
db file sequential read 128,742 0 239 2 173.3 4.0
direct path read 17,412 0 202 12 23.4 3.4
db file scattered read 7,630 0 35 5 10.3 .6
gc current grant 2-way 56,431 1 9 0 76.0 .1
DFS lock handle 381 15 5 12 0.5 .1
control file sequential re 2,574 0 4 2 3.5 .1
gc buffer busy acquire 13 15 4 297 0.0 .1
gc current block 2-way 9,220 2 3 0 12.4 .1
reliable message 2,939 0 2 1 4.0 .0
SQL*Net break/reset to cli 794 0 2 2 1.1 .0
gc current block lost 3 0 2 645 0.0 .0
os thread startup 16 0 2 115 0.0 .0
log file switch completion 47 0 2 36 0.1 .0
IPC send completion sync 10,782 91 2 0 14.5 .0
gc buffer busy release 4 25 1 257 0.0 .0
log file sync 98 0 1 9 0.1 .0
PX Nsq: PQ load info query 4 100 1 201 0.0 .0
enq: PS - contention 2,176 0 1 0 2.9 .0
PX Deq: reap credit 72,064 100 1 0 97.0 .0
buffer busy waits 18 0 1 40 0.0 .0
PX Deq: Slave Session Stat 5,658 26 0 0 7.6 .0
library cache pin 1,504 0 0 0 2.0 .0
read by other session 4 0 0 82 0.0 .0
gc cr grant 2-way 1,275 0 0 0 1.7 .0
enq: KO - fast object chec 122 0 0 2 0.2 .0
library cache lock 872 0 0 0 1.2 .0
PX Deq Credit: Session Sta 1,634 0 0 0 2.2 .0
name-service call wait 2 0 0 60 0.0 .0
gc cr block 2-way 328 0 0 0 0.4 .0
PX Deq: Signal ACK RSG 1,552 50 0 0 2.1 .0
gc current multi block req 506 0 0 0 0.7 .0
gc current grant busy 407 0 0 0 0.5 .0
gc current block busy 11 18 0 9 0.0 .0
enq: HW - contention 186 0 0 0 0.3 .0
row cache lock 137 0 0 0 0.2 .0
enq: JS - job run lock - s 57 100 0 0 0.1 .0
gc cr block busy 9 0 0 3 0.0 .0
SQL*Net message to client 5,652 0 0 0 7.6 .0
ges inquiry response 42 0 0 0 0.1 .0
PX Deq: Signal ACK EXT 91 0 0 0 0.1 .0
rdbms ipc reply 40 0 0 0 0.1 .0
cr request retry 348 100 0 0 0.5 .0
KJC: Wait for msg sends to 104 0 0 0 0.1 .0
PX qref latch 1,941 100 0 0 2.6 .0
SQL*Net more data to clien 134 0 0 0 0.2 .0
SQL*Net more data from cli 110 0 0 0 0.1 .0
library cache: mutex X 17 100 0 0 0.0 .0
SQL*Net message from clien 5,651 0 46,498 8228 7.6
PX Deq Credit: send blkd 34,265 8 28,288 826 46.1
Streams AQ: waiting for me 1,177 91 3,941 3348 1.6
jobq slave wait 570 100 1,711 3001 0.8
PX Deq: Execution Msg 10,992 25 641 58 14.8
PX Deq Credit: need buffer 386 1 314 814 0.5
PX Deq: Execute Reply 3,316 29 4 1 4.5
PX Deq: Parse Reply 2,255 36 1 1 3.0
PX Deq: Join ACK 1,330 0 1 0 1.8
PX Deq: Msg Fragment 4,975 34 0 0 6.7
-------------------------------------------------------------
Service Wait Class Stats DB/Inst: IOPDP/iopdp2 Snaps: 3911-3912
-> Wait Class info for services in the Service Statistics section.
-> Total Waits and Time Waited displayed for the following wait
classes: User I/O, Concurrency, Administrative, Network
-> Time Waited (Wt Time) in seconds
Service Name
----------------------------------------------------------------
User I/O User I/O Concurcy Concurcy Admin Admin Network Network
Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time Total Wts Wt Time
--------- --------- --------- --------- --------- --------- --------- ---------
iopdp_dr.dr.amer.dell.com
269900 989 966 3 0 0 2192 0
SYS$USERS
53 1 1606 0 0 0 3704 0
SYS$BACKGROUND
1536 8 17088 5 0 0 0 0
-------------------------------------------------------------
Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
----------------------------------------------------------------
1,215 286 1 1215.0 20.3
|
|
|
|
|
|
|
|
|
|
| Re: Reading AWR [message #547278 is a reply to message #547267] |
Tue, 13 March 2012 11:42  |
|
ninan
Messages: 163
Registered: June 2011
Location: Noida
|
Senior Member |
|
|
This is what I get from the AWR report..
Platform CPUs Cores Sockets Memory(GB)
---------------- -------------------------------- ---- ----- ------- ----------
Linux x86 64-bit 24 12 2 23.41
*BlackSwan added {code} tags to improve readability
[Updated on: Tue, 13 March 2012 12:06] by Moderator Report message to a moderator |
|
|
|
| Re: Reading AWR [message #547279 is a reply to message #547263] |
Tue, 13 March 2012 11:50 |
John Watson
Messages: 8931
Registered: January 2010
Location: Global Village
|
Senior Member |
|
|
You have stripped off some of the most useful parts of the report, can you post the whole thing? And of course what is the problem?
However, one thing does jump out: your DB CPU time is 76.6% of DB TIME. That ain't bad, it tells you that the database really is working, not waiting, and therefore probably no point in tuning the instance. So you may have to tune the application.
If, that is, you need to tune anything. I hope you aren't suffering from Compulsive Tuning Disorder.
|
|
|
|
|
|
| Re: Reading AWR [message #547285 is a reply to message #547283] |
Tue, 13 March 2012 12:01 |
John Watson
Messages: 8931
Registered: January 2010
Location: Global Village
|
Senior Member |
|
|
|
What you refer to as "elapsed time in the report" is not a problem. It is only a number in a report. What matters is wall-clock time: a business process takes longer than the users would like. You say "queries taking longer time": which queries?
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| Re: Reading AWR [message #547648 is a reply to message #547324] |
Thu, 15 March 2012 07:26 |
 |
LNossov
Messages: 318
Registered: July 2011
Location: Germany
|
Senior Member |
|
|
Hi Michel
I suppose, these elapsed times:
SQL ordered by Elapsed Time DB/Inst: / 2 Snaps: 3911-3912
-> Resources reported for PL/SQL code includes the resources used by all SQL
statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided
into the Total Database Time multiplied by 100
-> Total DB Time (s): 5,977
-> Captured SQL account for 98.3% of Total
-> Total DB Time (s): 5,977
-> Captured PL/SQL account for 98.1% of Total
Elapsed CPU Elap per % Total
Time (s) Time (s) Executions Exec (s) DB Time SQL Id
---------- ---------- ------------ ---------- ------- -------------
2,522 2,441 1 2522.0 42.2 ank4sbr3urr3m
Module: TOAD 10.1.1.8
begin update e2ec_item_ph b set fp_desc=(select distinct fp_desc from e2ec_pro
duct_hierarchy a where a.lob_id=b.lob_id and a.family_id=b.fmly_id) where
ccn = 'C40000'; commit; end;
2,469 2,426 1 2468.8 41.3 dyhcfyss545j9
Module: TOAD 10.1.1.8
UPDATE E2EC_ITEM_PH B SET FP_DESC=(SELECT DISTINCT FP_DESC FROM E2EC_PRODUCT_HIE
RARCHY A WHERE A.LOB_ID=B.LOB_ID AND A.FAMILY_ID=B.FMLY_ID) WHERE CCN = 'C40000'
1,399 315 3 466.5 23.4 bzb8b8xdrymd8
Module: ReportingServicesService.exe
begin GET_MTM_REP_PKG.GET_MTM_REP(P_USERGROUP=>:P_USERGROUP, P_REPORT=>:P_REPORT
, P_REPORTVIEW=>:P_REPORTVIEW, P_COSTTYPE=>:P_COSTTYPE, P_SELASOFDATE=>:P_SELASO
FDATE, P_SELCCN=>:P_SELCCN, P_PRIORASOFDATE=>:P_PRIORASOFDATE, P_SELBU=>:P_SELBU
, P_SELLOB=>:P_SELLOB, P_SELBRAND=>:P_SELBRAND, P_SELFP=>:P_SELFP, P_SELFAMILY=>
...
Regards
Leonid
|
|
|
|
|
|
Goto Forum:
Current Time: Wed Apr 24 09:42:19 CDT 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
