Statspack 14-"log File sync" Waiting for events

Original source:

Http://www.eygle.com/statspack/statspack14-LogFileSync.htm

When a user submits (commits) or rolls back (rollback), the redo information of the session needs to be written out to redo logfile.
The user process notifies the LGWR to perform the write operation, and LGWR notifies the user of the process after completing the task.
This waiting event means that the user process waits for the LGWR to write to complete the notification.

For a rollback operation, the event records the time from the user issuing the rollback command to the rollback completion.

If the wait is too high, it may indicate that LGWR is inefficient, or that the system submits too frequently.
To address this issue, you can focus on:
Log file parallel write wait event
Statistical information such as user Commits,user rollback can be used to observe the number of commits or rollbacks

Solution:
1. Improve LGWR Performance
Use fast disks as much as possible, and do not store redo log file on a RAID 5 disk
2. Using Bulk Submissions
3. Appropriate use of nologging/unrecoverable options

You can calculate the average redo write size by using the following formula:

Avg.redo Write size = (Redo Block Written/redo writes) *512 bytes

If the system produces a lot of redo and writes less each time, it is generally stated that LGWR is activated too frequently.
may result in excessive redo-related latch competition, and Oracle may not be able to effectively use piggyback functionality.

We extracted some data from a statspack to study the problem.

1. Main information

DB Name db Id Instance Inst Num release OPS Host-------------------------------------------------------------------- -db 1222010599 Oracle 1 8.1.7.4.5 NO Sun Snap Id snap time Sessions---------------------------------Begin snap:3473 1 3-oct-04 13:43:00 540 End snap:3475 13-oct-04 14:07:28 540 elapsed:24.47 (mins) Cache sizes~~~~~~~~~~~: 102400 log_buffer:20971520 db_block_size:8192 shared_pool_size:600mload profile~~~~~~~~~~~~ per Second per Transaction ------------------------------Redo size:28,458.11 2,852.03 ...

2. Waiting for events



Event Waits Timeouts Time (CS) (ms)/txn-------------------------------------------------------------------------Log File Sync 14,466 2 4,150 3 1.0db file sequential read 17,202 0 2,869 2 1.2latch free 24,841 13,489 2,072 1 1.7 Direct Pat H Write 121 0 1,455 0.0db file parallel write 1,314 0 1,383 one 0.1log file sequential read 1,540 0 0 0.1....log fil e Switch Completion 1 0 3 0.0refresh controlfile command 0 1 0 0.0LGWR wait for redo copy 0 0 0.0....log file s Ingle Write 4 0 0 0 0.0

We see here that the log file sync and db file parallel write wait to appear simultaneously.
Apparently log file sync is waiting for DB file parallel write to complete.

There must be a bottleneck in disk IO, where the actual user's redo and data files are stored on a RAID disk with performance problems.
Need to be adjusted.

3. Statistical information



 statistic Total/Second per Trans------------------------------------------------------------------------- .... Redo blocks written 93,853 63.9 6.4redo buffer allocation retries 1 0.0 0.0redo entries 135,837 92.5 9.3redo log space Requests 1 0.0 0.0redo log space wait time 3 0.0 0.0redo ordering marks 0 0.0 0.0redo size 41,776,508 28,458.1 2,852.0red O Synch time 4,174 2.8 0.3redo Synch writes 14,198 9.7 1.0redo wastage 4,769,200 3,248.8 325.6redo write time 3,698 2.5 0. 3redo writer latching time 0 0.0 0.0redo writes 14,572 9.9 1.0....sorts (disk) 4 0.0 0.0sorts (memory) 179,856 122.5 12.3s Orts (rows) 2,750,980 1,874.0 187.8....transaction rollbacks 0.0 0.0transaction tables consistent rea 0 0.0 0.0transact Ion tables consistent rea 0 0.0 0.0user calls 1,390,718 947.4 94.9user commits 14,136 9.6 1.0user rollbacks 0.4 0.0wri Te clones created in Backgroun 0 0.0 0.0write clones created in Foregroun one 0.0 0.0------------------------------------- ------------------------

Avg.redo Write size = (Redo Block Written/redo writes) *512 bytes = (93,853/14,572) *512 = 3K



This average is too small, indicating that the system is submitted too frequently.



Latch sleep breakdown to db:dpshdb instance:dpshdb snaps:3473-3475-> ordered by misses Desc get Spin &latch Na Me Requests misses sleeps sleeps 1->4-------------------------------------------------------------------------- Row Cache Objects 12,257,850 113,299 113235/64/0/0/0shared pool 3,690,715 60,279 15,857 52484/588/65 46/661/0library C Ache 4,912,465 29,454 8,876 23823/2682/2 733/216/0cache buffers chains 10,314,526 2,856-2823/33/0/0/0redo writing 76,5 937 1 936/1/0/0/0session Idle bit 2,871,949 1 224/1/0/0/0messages 107,950 159 2 157/2/0/0/0session allocation 184,3 6 38/6/0/0/0checkpoint Queue latch 96,583 1 1 0/1/0/0/0---------------------------------------------------------- ---

Due to the frequent transition of LGWR activation, we see that there is a redo writing latch competition.

About redo Writing competition You can find a detailed introduction at Steve's site:
Http://www.ixora.com.au/notes/lgwr_latching.htm


Quoted is as follows:



When Lgwr wakes up, it's the redo writing latch to update the SGA variable that shows whether it is active. This prevents the other Oracle processes from posting LGWR needlessly. Lgwr then takes the redo allocation latch to determine how much redo might is available to write (subject to the release O f the Redo copy latches). If None, it takes the redo writing latch again to record, it is no longer active, before starting another RDBMS IPC me Ssage wait.
If There is redo to write, LGWR then inspects the latch recovery-for the areas copy redo (latches without the taking ES) to determine whether there are any incomplete into the log buffer. For incomplete copies above the sync RBA LGWR just the defers of this block and writing log buffer subsequent. For incomplete copies below the sync RBA, Lgwr sleeps on a lgwr wait for redo copy of wait event, and are posted when the requ Ired Copy latches have been released. The time taken by LGWR to take the redo writing and redo allocation latches with to wait for the redo copy latches is Accum Ulated in the redo writer latching time statistic.

(Prior to release 8i, foreground processes held redo copy latches more briefly because they not did-for th e Application of the change vectors. Therefore, LGWR would instead attempt to assure itself this there were no ongoing copies into the log buffer by taking all The redo copy latches.)

After each redo write has completed, LGWR takes the redo allocation, latch, and order to update the SGA again variable Ning the base disk block for the log buffer. This is effectively frees the log buffer blocks that have just been and so is written.





The author of this article:
Eygle,oracle technology concern, from China's largest Oracle technology forum Itpub.
Www.eygle.com is the author's personal site. You can contact the author by Guoqiang.Gai@gmail.com. Welcome technical discussions and exchange of links.

Original source:

Http://www.eygle.com/statspack/statspack14-LogFileSync.htm