This discussion is archived
5 Replies Latest reply: Feb 12, 2013 6:07 AM by 990552 RSS

AWR Analysis

990552 Newbie
Currently Being Moderated
All,

My client is having an application which sends huge data (DML) into oracle DB with huge commits.

DB is 11.2.0.2 3 node RAC. In AWR i see Cluster, IO wait events:

Top Timed Events

Instance '*' - cluster wide summary
'*' Waits, %Timeouts, Wait Time Total(s) : Cluster-wide total for the wait event
'*' 'Wait Time Avg (ms)' : Cluster-wide average computed as (Wait Time Total / Event Waits) in ms
'*' Summary 'Avg Wait Time (ms)' : Per-instance 'Wait Time Avg (ms)' used to compute the following statistics
'*' [Avg/Min/Max/Std Dev] : average/minimum/maximum/standard deviation of per-instance 'Wait Time Avg(ms)'
'*' Cnt : count of instances with wait times for the event

     Wait      Event      Wait Time      Summary Avg Wait Time (ms)
I#     Class     Event     Waits     %Timeouts     Total(s)     Avg(ms)     %DB time     Avg     Min     Max     Std Dev     Cnt
*          DB CPU               13,824.93          21.68                         3
     Cluster     gc buffer busy release     436,010     0.04     11,018.18     25.27     17.28     25.21     23.91     26.29     1.20     3
     Cluster     gc current block busy     292,729     0.00     7,485.84     25.57     11.74     25.53     24.43     26.59     1.08     3
     Commit     log file sync     305,966     0.00     5,714.52     18.68     8.96     18.65     18.11     19.21     0.55     3
     System I/O     log file parallel write     591,415     0.00     5,681.62     9.61     8.91     9.60     9.38     9.85     0.24     3
     Cluster     gc buffer busy acquire     451,716     0.13     5,558.70     12.31     8.72     13.47     10.62     18.17     4.11     3
     Other     gcs log flush sync     2,527,757     3.43     3,965.91     1.57     6.22     1.57     1.52     1.61     0.05     3
     Cluster     gc cr block busy     203,275     0.00     3,938.88     19.38     6.18     19.42     18.13     20.28     1.13     3
     System I/O     db file parallel write     1,688,423     0.00     3,635.23     2.15     5.70     2.16     2.02     2.25     0.12     3
     Cluster     gc current block 2-way     1,533,649     0.00     2,849.37     1.86     4.47     1.84     1.80     1.90     0.05     3
1          DB CPU               5,182.75          22.03                         
     Cluster     gc buffer busy release     170,226     0.06     4,326.03     25.41     18.39                         
     Cluster     gc current block busy     96,868     0.00     2,366.07     24.43     10.06                         
     Commit     log file sync     113,587     0.00     2,182.26     19.21     9.28                         
     Cluster     gc buffer busy acquire     203,411     0.16     2,159.25     10.62     9.18                         
     System I/O     log file parallel write     211,897     0.00     2,086.50     9.85     8.87                         
     System I/O     db file parallel write     674,977     0.00     1,518.86     2.25     6.46                         
     Other     gcs log flush sync     936,981     3.13     1,472.32     1.57     6.26                         
     Cluster     gc current block 2-way     699,628     0.00     1,327.54     1.90     5.64                         
     Cluster     gc cr block busy     71,670     0.00     1,299.67     18.13     5.53                         
2          DB CPU               4,193.91          21.22                         
     Cluster     gc buffer busy release     124,277     0.01     2,971.95     23.91     15.03                         
     Cluster     gc current block busy     108,389     0.00     2,881.69     26.59     14.58                         
     System I/O     log file parallel write     184,188     0.00     1,763.66     9.58     8.92                         
     Commit     log file sync     94,321     0.00     1,756.28     18.62     8.88                         
     Cluster     gc buffer busy acquire     78,709     0.15     1,430.47     18.17     7.24                         
     Cluster     gc cr block busy     67,500     0.00     1,339.22     19.84     6.77                         
     Other     gcs log flush sync     778,606     3.50     1,182.68     1.52     5.98                         
     System I/O     db file parallel write     376,181     0.00     829.36     2.20     4.20                         
     Other     enq: FB - contention     141,822     0.00     613.97     4.33     3.11                         
