f



log file sync , log file parallel write

Hi ,

my top wait list shows 2 events ,  log file sync and log file parallel
write in 1 hour.

During this time , the db server created 370,594 bytes redo per second.

the docs say that high value of both log file sync and log file
parallel write indicates io problem .
How can we decide whether below numbers are close to each other or not?


If it is not possible to change the application and eliminate the
unnecessary commits (such as sap) ,  how can lg file sync be decreased?

Kind Regards


Load Profile
~~~~~~~~~~~~                            Per Second       Per
Transaction
                                   ---------------
---------------
                  Redo size:            370,594.95
2,966.21
              Logical reads:             39,925.48
319.56
              Block changes:              2,447.17
19.59
             Physical reads:                 67.83
0.54
            Physical writes:                433.47
3.47
                 User calls:                880.52
7.05
                     Parses:                275.49
2.21
                Hard parses:                  1.92
0.02
                      Sorts:                553.98
4.43
                     Logons:                  0.29
0.00
                   Executes:              5,303.67
42.45
               Transactions:                124.94

  % Blocks changed per Read:    6.13    Recursive Call %:     89.20
 Rollback per transaction %:    0.68       Rows per Sort:     11.52

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.99       Redo NoWait %:     99.95
            Buffer  Hit   %:   99.83    In-memory Sort %:    100.00
            Library Hit   %:  100.25        Soft Parse %:     99.30
         Execute to Parse %:   94.81         Latch Hit %:     99.03
Parse CPU to Parse Elapsd %:   15.58     % Non-Parse CPU:     98.01

 Shared Pool Statistics        Begin   End
                               ------  ------
             Memory Usage %:   94.91   95.30
    % SQL with executions>1:   87.78   87.31
  % Memory for SQL w/exec>1:   70.98   71.07

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~
% Total
Event                                               Waits    Time (s)
Ela Time
-------------------------------------------- ------------ -----------
--------
log file sync                                     483,596     194,940
 64.17
latch free                                        656,366      46,963
 15.46
db file sequential read                           232,327      31,051
 10.22
CPU time                                                       20,846
  6.86
log file parallel write                           201,538       2,810
   .93
          -------------------------------------------------------------

0
hopehope_123 (149)
12/18/2006 9:28:06 PM
comp.databases.oracle.server 22978 articles. 1 followers. Post Follow

9 Replies
1255 Views

Similar Articles

[PageSpeed] 3

db_man wrote:
> Hi ,
>
> my top wait list shows 2 events ,  log file sync and log file parallel
> write in 1 hour.
>
> During this time , the db server created 370,594 bytes redo per second.
>
> the docs say that high value of both log file sync and log file
> parallel write indicates io problem .
> How can we decide whether below numbers are close to each other or not?
>
>
> If it is not possible to change the application and eliminate the
> unnecessary commits (such as sap) ,  how can lg file sync be decreased?
>
> Kind Regards
>
>
> Load Profile
> ~~~~~~~~~~~~                            Per Second       Per
> Transaction
>                                    ---------------
> ---------------
>                   Redo size:            370,594.95
> 2,966.21
>               Logical reads:             39,925.48
> 319.56
>               Block changes:              2,447.17
> 19.59
>              Physical reads:                 67.83
> 0.54
>             Physical writes:                433.47
> 3.47
>                  User calls:                880.52
> 7.05
>                      Parses:                275.49
> 2.21
>                 Hard parses:                  1.92
> 0.02
>                       Sorts:                553.98
> 4.43
>                      Logons:                  0.29
> 0.00
>                    Executes:              5,303.67
> 42.45
>                Transactions:                124.94
>
>   % Blocks changed per Read:    6.13    Recursive Call %:     89.20
>  Rollback per transaction %:    0.68       Rows per Sort:     11.52
>
> Instance Efficiency Percentages (Target 100%)
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>             Buffer Nowait %:   99.99       Redo NoWait %:     99.95
>             Buffer  Hit   %:   99.83    In-memory Sort %:    100.00
>             Library Hit   %:  100.25        Soft Parse %:     99.30
>          Execute to Parse %:   94.81         Latch Hit %:     99.03
> Parse CPU to Parse Elapsd %:   15.58     % Non-Parse CPU:     98.01
>
>  Shared Pool Statistics        Begin   End
>                                ------  ------
>              Memory Usage %:   94.91   95.30
>     % SQL with executions>1:   87.78   87.31
>   % Memory for SQL w/exec>1:   70.98   71.07
>
> Top 5 Timed Events
> ~~~~~~~~~~~~~~~~~~
> % Total
> Event                                               Waits    Time (s)
> Ela Time
> -------------------------------------------- ------------ -----------
> --------
> log file sync                                     483,596     194,940
>  64.17
> latch free                                        656,366      46,963
>  15.46
> db file sequential read                           232,327      31,051
>  10.22
> CPU time                                                       20,846
>   6.86
> log file parallel write                           201,538       2,810
>    .93
>           -------------------------------------------------------------

