FAQ
I pulled an awr this morning for a period and the top wait events add up to
almost 200%. I was curious if anyone saw this before. I've seen it slightly
over 100% that I wrote off for rounding but never saw it so high. I'm
addressing the actual wait events so no issues there.






Top 5 Timed Events

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

log file sync

356,514

2,521

7

84.5

Commit

log file parallel write

358,641

1,967

5

65.9

System I/O

CPU time



1,192



39.9



db file parallel write

23,911

364

15

12.2

System I/O

log buffer space

135

58

427

1.9

Configuration



Thanks,

ken

Search Discussions

  • Marcus Mönnig at Sep 28, 2011 at 4:58 pm
    Hi Kenneth,

    the time for log buffer space and log file parallel write might partly
    be included in log file sync, especially when there are frequent
    commits, so there is some double counting taking place.

    Tony Hasler explained this in his 3 blog posts here:
    http://tonyhasler.wordpress.com/2011/07/24/log-file-sync-and-log-file-parallel-write-part-1/

    Cheers,
    Marcus

    2011/9/28 Kenneth Naim <kennethnaim@gmail.com>:
    I pulled an awr this morning for a period and the top wait events add up to
    almost 200%. I was curious if anyone saw this before. I've seen it slightly
    over 100% that I wrote off for rounding but never saw it so high. I'm
    addressing the actual wait events so no issues there.






    Top 5 Timed Events


    Event

    Waits

    Time(s)

    Avg Wait(ms)

    % Total Call Time

    Wait Class


    log file sync

    356,514

    2,521

    7

    84.5

    Commit


    log file parallel write

    358,641

    1,967

    5

    65.9

    System I/O


    CPU time



    1,192



    39.9




    db file parallel write

    23,911

    364

    15

    12.2

    System I/O


    log buffer space

    135

    58

    427

    1.9

    Configuration



    Thanks,

    ken



    --
    http://www.freelists.org/webpage/oracle-l

    --
    http://www.freelists.org/webpage/oracle-l
  • Marcus Mönnig at Sep 28, 2011 at 4:57 pm
    Another shot with a short answer, instead of just a link: While your
    client session/process waits for "log file sync" when comitting, the
    LGWR process does the work of writing out the log buffer to disk and
    waits for "log file parallel write". "log file parallel write" wait
    events happen during the "log file sync" wait event.

    Cheers,
    Marcus

    2011/9/28 Marcus Mönnig <mm@marcusmoennig.de>:
    Hi Kenneth,

    the time for log buffer space and log file parallel write might partly
    be included in log file sync, especially when there are frequent
    commits, so there is some double counting taking place.

    Tony Hasler explained this in his 3 blog posts here:
    http://tonyhasler.wordpress.com/2011/07/24/log-file-sync-and-log-file-parallel-write-part-1/

    Cheers,
    Marcus

    2011/9/28 Kenneth Naim <kennethnaim@gmail.com>:
    I pulled an awr this morning for a period and the top wait events add up to
    almost 200%. I was curious if anyone saw this before. I've seen it slightly
    over 100% that I wrote off for rounding but never saw it so high. I'm
    addressing the actual wait events so no issues there.






    Top 5 Timed Events


    Event

    Waits

    Time(s)

    Avg Wait(ms)

    % Total Call Time

    Wait Class


    log file sync

    356,514

    2,521

    7

    84.5

    Commit


    log file parallel write

    358,641

    1,967

    5

    65.9

    System I/O


    CPU time



    1,192



    39.9




    db file parallel write

    23,911

    364

    15

    12.2

    System I/O


    log buffer space

    135

    58

    427

    1.9

    Configuration



    Thanks,

    ken



    --
    http://www.freelists.org/webpage/oracle-l

    --
    http://www.freelists.org/webpage/oracle-l
  • Marcus Mönnig at Sep 28, 2011 at 3:46 pm
    (Resending due to overquoting...)

    While your client session/process waits for "log file sync" when
    comitting, the LGWR process does the work of writing out the log
    buffer to disk and waits for "log file parallel write". "log file
    parallel write" wait events happen during the "log file sync" wait
    event, so there is some double counting taking place.

    Tony Hasler explained this very nice in his three blog posts here:

    http://tonyhasler.wordpress.com/2011/07/24/log-file-sync-and-log-file-parallel-write-part-1/

    Cheers,
    Marcus
  • Wolfgang Breitling at Sep 28, 2011 at 6:20 pm
    I'd consider that "normal"
    While a system has only a limited ( to the number of cpus/cores ) capacity for productive work, any system has an unlimited capacity to wait.
    E.g. if one session holds a lock for 1 hour and 2 sessions wait for that lock fthen you may have up to 100% ( 1 hour in 1 hour ) cpu usage from that one session and 200% ( 2 hours in 1 hour ) waits from the other 2 sessions.
    Regards
    Wolfgang Breitling
    Centrex Consulting Corporation
    http://www.centrexcc.com
    On 2011-09-28, at 8:55 AM, Kenneth Naim wrote:

    I pulled an awr this morning for a period and the top wait events add up to
    almost 200%. I was curious if anyone saw this before. I've seen it slightly
    over 100% that I wrote off for rounding but never saw it so high. I'm
    addressing the actual wait events so no issues there.

    --
    http://www.freelists.org/webpage/oracle-l
  • Wolfgang Breitling at Sep 28, 2011 at 10:26 pm
    To add a bit more, on a busy system it is even possible that productive work ( CPU time ) "appears" to be > 100% according to AWR.

    Regards
    Wolfgang Breitling
    Centrex Consulting Corporation
    http://www.centrexcc.com
    On 2011-09-28, at 12:19 PM, Wolfgang Breitling wrote:

    I'd consider that "normal"
    While a system has only a limited ( to the number of cpus/cores ) capacity for productive work, any system has an unlimited capacity to wait.
    E.g. if one session holds a lock for 1 hour and 2 sessions wait for that lock fthen you may have up to 100% ( 1 hour in 1 hour ) cpu usage from that one session and 200% ( 2 hours in 1 hour ) waits from the other 2 sessions.
    Regards
    Wolfgang Breitling
    Centrex Consulting Corporation
    http://www.centrexcc.com
    On 2011-09-28, at 8:55 AM, Kenneth Naim wrote:

    I pulled an awr this morning for a period and the top wait events add up to
    almost 200%. I was curious if anyone saw this before. I've seen it slightly
    over 100% that I wrote off for rounding but never saw it so high. I'm
    addressing the actual wait events so no issues there.

    --
    http://www.freelists.org/webpage/oracle-l
    --
    http://www.freelists.org/webpage/oracle-l
  • Kenneth Naim at Sep 29, 2011 at 5:13 am
    I understand that that due to the number of processors and waits that db
    time will and should exceed the elapsed time in a busy system. I've it as
    high as 3 times the processors time the elapsed time. But shouldn't the
    waits + cpu time be divided by the db time so it can't never exceed 100%
    unless it is double counting like Marcus said. If it were dividing by the
    elapsed time then it would routinely go over 100% but that isn't the case in
    hundreds of awr's I've looked at over the years. It begs the question isn't
    the double counting a bug? I'd understand if it was minor to rounding but to
    be off by such a high number makes the understanding the top 5 issues
    deceptive as one doesn't know how off they are and if they are in the
    correct order which leads to incorrect analysis and solutions.

    Thanks.
    -----Original Message-----
    From: Wolfgang Breitling
    Sent: Wednesday, September 28, 2011 6:26 PM
    To: kennethnaim@gmail.com
    Cc: oracle-l
    Subject: Re: Awr waits over 100%

    To add a bit more, on a busy system it is even possible that productive work
    ( CPU time ) "appears" to be > 100% according to AWR.

    Regards
    Wolfgang Breitling
    Centrex Consulting Corporation
    http://www.centrexcc.com
    On 2011-09-28, at 12:19 PM, Wolfgang Breitling wrote:

    I'd consider that "normal"
    While a system has only a limited ( to the number of cpus/cores ) capacity
    for productive work, any system has an unlimited capacity to wait.
    E.g. if one session holds a lock for 1 hour and 2 sessions wait for that
    lock fthen you may have up to 100% ( 1 hour in 1 hour ) cpu usage from that
    one session and 200% ( 2 hours in 1 hour ) waits from the other 2 sessions.
    Regards
    Wolfgang Breitling
    Centrex Consulting Corporation
    http://www.centrexcc.com
    On 2011-09-28, at 8:55 AM, Kenneth Naim wrote:

    I pulled an awr this morning for a period and the top wait events add
    up to almost 200%. I was curious if anyone saw this before. I've seen
    it slightly over 100% that I wrote off for rounding but never saw it
    so high. I'm addressing the actual wait events so no issues there.

    --
    http://www.freelists.org/webpage/oracle-l
    --
    http://www.freelists.org/webpage/oracle-l
  • Marcus Mönnig at Sep 29, 2011 at 6:13 am
    Hi Kenneth,

    2011/9/29 Kenneth Naim <kennethnaim@gmail.com>:
    But shouldn't the waits + cpu time be divided by the db time so it can't never exceed 100%
    unless it is double counting like Marcus said. If it were dividing by the
    elapsed time then it would routinely go over 100% but that isn't the case in
    hundreds of awr's I've looked at over the years. It begs the question isn't
    the double counting a bug?
    the "DB time" value used as the divisor for calculating "% Total Call
    Time" value comes from Oracle's Time Model Statistics and is defined
    as:

    "Database time is calculated by aggregating the CPU time and wait time
    of all user sessions not waiting for idle wait events (nonidle user
    sessions)."

    So, it's not the sum for all sessions, but only for user sessions. All
    cpu and wait times for background sessions are in the numerator, but
    not in the denominator. In your case, the times for "log file parallel
    write" and possible parts of other wait events/CPU time refer to the
    LGWR background process.

    You can look at the "Background Wait Events" section in the AWR report
    for all background wait events and "background cpu time" value in the
    "Time Model System Stats" to get the CPU times for background
    processes.

    Cheers,
    Marcus
  • Kenneth Naim at Sep 29, 2011 at 4:40 pm
    Thanks, that's a very interesting distinction. I'll look into it.

    -----Original Message-----
    From: oracle-l-bounce@freelists.org
    On Behalf Of Marcus Mönnig
    Sent: Thursday, September 29, 2011 2:12 AM
    To: ORACLE-L
    Subject: Re: Awr waits over 100%

    Hi Kenneth,

    2011/9/29 Kenneth Naim <kennethnaim@gmail.com>:
    But shouldn't the waits + cpu time be divided by the db time so it
    can't never exceed 100% unless it is double counting like Marcus said.
    If it were dividing by the elapsed time then it would routinely go
    over 100% but that isn't the case in hundreds of awr's I've looked at
    over the years. It begs the question isn't the double counting a bug?
    the "DB time" value used as the divisor for calculating "% Total Call Time"
    value comes from Oracle's Time Model Statistics and is defined
    as:

    "Database time is calculated by aggregating the CPU time and wait time of
    all user sessions not waiting for idle wait events (nonidle user sessions)."

    So, it's not the sum for all sessions, but only for user sessions. All cpu
    and wait times for background sessions are in the numerator, but not in the
    denominator. In your case, the times for "log file parallel write" and
    possible parts of other wait events/CPU time refer to the LGWR background
    process.

    You can look at the "Background Wait Events" section in the AWR report for
    all background wait events and "background cpu time" value in the "Time
    Model System Stats" to get the CPU times for background processes.

    Cheers,
    Marcus
  • Michael Schmitt at Oct 26, 2011 at 9:00 pm
    Hello,

    We are running 11.2.0.2 Dataguard in fast_start failover mode and one of the applications we support in this configuration creates an after logon trigger to track who connects to the database. Whenever we do a controlled switchover (or unplanned failover), the Dataguard configuration gets messed up. From what I can tell the after logon trigger is causing ORA-00604 errors at some point in the rebuild process of the old primary.

    Does anyone have any experience on working around an issue like this with DataGuard?

    Thanks in advance

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouporacle-l @
categoriesoracle
postedSep 28, '11 at 2:55p
activeOct 26, '11 at 9:00p
posts10
users4
websiteoracle.com

People

Translate

site design / logo © 2022 Grokbase