3          DB CPU               4,448.27          21.72                         
     Cluster     gc buffer busy release     141,507     0.04     3,720.20     26.29     18.16                         
     Cluster     gc current block busy     87,472     0.00     2,238.08     25.59     10.93                         
     Cluster     gc buffer busy acquire     169,596     0.09     1,968.99     11.61     9.61                         
     System I/O     log file parallel write     195,330     0.00     1,831.45     9.38     8.94                         
     Commit     log file sync     98,058     0.00     1,775.98     18.11     8.67                         
     Other     gcs log flush sync     812,170     3.70     1,310.91     1.61     6.40                         
     Cluster     gc cr block busy     64,105     0.00     1,299.99     20.28     6.35                         
     System I/O     db file parallel write     637,265     0.00     1,287.01     2.02     6.28          
Cluster     gc current block 2-way     625,590     0.00     1,147.18     1.83     5.60

Load Profile:

System Statistics

I#     Logical Reads     Physical Reads     Physical Writes     Redo Size (k)     Block Changes     User Calls     Execs     Parses     Logons     Txns
1     660,246,304     10,588     6,108,621     61,408,883     227,914,819     1,390,688     842,125     99,173     741     112,444
2     528,112,160     496,517     4,894,272     48,201,955     180,212,408     1,688,845     788,422     92,305     552     93,426
3     554,450,192     13,957     5,149,779     52,332,506     195,211,150     1,409,997     795,309     103,876     895     98,048
Sum     1,742,808,656     521,062     16,152,672     161,943,345     603,338,377     4,489,530     2,425,856     295,354     2,188     303,918
Avg     580,936,219     173,687     5,384,224     53,981,115     201,112,792     1,496,510     808,619     98,451     729     101,306
Std     69,935,615     279,584     640,222     6,756,047     24,392,664     166,847     29,221     5,819     172     9,919

System Statistics - Per Second

I#     Logical Reads/s     Physical Reads/s     Physical Writes/s     Redo Size (k)/s     Block Changes/s     User Calls/s     Execs/s     Parses/s     Logons/s     Txns/s
1     61,223.89     0.98     566.45     5,694.38     21,134.28     128.96     78.09     9.20     0.07     10.43
2     48,970.64     46.04     453.83     4,469.66     16,710.69     156.60     73.11     8.56     0.05     8.66
3     51,412.72     1.29     477.53     4,852.66     18,101.42     130.75     73.75     9.63     0.08     9.09
Sum     161,607.26     48.32     1,497.81     15,016.69     55,946.39     416.31     224.94     27.39     0.20     28.18
Avg     53,869.09     16.11     499.27     5,005.56     18,648.80     138.77     74.98     9.13     0.07     9.39
Std     6,485.43     25.93     59.37     626.51     2,262.03     15.47     2.71     0.54     0.02     0.92

System Statistics - Per Transaction

I#     Logical Reads/tx     Physical Reads/tx     Physical Writes/tx     Redo Size (k)/tx     Block Changes/tx     User Calls/tx     Execs/tx     Parses/tx     Logons/tx
1     5,871.78     0.09     54.33     546.13     2,026.92     12.37     7.49     0.88     0.01
2     5,652.73     5.31     52.39     515.94     1,928.93     18.08     8.44     0.99     0.01
3     5,654.89     0.14     52.52     533.74     1,990.98     14.38     8.11     1.06     0.01
Avg     5,726.47     1.85     53.08     531.94     1,982.28     14.94     8.01     0.98     0.01


SysStat and Global Messaging - RAC

     Blocks Received      Blocks Served      CPU (seconds)      Messages      GC Blks      GC CR
I#     GC Current     GC CR     GC Current     GC CR     GC     IPC     GCS Received     GES Received     GCS Sent     GES Sent      Sent Direct     Sent Indir     Lost     Failure
1     1,103,531     188,244     554,826     473,053     0     0     8,972,337     1,221,285     8,989,831     1,242,078     2,120,587     4,142,918     32     77
2     607,697     716,593     1,668,509     173,636     0     0     10,002,688     1,276,734     9,795,640     1,317,581     1,676,785     4,579,098     37     57
3     1,044,839     173,096     532,568     431,185     0     0     8,160,011     1,246,734     8,349,110     1,185,179     1,982,439     3,931,956     26     72
Sum     2,756,067     1,077,933     2,755,903     1,077,874     0     0     27,135,036     3,744,753     27,134,581     3,744,838     5,779,811     12,653,972     95     206
Avg     918,689     359,311     918,634     359,291     0     0     9,045,012     1,248,251     9,044,860     1,248,279     1,926,604     4,217,991     32     69
Std     270,921     309,508     649,506     162,139     0     0     923,486     27,756     724,833     66,418     227,108     330,038     6     10

I am just looking for recommendations for performance improvement. We are considering to place redo logs on Fast Disk to reduce IO so is it okay to have 3 ASM diskgroups 1 for DATA and 2 for Redo logs (Faster Disks)?