A lot depends on things like which hardware you are on, are you
using/does the OS support async i/o, are you dedicating your redo logs
to a device that doesn't have other things writing to it, are you using
raid, and if so, what kind/what kind of cache, Oracle version/patch
level, how big is your redo buffer, how big are redo files and how many
groups, is this all the time or just during certain times, etc.

If you are doing something putting everything on a RAID-5 device, that
might be the problem right there.

jg
--
@home.com is bogus.
http://htmldb.oracle.com/pls/otn/f?p=21195:1:2525094322570244

0
joel-garry (4553)
12/18/2006 9:47:18 PM
db_man wrote:
> Hi ,
>
> my top wait list shows 2 events ,  log file sync and log file parallel
> write in 1 hour.
>
> During this time , the db server created 370,594 bytes redo per second.
>
> the docs say that high value of both log file sync and log file
> parallel write indicates io problem .
> How can we decide whether below numbers are close to each other or not?
>
>
> If it is not possible to change the application and eliminate the
> unnecessary commits (such as sap) ,  how can lg file sync be decreased?
>
> Kind Regards
>
>
> Load Profile
> ~~~~~~~~~~~~                            Per Second       Per
> Transaction
>                                    ---------------
> ---------------
>                   Redo size:            370,594.95
> 2,966.21
>               Logical reads:             39,925.48
> 319.56
>               Block changes:              2,447.17
> 19.59
>              Physical reads:                 67.83
> 0.54
>             Physical writes:                433.47
> 3.47
>                  User calls:                880.52
> 7.05
>                      Parses:                275.49
> 2.21
>                 Hard parses:                  1.92
> 0.02
>                       Sorts:                553.98
> 4.43
>                      Logons:                  0.29
> 0.00
>                    Executes:              5,303.67
> 42.45
>                Transactions:                124.94
>
>   % Blocks changed per Read:    6.13    Recursive Call %:     89.20
>  Rollback per transaction %:    0.68       Rows per Sort:     11.52
>
> Instance Efficiency Percentages (Target 100%)
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>             Buffer Nowait %:   99.99       Redo NoWait %:     99.95
>             Buffer  Hit   %:   99.83    In-memory Sort %:    100.00
>             Library Hit   %:  100.25        Soft Parse %:     99.30
>          Execute to Parse %:   94.81         Latch Hit %:     99.03
> Parse CPU to Parse Elapsd %:   15.58     % Non-Parse CPU:     98.01
>
>  Shared Pool Statistics        Begin   End
>                                ------  ------
>              Memory Usage %:   94.91   95.30
>     % SQL with executions>1:   87.78   87.31
>   % Memory for SQL w/exec>1:   70.98   71.07
>
> Top 5 Timed Events
> ~~~~~~~~~~~~~~~~~~
> % Total
> Event                                               Waits    Time (s)
> Ela Time
> -------------------------------------------- ------------ -----------
> --------
> log file sync                                     483,596     194,940
>  64.17
> latch free                                        656,366      46,963
>  15.46
> db file sequential read                           232,327      31,051
>  10.22
> CPU time                                                       20,846
>   6.86
> log file parallel write                           201,538       2,810
>    .93
>           -------------------------------------------------------------


log file sync = commit.
Consequently, if you state you can't change the app, you can't change
the *number* of commits, but you can influence their *duration*.

-- 
Sybrand Bakker
Senior Oracke DBA'

0
sybrandb1 (715)
12/18/2006 10:16:10 PM
Thanks for your answers. Everything is in raid5 .

Os is sun solaris , 16gb.ram , 8 cpus.

Statistic                                      Total     per Second
per Trans
--------------------------------- ------------------ --------------
------------

user commits                                 446,365          124.1
     1.0


in one hour , 446365 commits occurred.

Kind Regards,




