5 Replies Latest reply: Feb 12, 2013 8:07 AM by 990552 RSS

    AWR Analysis

    990552
      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
          Hi,
          Sorry if above AWR data is not in proper layout!
          You can use
           tag, pls..
          Regards,                                                                                                                                                                                                    
          • 2. Re: AWR Analysis
            Osama_Mustafa
            if you use
             tag it will be better                                                                                                                                                                                                                            
            • 3. Re: AWR Analysis
              990552
              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
                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
                  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.