Re: log file sync , log file parallel write

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". Received on Wed Dec 20 2006 - 09:12:48 CST