sybrandb wrote:
> db_man wrote:
> > Hi ,
> >
> > my top wait list shows 2 events ,  log file sync and log file parallel
> > write in 1 hour.
> >
> > During this time , the db server created 370,594 bytes redo per second.
> >
> > the docs say that high value of both log file sync and log file
> > parallel write indicates io problem .
> > How can we decide whether below numbers are close to each other or not?
> >
> >
> > If it is not possible to change the application and eliminate the
> > unnecessary commits (such as sap) ,  how can lg file sync be decreased?
> >
> > Kind Regards
> >
> >
> > Load Profile
> > ~~~~~~~~~~~~                            Per Second       Per
> > Transaction
> >                                    ---------------
> > ---------------
> >                   Redo size:            370,594.95
> > 2,966.21
> >               Logical reads:             39,925.48
> > 319.56
> >               Block changes:              2,447.17
> > 19.59
> >              Physical reads:                 67.83
> > 0.54
> >             Physical writes:                433.47
> > 3.47
> >                  User calls:                880.52
> > 7.05
> >                      Parses:                275.49
> > 2.21
> >                 Hard parses:                  1.92
> > 0.02
> >                       Sorts:                553.98
> > 4.43
> >                      Logons:                  0.29
> > 0.00
> >                    Executes:              5,303.67
> > 42.45
> >                Transactions:                124.94
> >
> >   % Blocks changed per Read:    6.13    Recursive Call %:     89.20
> >  Rollback per transaction %:    0.68       Rows per Sort:     11.52
> >
> > Instance Efficiency Percentages (Target 100%)
> > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> >             Buffer Nowait %:   99.99       Redo NoWait %:     99.95
> >             Buffer  Hit   %:   99.83    In-memory Sort %:    100.00
> >             Library Hit   %:  100.25        Soft Parse %:     99.30
> >          Execute to Parse %:   94.81         Latch Hit %:     99.03
> > Parse CPU to Parse Elapsd %:   15.58     % Non-Parse CPU:     98.01
> >
> >  Shared Pool Statistics        Begin   End
> >                                ------  ------
> >              Memory Usage %:   94.91   95.30
> >     % SQL with executions>1:   87.78   87.31
> >   % Memory for SQL w/exec>1:   70.98   71.07
> >
> > Top 5 Timed Events
> > ~~~~~~~~~~~~~~~~~~
> > % Total
> > Event                                               Waits    Time (s)
> > Ela Time
> > -------------------------------------------- ------------ -----------
> > --------
> > log file sync                                     483,596     194,940
> >  64.17
> > latch free                                        656,366      46,963
> >  15.46
> > db file sequential read                           232,327      31,051
> >  10.22
> > CPU time                                                       20,846
> >   6.86
> > log file parallel write                           201,538       2,810
> >    .93
> >           -------------------------------------------------------------
>
>
> log file sync = commit.
> Consequently, if you state you can't change the app, you can't change
> the *number* of commits, but you can influence their *duration*.
> 
> -- 
> Sybrand Bakker
> Senior Oracke DBA'

0
hopehope_123 (149)
12/19/2006 6:51:13 AM
Not always (at least in RAC!!)

In a RAC environment, cache fusion transfers sometimes causes the log
file sync event. This is due to the write ahead logging mechanism. When
a foreground process requests a block from another instance, all the
redo entries associated with the block must be flushed to disk prior to
transferring the block. In this case, there is no commit involved, but
buffer cahe synchronization and waits on the log file sync event.


>log file sync = commit.
> Consequently, if you state you can't change the app, you can't change
> the *number* of commits, but you can influence their *duration*.
>
> --
> Sybrand Bakker
> Senior Oracke DBA'- Hide quoted text -- Show quoted text -

Best Regards,
K Gopalakrishnan

Co-Author: Oracle Wait Interface, Oracle Press 2004
http://www.amazon.com/exec/obidos/tg/detail/-/007222729X/

Author: Oracle Database 10g RAC Handbook, Oracle Press 2006
http://www.amazon.com/gp/product/007146509X/

0
kaygopal (35)
12/19/2006 7:17:49 AM