Sorry if above AWR data is not in proper layout!

Thanks in advance!!
  • 1. Re: AWR Analysis
    asahide Expert
    Currently Being Moderated
    Hi,
    Sorry if above AWR data is not in proper layout!
    You can use
     tag, pls..
    Regards,                                                                                                                                                                                                    
  • 2. Re: AWR Analysis
    Osama_Mustafa Oracle ACE
    Currently Being Moderated
    if you use
     tag it will be better                                                                                                                                                                                                                            
  • 3. Re: AWR Analysis
    990552 Newbie
    Currently Being Moderated
    Thanks! This is my first post so never knew about code tag.
    Top Timed Events
    
        Instance '*' - cluster wide summary
        '*' Waits, %Timeouts, Wait Time Total(s) : Cluster-wide total for the wait event
        '*' 'Wait Time Avg (ms)' : Cluster-wide average computed as (Wait Time Total / Event Waits) in ms
        '*' Summary 'Avg Wait Time (ms)' : Per-instance 'Wait Time Avg (ms)' used to compute the following statistics
        '*' [Avg/Min/Max/Std Dev] : average/minimum/maximum/standard deviation of per-instance 'Wait Time Avg(ms)'
        '*' Cnt : count of instances with wait times for the event
    
          Wait      Event      Wait Time      Summary Avg Wait Time (ms)
    I#     Class     Event     Waits     %Timeouts     Total(s)     Avg(ms)     %DB time     Avg     Min     Max     Std Dev     Cnt
    *           DB CPU                 13,824.93           21.68                             3
          Cluster     gc buffer busy release     436,010     0.04     11,018.18     25.27     17.28     25.21     23.91     26.29     1.20     3
          Cluster     gc current block busy     292,729     0.00     7,485.84     25.57     11.74     25.53     24.43     26.59     1.08     3
          Commit     log file sync     305,966     0.00     5,714.52     18.68     8.96     18.65     18.11     19.21     0.55     3
          System I/O     log file parallel write     591,415     0.00     5,681.62     9.61     8.91     9.60     9.38     9.85     0.24     3
          Cluster     gc buffer busy acquire     451,716     0.13     5,558.70     12.31     8.72     13.47     10.62     18.17     4.11     3
          Other     gcs log flush sync     2,527,757     3.43     3,965.91     1.57     6.22     1.57     1.52     1.61     0.05     3
          Cluster     gc cr block busy     203,275     0.00     3,938.88     19.38     6.18     19.42     18.13     20.28     1.13     3
          System I/O     db file parallel write     1,688,423     0.00     3,635.23     2.15     5.70     2.16     2.02     2.25     0.12     3
          Cluster     gc current block 2-way     1,533,649     0.00     2,849.37     1.86     4.47     1.84     1.80     1.90     0.05     3
    1           DB CPU                 5,182.75           22.03                              
          Cluster     gc buffer busy release     170,226     0.06     4,326.03     25.41     18.39                              
          Cluster     gc current block busy     96,868     0.00     2,366.07     24.43     10.06                              
          Commit     log file sync     113,587     0.00     2,182.26     19.21     9.28                              
          Cluster     gc buffer busy acquire     203,411     0.16     2,159.25     10.62     9.18                              
          System I/O     log file parallel write     211,897     0.00     2,086.50     9.85     8.87                              
          System I/O     db file parallel write     674,977     0.00     1,518.86     2.25     6.46                              
          Other     gcs log flush sync     936,981     3.13     1,472.32     1.57     6.26                              
          Cluster     gc current block 2-way     699,628     0.00     1,327.54     1.90     5.64                              
          Cluster     gc cr block busy     71,670     0.00     1,299.67     18.13     5.53                              
    2           DB CPU                 4,193.91           21.22                              
          Cluster     gc buffer busy release     124,277     0.01     2,971.95     23.91     15.03                              
          Cluster     gc current block busy     108,389     0.00     2,881.69     26.59     14.58                              
          System I/O     log file parallel write     184,188     0.00     1,763.66     9.58     8.92                              
          Commit     log file sync     94,321     0.00     1,756.28     18.62     8.88                              
          Cluster     gc buffer busy acquire     78,709     0.15     1,430.47     18.17     7.24                              
          Cluster     gc cr block busy     67,500     0.00     1,339.22     19.84     6.77                              
          Other     gcs log flush sync     778,606     3.50     1,182.68     1.52     5.98                              
          System I/O     db file parallel write     376,181     0.00     829.36     2.20     4.20                              
          Other     enq: FB - contention     141,822     0.00     613.97     4.33     3.11                              
    3           DB CPU                 4,448.27           21.72                              
          Cluster     gc buffer busy release     141,507     0.04     3,720.20     26.29     18.16                              
          Cluster     gc current block busy     87,472     0.00     2,238.08     25.59     10.93                              
          Cluster     gc buffer busy acquire     169,596     0.09     1,968.99     11.61     9.61                              
          System I/O     log file parallel write     195,330     0.00     1,831.45     9.38     8.94                              
          Commit     log file sync     98,058     0.00     1,775.98     18.11     8.67                              
          Other     gcs log flush sync     812,170     3.70     1,310.91     1.61     6.40                              
          Cluster     gc cr block busy     64,105     0.00     1,299.99     20.28     6.35                              
          System I/O     db file parallel write     637,265     0.00     1,287.01     2.02     6.28                              
          Cluster     gc current block 2-way     625,590     0.00     1,147.18     1.83     5.60            
    
    Load Profile:
    
    System Statistics
    
    I#     Logical Reads     Physical Reads     Physical Writes     Redo Size (k)     Block Changes     User Calls     Execs     Parses     Logons     Txns
    1     660,246,304     10,588     6,108,621     61,408,883     227,914,819     1,390,688     842,125     99,173     741     112,444
    2     528,112,160     496,517     4,894,272     48,201,955     180,212,408     1,688,845     788,422     92,305     552     93,426
    3     554,450,192     13,957     5,149,779     52,332,506     195,211,150     1,409,997     795,309     103,876     895     98,048
    Sum     1,742,808,656     521,062     16,152,672     161,943,345     603,338,377     4,489,530     2,425,856     295,354     2,188     303,918
    Avg     580,936,219     173,687     5,384,224     53,981,115     201,112,792     1,496,510     808,619     98,451     729     101,306
    Std     69,935,615     279,584     640,222     6,756,047     24,392,664     166,847     29,221     5,819     172     9,919
    
    System Statistics - Per Second
    
    I#     Logical Reads/s     Physical Reads/s     Physical Writes/s     Redo Size (k)/s     Block Changes/s     User Calls/s     Execs/s     Parses/s     Logons/s     Txns/s
    1     61,223.89     0.98     566.45     5,694.38     21,134.28     128.96     78.09     9.20     0.07     10.43
    2     48,970.64     46.04     453.83     4,469.66     16,710.69     156.60     73.11     8.56     0.05     8.66
    3     51,412.72     1.29     477.53     4,852.66     18,101.42     130.75     73.75     9.63     0.08     9.09
    Sum     161,607.26     48.32     1,497.81     15,016.69     55,946.39     416.31     224.94     27.39     0.20     28.18
    Avg     53,869.09     16.11     499.27     5,005.56     18,648.80     138.77     74.98     9.13     0.07     9.39
    Std     6,485.43     25.93     59.37     626.51     2,262.03     15.47     2.71     0.54     0.02     0.92
    
    
    System Statistics - Per Transaction
    
    I#     Logical Reads/tx     Physical Reads/tx     Physical Writes/tx     Redo Size (k)/tx     Block Changes/tx     User Calls/tx     Execs/tx     Parses/tx     Logons/tx
    1     5,871.78     0.09     54.33     546.13     2,026.92     12.37     7.49     0.88     0.01
    2     5,652.73     5.31     52.39     515.94     1,928.93     18.08     8.44     0.99     0.01
    3     5,654.89     0.14     52.52     533.74     1,990.98     14.38     8.11     1.06     0.01
    Avg     5,726.47     1.85     53.08     531.94     1,982.28     14.94     8.01     0.98     0.01
    
    SysStat and Global Messaging - RAC
    
          Blocks Received      Blocks Served      CPU (seconds)      Messages      GC Blks      GC CR
    I#     GC Current     GC CR     GC Current     GC CR     GC     IPC     GCS Received     GES Received     GCS Sent     GES Sent      Sent Direct     Sent Indir     Lost     Failure
    1     1,103,531     188,244     554,826     473,053     0     0     8,972,337     1,221,285     8,989,831     1,242,078     2,120,587     4,142,918     32     77
    2     607,697     716,593     1,668,509     173,636     0     0     10,002,688     1,276,734     9,795,640     1,317,581     1,676,785     4,579,098     37     57
    3     1,044,839     173,096     532,568     431,185     0     0     8,160,011     1,246,734     8,349,110     1,185,179     1,982,439     3,931,956     26     72
    Sum     2,756,067     1,077,933     2,755,903     1,077,874     0     0     27,135,036     3,744,753     27,134,581     3,744,838     5,779,811     12,653,972     95     206
    Avg     918,689     359,311     918,634     359,291     0     0     9,045,012     1,248,251     9,044,860     1,248,279     1,926,604     4,217,991     32     69
    Std     270,921     309,508     649,506     162,139     0     0     923,486     27,756     724,833     66,418     227,108     330,038     6     10
    
    SQL ordered by Elapsed Time (Global)
    
        Captured SQL account for 4.0% of Total DB Time (s): 63,772
        Captured PL/SQL account for 0.5% of Total DB Time (s): 63,772
    
          Total      Per Execution      Percentage of Total       
    SQL Id     Elapsed (s)     CPU (s)     IOWait (s)     Gets     Reads     Rows     Cluster (s)     Execs     Elapsed (s)     CPU (s)     IOWait (s)     Gets     Reads     Rows     Cluster (s)     DB time     DB CPU     IO Wait     Gets     Reads     Cluster     Execs     SQL Text
    6stvw9dn0fsar     671.66     39.71     0.00     281,982     0     266,609     633.03     281,934     0.00     0.00     0.00     1.00     0.00     0.95     0.00     1.05     0.29     0.00     0.02     0.00     1.72     11.62      SELECT 'X' FROM WELL_LOG_TRIP ...
    b15x8du43j38f     400.31     85.44     49.35     5,877,656     37,726     16     275.64     18     22.24     4.75     2.74     326,536.44     2,095.89     0.89     15.31     0.63     0.62     0.09     0.34     7.24     0.75     0.00      select count(*), systimestamp ...
    axf88g9c9cgsk     288.92     90.81     34.00     2,136,503     3,913     6,123,054     158.07     1,100     0.26     0.08     0.03     1,942.28     3.56     5,566.41     0.14     0.45     0.66     0.07     0.12     0.75     0.43     0.05      SELECT LOG_TOOL_PASS_NO, WELL_...
    6qh449rx4apfb     235.75     53.85     0.54     463,999     15     60,130     172.28     64,744     0.00     0.00     0.00     7.17     0.00     0.93     0.00     0.37     0.39     0.00     0.03     0.00     0.47     2.67      BEGIN PERSIST_CURVEDATA(:1 , :...
    455q5rtqg0bpu     232.50     33.85     84.42     587,461     438,230     0     119.09     1     232.50     33.85     84.42     587,461.00     438,230.00     0.00     119.09     0.36     0.24     0.16     0.03     84.10     0.32     0.00      select count(*), systimestamp ...
    ct37ws0v64cac     154.34     43.14     2.19     4,731,538     320     5     116.52     5     30.87     8.63     0.44     946,307.60     64.00     1.00     23.30     0.24     0.31     0.00     0.27     0.06     0.32     0.00      select count(*), systimestamp ...
    4h3qph3n9ysfj     89.79     14.40     3.29     90,289     266     13,398     67.10     13,398     0.01     0.00     0.00     6.74     0.02     1.00     0.01     0.14     0.10     0.01     0.01     0.05     0.18     0.55      INSERT INTO WLE_LOG (LOG_ID, M...
    9gxbwvyvx2349     88.32     76.58     0.04     2,478,451     2     322,982     0.00     317,658     0.00     0.00     0.00     7.80     0.00     1.02     0.00     0.14     0.55     0.00     0.14     0.00     0.00     13.09      SELECT c.channel_Type, c.chann...
    aq5wdhrrbyr16     72.39     27.32     0.66     1,493,337     126     9     47.94     9     8.04     3.04     0.07     165,926.33     14.00     1.00     5.33     0.11     0.20     0.00     0.09     0.02     0.13     0.00      select count(*), systimestamp ...
    9vkm19fmduua3     54.87     6.32     0.00     33,807     0     16,374     48.84     17,246     0.00     0.00     0.00     1.96     0.00     0.95     0.00     0.09     0.05     0.00     0.00     0.00     0.13     0.71      SELECT WELL_UUID, TRIP_OBS_NO,...
                      
  • 4. Re: AWR Analysis
    Dom Brooks Guru
    Currently Being Moderated
    Performant RAC is all about node affinity - avoiding the nodes constantly requesting the same data.

    Do you treat your RAC cluster like a black box with all requests serviceable by all nodes?

    Is this performance profile new?
    Combining inefficient SQL execution plans with a lack of node affinity can really hurt performance.
  • 5. Re: AWR Analysis
    990552 Newbie
    Currently Being Moderated
    Dom - Thanks for reply.

    Yes application is sending data to all 3 RAC nodes.
    Based on wait event Gc cr/current block busy i see that we should reduce concurrency or limit parallelism to 1 instance.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points