Home » RDBMS Server » Performance Tuning » Reading AWR
Reading AWR [message #547263] Tue, 13 March 2012 11:12 Go to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
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 #547267 is a reply to message #547263] Tue, 13 March 2012 11:25 Go to previous messageGo to next message
BlackSwan
Messages: 22512
Registered: January 2009
Senior Member
how many CPU & cores in the DB Server?
Re: Reading AWR [message #547269 is a reply to message #547263] Tue, 13 March 2012 11:32 Go to previous messageGo to next message
Michel Cadot
Messages: 58599
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
One of the expert advised that the problem is with the queries


This experts should explain if there is an problem and precisely where it is and why he thinks it is with SQL.

Regards
Michel
Re: Reading AWR [message #547277 is a reply to message #547269] Tue, 13 March 2012 11:40 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
Based on the elapsed time on the Query. in AWR.


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 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
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 Go to previous messageGo to next message
John Watson
Messages: 4390
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 #547283 is a reply to message #547279] Tue, 13 March 2012 11:58 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
Find it attached. What is CTD ?

Problem is the queries taking longer time and elapsed time in the report is higher.
  • Attachment: AWR.txt
    (Size: 202.56KB, Downloaded 449 times)
Re: Reading AWR [message #547285 is a reply to message #547283] Tue, 13 March 2012 12:01 Go to previous messageGo to next message
John Watson
Messages: 4390
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 #547287 is a reply to message #547285] Tue, 13 March 2012 12:05 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
The queries starting with "WITH " Clause. These are Oracle Procedures invoked from a reporting application , SQL SERVER reporting SERVICE.
Re: Reading AWR [message #547291 is a reply to message #547287] Tue, 13 March 2012 12:09 Go to previous messageGo to next message
John Watson
Messages: 4390
Registered: January 2010
Location: Global Village
Senior Member
You need to get reports for those particular queries, use the awrsqrpt.sql script.
Re: Reading AWR [message #547293 is a reply to message #547291] Tue, 13 March 2012 12:10 Go to previous messageGo to next message
John Watson
Messages: 4390
Registered: January 2010
Location: Global Village
Senior Member
And get them for several times, ie, the current snapshot and as far back in the past as you can go.
Re: Reading AWR [message #547296 is a reply to message #547293] Tue, 13 March 2012 12:16 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
I have to request the DBA to run awrsqrpt.sql . I don't think I will have privilege. What is the input I should I give to run this sql. the SQL id?
Re: Reading AWR [message #547300 is a reply to message #547278] Tue, 13 March 2012 12:22 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
Hi BlackSwan,

Thanks for adding tag, I missed it.

Does this info help you to analyze this anyway?

Thanks,

Ninan.
Re: Reading AWR [message #547304 is a reply to message #547300] Tue, 13 March 2012 12:26 Go to previous messageGo to next message
BlackSwan
Messages: 22512
Registered: January 2009
Senior Member
If things are slow, it is NOT due to any CPU bottleneck.

Since NOBODY can optimize SQL just by looking at it, we need a few more details.
http://www.orafaq.com/forum/m/433888/136107/#msg_433888
Please refer to URL above & be sure to provide the details requested:
1) DDL for all tables & indexes
2) EXPLAIN PLAN
3) output from SQL_TRACE & tkprof
Re: Reading AWR [message #547315 is a reply to message #547300] Tue, 13 March 2012 12:50 Go to previous messageGo to next message
Michel Cadot
Messages: 58599
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
For myself, I don't see any problem in what you posted (note that I can't read attached file).
So is there anyone (but you "expert") that reports some problem? Which one?

Regards
Michel
Re: Reading AWR [message #547318 is a reply to message #547315] Tue, 13 March 2012 13:02 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
Thanks Michel.

The "expert" tells me about the elapsed time, for the queries is a problem.
Re: Reading AWR [message #547319 is a reply to message #547318] Tue, 13 March 2012 13:11 Go to previous messageGo to next message
BlackSwan
Messages: 22512
Registered: January 2009
Senior Member
>The "expert" tells me about the elapsed time, for the queries is a problem.
what elapsed time? (none have been posted)
Which queries? (none have been posted)
Re: Reading AWR [message #547321 is a reply to message #547319] Tue, 13 March 2012 13:19 Go to previous messageGo to next message
ninan
Messages: 116
Registered: June 2011
Location: bangalore
Senior Member
elapsed time in AWR report , which I have pasted earlier and also attached earlier.
Re: Reading AWR [message #547324 is a reply to message #547321] Tue, 13 March 2012 13:25 Go to previous messageGo to next message
Michel Cadot
Messages: 58599
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Which elapsed time is a problem? Copy and paste the line.

Quote:
The "expert" tells me about the elapsed time, for the queries is a problem.


Ask the expert to explain his point.
Once again, for the moment, I do not see any problem.

Regards
Michel
Re: Reading AWR [message #547648 is a reply to message #547324] Thu, 15 March 2012 07:26 Go to previous messageGo to next message
LNossov
Messages: 284
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
Re: Reading AWR [message #547649 is a reply to message #547648] Thu, 15 March 2012 07:33 Go to previous message
Michel Cadot
Messages: 58599
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
And?

Regards
Michel
Previous Topic: Wait/Sleep command in SQL
Next Topic: How to find Local and global indexes on Particular Table
Goto Forum:
  


Current Time: Mon Jul 28 02:48:27 CDT 2014

Total time taken to generate the page: 0.07344 seconds