On Dec 19, 7:51 am, "db_man" <hopehope_...@yahoo.com> wrote:
> Thanks for your answers. Everything is in raid5 .
>
> Os is sun solaris , 16gb.ram , 8 cpus.
>
> Statistic                                      Total     per Second
> per Trans
> --------------------------------- ------------------ --------------
> ------------
>
> user commits                                 446,365          124.1
>      1.0
>
> in one hour , 446365 commits occurred.
>
> Kind Regards,
>
>
>
> sybrandb wrote:
> > db_man wrote:
> > > Hi ,
>
> > > my top wait list shows 2 events ,  log file sync and log file parallel
> > > write in 1 hour.
>
> > > During this time , the db server created 370,594 bytes redo per second.
>
> > > the docs say that high value of both log file sync and log file
> > > parallel write indicates io problem .
> > > How can we decide whether below numbers are close to each other or not?
>
> > > If it is not possible to change the application and eliminate the
> > > unnecessary commits (such as sap) ,  how can lg file sync be decreased?
>
> > > Kind Regards
>
> > > Load Profile
> > > ~~~~~~~~~~~~                            Per Second       Per
> > > Transaction
> > >                                    ---------------
> > > ---------------
> > >                   Redo size:            370,594.95
> > > 2,966.21
> > >               Logical reads:             39,925.48
> > > 319.56
> > >               Block changes:              2,447.17
> > > 19.59
> > >              Physical reads:                 67.83
> > > 0.54
> > >             Physical writes:                433.47
> > > 3.47
> > >                  User calls:                880.52
> > > 7.05
> > >                      Parses:                275.49
> > > 2.21
> > >                 Hard parses:                  1.92
> > > 0.02
> > >                       Sorts:                553.98
> > > 4.43
> > >                      Logons:                  0.29
> > > 0.00
> > >                    Executes:              5,303.67
> > > 42.45
> > >                Transactions:                124.94
>
> > >   % Blocks changed per Read:    6.13    Recursive Call %:     89.20
> > >  Rollback per transaction %:    0.68       Rows per Sort:     11.52
>
> > > Instance Efficiency Percentages (Target 100%)
> > > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > >             Buffer Nowait %:   99.99       Redo NoWait %:     99.95
> > >             Buffer  Hit   %:   99.83    In-memory Sort %:    100.00
> > >             Library Hit   %:  100.25        Soft Parse %:     99.30
> > >          Execute to Parse %:   94.81         Latch Hit %:     99.03
> > > Parse CPU to Parse Elapsd %:   15.58     % Non-Parse CPU:     98.01
>
> > >  Shared Pool Statistics        Begin   End
> > >                                ------  ------
> > >              Memory Usage %:   94.91   95.30
> > >     % SQL with executions>1:   87.78   87.31
> > >   % Memory for SQL w/exec>1:   70.98   71.07
>
> > > Top 5 Timed Events
> > > ~~~~~~~~~~~~~~~~~~
> > > % Total
> > > Event                                               Waits    Time (s)
> > > Ela Time
> > > -------------------------------------------- ------------ -----------
> > > --------
> > > log file sync                                     483,596     194,940
> > >  64.17
> > > latch free                                        656,366      46,963
> > >  15.46
> > > db file sequential read                           232,327      31,051
> > >  10.22
> > > CPU time                                                       20,846
> > >   6.86
> > > log file parallel write                           201,538       2,810
> > >    .93
> > >           -------------------------------------------------------------
>
> > log file sync = commit.
> > Consequently, if you state you can't change the app, you can't change
> > the *number* of commits, but you can influence their *duration*.
>
> > --
> > Sybrand Bakker
> > Senior Oracke DBA'- Hide quoted text -- Show quoted text -


RAID5 usually is just plain evil.

Also: please stop top posting. You can change your nick, but you have
been here long enough to know we don't appreciate top-posting.

-- 
Sybrand Bakker
Senior Oracle DBA

0
sybrandb1 (715)
12/19/2006 9:07:00 AM
Hi

Thanks for your comments.

Sybrand , spend some time in google to find what top-posting mean ,
sorry to be honest i
havent heard the term till you told to me.
Changing the nick name is a bad idea  , i admit.  Anyway dont want to
do top-posting , but dont know how to stop it .

Returning to the statspack output :

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~
% Total
Event                                               Waits    Time (s)
Ela Time
-------------------------------------------- ------------ -----------
--------
log file sync                                     483,596     194,940
 64.17
latch free                                        656,366      46,963
 15.46
db file sequential read                           232,327      31,051
 10.22
CPU time                                                       20,846
  6.86
log file parallel write                           201,538       2,810
   .93
          -------------------------------------------------------------


Here the short story is to change the redo log location on a non-raid5
location or not.
One of the dba's who i trust told to me that , providing with the low
log file parallel write average wait time
the main problem is not the redo log writing but huge number of
commits.

I want to be sure , and if writing through the redo log is problem , i
must proof it.

After reading more documents , i see lots of statistics , values to
compare , will be appreciated if you comment . I am not sure whether
this type of digging values is the right way to go.


     Load Profile
~~~~~~~~~~~~                            Per Second       Per
Transaction
                                ---------------       ---------------
                  Redo size:            370,594.95
2,966.21
              Logical reads:             39,925.48
319.56
              Block changes:              2,447.17
19.59
             Physical reads:                 67.83
0.54
            Physical writes:                433.47
3.47
                 User calls:                880.52
7.05
                     Parses:                275.49
2.21
                Hard parses:                  1.92
0.02
                      Sorts:                553.98
4.43
                     Logons:                  0.29
0.00
                   Executes:              5,303.67
42.45
               Transactions:                124.94

Statistic                                      Total     per Second
per Trans
--------------------------------- ------------------ --------------
------------
user commits                                 446,365          124.1
     1.0
user rollbacks                                 3,040            0.9
     0.0


                                                                   Avg
                                                     Total Wait   wait
  Waits
Event                               Waits   Timeouts   Time (s)   (ms)
   /txn
---------------------------- ------------ ---------- ---------- ------
--------
log file sync                     483,596     84,157    194,940    403
    1.1
latch free                        656,366     97,456     46,963     72
    1.5
db file sequential read           232,327          0     31,051    134
    0.5
log file parallel write           201,538          0      2,810     14
    0.4
log file switch completion          2,144        951      1,400    653
    0.0
LGWR wait for redo copy            28,882        987         90      3
    0.1
log buffer space                      139          0         33    237
    0.0

Statistic                                      Total     per Second
per Trans
--------------------------------- ------------------ --------------
------------
redo blocks written                        2,741,252          762.1
     6.1
redo buffer allocation retries                   987            0.3
     0.0
redo entries                               4,679,630        1,301.0
    10.4
redo log space requests                        2,152            0.6
     0.0
redo log space wait time                     143,443           39.9
     0.3
redo ordering marks                           52,641           14.6
     0.1
redo size                              1,333,030,044      370,595.0
 2,966.2
redo synch time                           19,878,863        5,526.5
    44.2
redo synch writes                            420,314          116.9
     0.9
redo wastage                              26,035,760        7,238.2
    57.9
redo write time                              288,328           80.2
     0.6
redo writer latching time                      9,263            2.6
     0.0
redo writes                                  101,250           28.2
     0.2


                                           Pct    Avg   Wait
     Pct
                              Get          Get   Slps   Time
NoWait NoWait
Latch                       Requests      Miss  /Miss    (s)
Requests   Miss
------------------------ -------------- ------ ------ ------
------------ ------

redo allocation               4,875,468    0.6    0.1    195
0
redo copy                           962   98.0    1.0    104
4,677,696    1.4
redo writing                    315,135    0.0    0.1      0
0


124.1 commit occurs in each second.

1.

log file sync avg.wait time is 403 msec , and log file parallel write
avg. wait time is 14msec.

log file sync total wait value is about 2 times of log file parallel
write . Is this a great difference or not i dont know.

dsi405 instance tuning document says ,

if log file sync is main wait event , than check if lgwr wait for redo
copy is also high . Here i consider it low . ( 3ms.)

then the same doc says , check log buffer space :

log buffer space                      139          0         33    237
    0.0

very low number of total waits but very high number of average wait .
How should i consider this value? (I choose  low , because of 139 total
wait )

so the doc says , if neither of these two wait events are high than the
disk io is slow, tune disk io.

2.  again same doc says , if latch free is also in top list , check
latch values:



                                           Pct    Avg   Wait
     Pct
                              Get          Get   Slps   Time
NoWait NoWait
Latch                       Requests      Miss  /Miss    (s)
Requests   Miss
------------------------ -------------- ------ ------ ------
------------ ------

redo copy                           962   98.0    1.0    104
4,677,696    1.4


pctgetmiss is 98 , but nowait is 1.4 . nowait requests is much more
bigger than get requests. so is redo copy latch value considered high
or low?



Kind Regards,
hope



K Gopalakrishnan wrote:
> Not always (at least in RAC!!)
>
> In a RAC environment, cache fusion transfers sometimes causes the log
> file sync event. This is due to the write ahead logging mechanism. When
> a foreground process requests a block from another instance, all the
> redo entries associated with the block must be flushed to disk prior to
> transferring the block. In this case, there is no commit involved, but
> buffer cahe synchronization and waits on the log file sync event.
>
>
> >log file sync = commit.
> > Consequently, if you state you can't change the app, you can't change
> > the *number* of commits, but you can influence their *duration*.
> >
> > --
> > Sybrand Bakker
> > Senior Oracke DBA'- Hide quoted text -- Show quoted text -
>
> Best Regards,
> K Gopalakrishnan
>
> Co-Author: Oracle Wait Interface, Oracle Press 2004
> http://www.amazon.com/exec/obidos/tg/detail/-/007222729X/
>
> Author: Oracle Database 10g RAC Handbook, Oracle Press 2006
> http://www.amazon.com/gp/product/007146509X/

0
hopehope_123 (149)
12/19/2006 8:51:02 PM
db_man wrote:
> Hi
> 
> Thanks for your comments.
> 
> Sybrand , spend some time in google to find what top-posting mean ,
> sorry to be honest i
> havent heard the term till you told to me.
> Changing the nick name is a bad idea  , i admit.  Anyway dont want to
> do top-posting , but dont know how to stop it .

You use your mouse on the scroll bar to scroll to the bottom.

You insert a new line.

Then you type your message.

Everyone else seems to be able to do it.

If you are having some issue that seems to prevent it please advise
as to your browser version, etc.
-- 
Daniel A. Morgan
University of Washington
damorgan@x.washington.edu
(replace x with u to respond)
Puget Sound Oracle Users Group
www.psoug.org
0
damorgan3 (6326)
12/19/2006 10:57:16 PM
db_man wrote:
> Hi
>
> Thanks for your comments.
>
> Sybrand , spend some time in google to find what top-posting mean ,
> sorry to be honest i
> havent heard the term till you told to me.
> Changing the nick name is a bad idea  , i admit.  Anyway dont want to
> do top-posting , but dont know how to stop it .
>
> Returning to the statspack output :
>
> Top 5 Timed Events
> ~~~~~~~~~~~~~~~~~~
> % Total
> Event                                               Waits    Time (s)
> Ela Time
> -------------------------------------------- ------------ -----------
> --------
> log file sync                                     483,596     194,940
>  64.17
> latch free                                        656,366      46,963
>  15.46
> db file sequential read                           232,327      31,051
>  10.22
> CPU time                                                       20,846
>   6.86
> log file parallel write                           201,538       2,810
>    .93
>           -------------------------------------------------------------
>
>
> Here the short story is to change the redo log location on a non-raid5
> location or not.
> One of the dba's who i trust told to me that , providing with the low
> log file parallel write average wait time
> the main problem is not the redo log writing but huge number of
> commits.
>
> I want to be sure , and if writing through the redo log is problem , i
> must proof it.
>
> After reading more documents , i see lots of statistics , values to
> compare , will be appreciated if you comment . I am not sure whether
> this type of digging values is the right way to go.
>
>
>      Load Profile
> ~~~~~~~~~~~~                            Per Second       Per
> Transaction
>                                 ---------------       ---------------
>                   Redo size:            370,594.95
> 2,966.21
>               Logical reads:             39,925.48
> 319.56
>               Block changes:              2,447.17
> 19.59
>              Physical reads:                 67.83
> 0.54
>             Physical writes:                433.47
> 3.47
>                  User calls:                880.52
> 7.05
>                      Parses:                275.49
> 2.21
>                 Hard parses:                  1.92
> 0.02
>                       Sorts:                553.98
> 4.43
>                      Logons:                  0.29
> 0.00
>                    Executes:              5,303.67
> 42.45
>                Transactions:                124.94
>
> Statistic                                      Total     per Second
> per Trans
> --------------------------------- ------------------ --------------
> ------------
> user commits                                 446,365          124.1
>      1.0
> user rollbacks                                 3,040            0.9
>      0.0
>
>
>                                                                    Avg
>                                                      Total Wait   wait
>   Waits
> Event                               Waits   Timeouts   Time (s)   (ms)
>    /txn
> ---------------------------- ------------ ---------- ---------- ------
> --------
> log file sync                     483,596     84,157    194,940    403
>     1.1
> latch free                        656,366     97,456     46,963     72
>     1.5
> db file sequential read           232,327          0     31,051    134
>     0.5
> log file parallel write           201,538          0      2,810     14
>     0.4
> log file switch completion          2,144        951      1,400    653
>     0.0
> LGWR wait for redo copy            28,882        987         90      3
>     0.1
> log buffer space                      139          0         33    237
>     0.0
>
> Statistic                                      Total     per Second
> per Trans
> --------------------------------- ------------------ --------------
> ------------
> redo blocks written                        2,741,252          762.1
>      6.1
> redo buffer allocation retries                   987            0.3
>      0.0
> redo entries                               4,679,630        1,301.0
>     10.4
> redo log space requests                        2,152            0.6
>      0.0
> redo log space wait time                     143,443           39.9
>      0.3
> redo ordering marks                           52,641           14.6
>      0.1
> redo size                              1,333,030,044      370,595.0
>  2,966.2
> redo synch time                           19,878,863        5,526.5
>     44.2
> redo synch writes                            420,314          116.9
>      0.9
> redo wastage                              26,035,760        7,238.2
>     57.9
> redo write time                              288,328           80.2
>      0.6
> redo writer latching time                      9,263            2.6
>      0.0
> redo writes                                  101,250           28.2
>      0.2
>
>
>                                            Pct    Avg   Wait
>      Pct
>                               Get          Get   Slps   Time
> NoWait NoWait
> Latch                       Requests      Miss  /Miss    (s)
> Requests   Miss
> ------------------------ -------------- ------ ------ ------
> ------------ ------
>
> redo allocation               4,875,468    0.6    0.1    195
> 0
> redo copy                           962   98.0    1.0    104
> 4,677,696    1.4
> redo writing                    315,135    0.0    0.1      0
> 0
>
>
> 124.1 commit occurs in each second.
>
> 1.
>
> log file sync avg.wait time is 403 msec , and log file parallel write
> avg. wait time is 14msec.
>
> log file sync total wait value is about 2 times of log file parallel
> write . Is this a great difference or not i dont know.
>
> dsi405 instance tuning document says ,
>
> if log file sync is main wait event , than check if lgwr wait for redo
> copy is also high . Here i consider it low . ( 3ms.)
>
> then the same doc says , check log buffer space :
>
> log buffer space                      139          0         33    237
>     0.0
>
> very low number of total waits but very high number of average wait .
> How should i consider this value? (I choose  low , because of 139 total
> wait )
>
> so the doc says , if neither of these two wait events are high than the
> disk io is slow, tune disk io.
>
> 2.  again same doc says , if latch free is also in top list , check
> latch values:
>
>
>
>                                            Pct    Avg   Wait
>      Pct
>                               Get          Get   Slps   Time
> NoWait NoWait
> Latch                       Requests      Miss  /Miss    (s)
> Requests   Miss
> ------------------------ -------------- ------ ------ ------
> ------------ ------
>
> redo copy                           962   98.0    1.0    104
> 4,677,696    1.4
>
>
> pctgetmiss is 98 , but nowait is 1.4 . nowait requests is much more
> bigger than get requests. so is redo copy latch value considered high
> or low?
>
>
>
> Kind Regards,
> hope

Yes your average time for the log file sync does seem high.  You would
hope to see that in the 2 to 15 msec range.  RAID 5 setup may be
somewhat implicated in your problem but a larger problem maybe the
application behavior.  Is your application doing a commit for every row
updated?

I suggest you go to Tom Kyte's site http://asktom.oracle.com and so
some searches on things like "log file sync" and/or "commit strategy"
etc.

Look for an item "what is redo log sync".

0
johnbhurley (2707)
12/20/2006 3:12:48 PM
Thanks for your replies.

We started to control the application also.

Kind Regards,


hpuxrac wrote:
> db_man wrote:
> > Hi
> >
> > Thanks for your comments.
> >
> > Sybrand , spend some time in google to find what top-posting mean ,
> > sorry to be honest i
> > havent heard the term till you told to me.
> > Changing the nick name is a bad idea  , i admit.  Anyway dont want to
> > do top-posting , but dont know how to stop it .
> >
> > Returning to the statspack output :
> >
> > Top 5 Timed Events
> > ~~~~~~~~~~~~~~~~~~
> > % Total
> > Event                                               Waits    Time (s)
> > Ela Time
> > -------------------------------------------- ------------ -----------
> > --------
> > log file sync                                     483,596     194,940
> >  64.17
> > latch free                                        656,366      46,963
> >  15.46
> > db file sequential read                           232,327      31,051
> >  10.22
> > CPU time                                                       20,846
> >   6.86
> > log file parallel write                           201,538       2,810
> >    .93
> >           -------------------------------------------------------------
> >
> >
> > Here the short story is to change the redo log location on a non-raid5
> > location or not.
> > One of the dba's who i trust told to me that , providing with the low
> > log file parallel write average wait time
> > the main problem is not the redo log writing but huge number of
> > commits.
> >
> > I want to be sure , and if writing through the redo log is problem , i
> > must proof it.
> >
> > After reading more documents , i see lots of statistics , values to
> > compare , will be appreciated if you comment . I am not sure whether
> > this type of digging values is the right way to go.
> >
> >
> >      Load Profile
> > ~~~~~~~~~~~~                            Per Second       Per
> > Transaction
> >                                 ---------------       ---------------
> >                   Redo size:            370,594.95
> > 2,966.21
> >               Logical reads:             39,925.48
> > 319.56
> >               Block changes:              2,447.17
> > 19.59
> >              Physical reads:                 67.83
> > 0.54
> >             Physical writes:                433.47
> > 3.47
> >                  User calls:                880.52
> > 7.05
> >                      Parses:                275.49
> > 2.21
> >                 Hard parses:                  1.92
> > 0.02
> >                       Sorts:                553.98
> > 4.43
> >                      Logons:                  0.29
> > 0.00
> >                    Executes:              5,303.67
> > 42.45
> >                Transactions:                124.94
> >
> > Statistic                                      Total     per Second
> > per Trans
> > --------------------------------- ------------------ --------------
> > ------------
> > user commits                                 446,365          124.1
> >      1.0
> > user rollbacks                                 3,040            0.9
> >      0.0
> >
> >
> >                                                                    Avg
> >                                                      Total Wait   wait
> >   Waits
> > Event                               Waits   Timeouts   Time (s)   (ms)
> >    /txn
> > ---------------------------- ------------ ---------- ---------- ------
> > --------
> > log file sync                     483,596     84,157    194,940    403
> >     1.1
> > latch free                        656,366     97,456     46,963     72
> >     1.5
> > db file sequential read           232,327          0     31,051    134
> >     0.5
> > log file parallel write           201,538          0      2,810     14
> >     0.4
> > log file switch completion          2,144        951      1,400    653
> >     0.0
> > LGWR wait for redo copy            28,882        987         90      3
> >     0.1
> > log buffer space                      139          0         33    237
> >     0.0
> >
> > Statistic                                      Total     per Second
> > per Trans
> > --------------------------------- ------------------ --------------
> > ------------
> > redo blocks written                        2,741,252          762.1
> >      6.1
> > redo buffer allocation retries                   987            0.3
> >      0.0
> > redo entries                               4,679,630        1,301.0
> >     10.4
> > redo log space requests                        2,152            0.6
> >      0.0
> > redo log space wait time                     143,443           39.9
> >      0.3
> > redo ordering marks                           52,641           14.6
> >      0.1
> > redo size                              1,333,030,044      370,595.0
> >  2,966.2
> > redo synch time                           19,878,863        5,526.5
> >     44.2
> > redo synch writes                            420,314          116.9
> >      0.9
> > redo wastage                              26,035,760        7,238.2
> >     57.9
> > redo write time                              288,328           80.2
> >      0.6
> > redo writer latching time                      9,263            2.6
> >      0.0
> > redo writes                                  101,250           28.2
> >      0.2
> >
> >
> >                                            Pct    Avg   Wait
> >      Pct
> >                               Get          Get   Slps   Time
> > NoWait NoWait
> > Latch                       Requests      Miss  /Miss    (s)
> > Requests   Miss
> > ------------------------ -------------- ------ ------ ------
> > ------------ ------
> >
> > redo allocation               4,875,468    0.6    0.1    195
> > 0
> > redo copy                           962   98.0    1.0    104
> > 4,677,696    1.4
> > redo writing                    315,135    0.0    0.1      0
> > 0
> >
> >
> > 124.1 commit occurs in each second.
> >
> > 1.
> >
> > log file sync avg.wait time is 403 msec , and log file parallel write
> > avg. wait time is 14msec.
> >
> > log file sync total wait value is about 2 times of log file parallel
> > write . Is this a great difference or not i dont know.
> >
> > dsi405 instance tuning document says ,
> >
> > if log file sync is main wait event , than check if lgwr wait for redo
> > copy is also high . Here i consider it low . ( 3ms.)
> >
> > then the same doc says , check log buffer space :
> >
> > log buffer space                      139          0         33    237
> >     0.0
> >
> > very low number of total waits but very high number of average wait .
> > How should i consider this value? (I choose  low , because of 139 total
> > wait )
> >
> > so the doc says , if neither of these two wait events are high than the
> > disk io is slow, tune disk io.
> >
> > 2.  again same doc says , if latch free is also in top list , check
> > latch values:
> >
> >
> >
> >                                            Pct    Avg   Wait
> >      Pct
> >                               Get          Get   Slps   Time
> > NoWait NoWait
> > Latch                       Requests      Miss  /Miss    (s)
> > Requests   Miss
> > ------------------------ -------------- ------ ------ ------
> > ------------ ------
> >
> > redo copy                           962   98.0    1.0    104
> > 4,677,696    1.4
> >
> >
> > pctgetmiss is 98 , but nowait is 1.4 . nowait requests is much more
> > bigger than get requests. so is redo copy latch value considered high
> > or low?
> >
> >
> >
> > Kind Regards,
> > hope
>
> Yes your average time for the log file sync does seem high.  You would
> hope to see that in the 2 to 15 msec range.  RAID 5 setup may be
> somewhat implicated in your problem but a larger problem maybe the
> application behavior.  Is your application doing a commit for every row
> updated?
>
> I suggest you go to Tom Kyte's site http://asktom.oracle.com and so
> some searches on things like "log file sync" and/or "commit strategy"
> etc.
> 
> Look for an item "what is redo log sync".

0
hopehope_123 (149)
12/20/2006 3:23:27 PM
Reply: