Log File Sync

Understanding LGWR, Log File Sync Waits and Commit Performance
Tanel Pder http://blog.tanelpoder.com http://tech.e2sn.com
Enterprise 2.0 Service Networks
2009-2010 www.e2sn.com
WWW.E2SN.COM
Intro: About me
Tanel Pder
http://tech.e2sn.com - My company and technical Oracle stuff http://blog.tanelpoder.com - Personal Blog (more tech stuff) tanel@tanelpoder.com - Questions & enquiries
Consulting, Training, Seminars tanel@tanelpoder.com http://tech.e2sn.com/oracle-training-seminars

Online seminars coming soon!
WWW.E2SN.COM
Topics
How does commit & log file sync work
Overview
Reasons for too long log file sync waits
How to measure wheres the problem?
WWW.E2SN.COM
Reasons for log file sync waits

Commits wait for log file sync by default
User commits
Theres an user commits statistic in v$sesstat
DDL
Resulting recursive transactions commit
Recursive data dictionary DML
Rollbacks wait too!

User rollbacks
User/application issued a rollback command
Transaction rollbacks
We had an internal rollback (because of some failure) Space allocation/ASSM problems, cancelled queries, killed sessions
WWW.E2SN.COM
Commit & log file sync flow idealistic overview

Time
1) User issues a COMMIT 2) Foreground proc posts LGWR 3) LGWR issues the physical write syscall 5) LGWR posts the FG proc.
6) Commit complete
FG proc.
LGWR IO
4) The physcical write syscall completes
log file parallel write log file sync

Enterprise 2.0 Service Networks 2009-2010 www.e2sn.com
WWW.E2SN.COM
Log file sync performance -> disk IO speed

Time
FG proc.
LGWR IO
The physical write IO (log file parallel write) takes most of the time
Most of the log file sync time was spent waiting on log file parallel write The other components, scheduling latency, IPC were small
WWW.E2SN.COM
Log file sync performance -> scheduling latency

Time
1) User issues a COMMIT

FG proc.
2) LGWR waits in CPU runqueue
6) Foreground proc gets posted, gets onto CPU runqueue
LGWR IO
3) LGWR submits the IO, goes to sleep
4) IO completes, OS puts LGWR to CPU runqueue

WWW.E2SN.COM
5) LGWR gets onto CPU, posts foreground proc.
Log file sync flow

1. Foreground process (FG) posts LGWR and goes to sleep
The log file sync wait starts Posting is done via a semaphore operation on Unix/Linux
2. LGWR wakes up, gets onto CPU

Issues the IO request(s) LGWR goes to sleep, waiting for log file parallel write wait
3. Hardware completes the IO and OS wakes up LGWR

LGWR gets onto CPU Marks log file parallel write event complete and posts the FG
4. Foreground process is woken up by LGWR post

Foreground process gets onto CPU and completes the log file sync wait
WWW.E2SN.COM
Measuring LGWR "speed"

SQL> @snapper out 1 10 1096 -- Session Snapper v2.01 by Tanel Poder ( http://www.tanelpoder.com ) --------------------------------------------------------------------------------SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH --------------------------------------------------------------------------------1096, (LGWR) , STAT, messages sent , 12 , 12, 1096, (LGWR) , STAT, messages received , 10 , 10, 1096, (LGWR) , STAT, background timeouts , 1 , 1, 1096, (LGWR) , STAT, physical write total IO requests , 40, 40, 1096, (LGWR) , STAT, physical write total multi block request, 38, 38, 1096, (LGWR) , STAT, physical write total bytes, 2884608 , 2.88M, 1096, (LGWR) , STAT, calls to kcmgcs , 20 , 20, 1096, (LGWR) , STAT, redo wastage , 4548 , 4.55k, 1096, (LGWR) , STAT, redo writes , 10 , 10, 1096, (LGWR) , STAT, redo blocks written , 2817 , 2.82k, 1096, (LGWR) , STAT, redo write time , 25 , 25, 1096, (LGWR) , WAIT, LGWR wait on LNS , 1040575 , 1.04s, 104.1%, |@@@@@@@@@@| 1096, (LGWR) , WAIT, log file parallel write , 273837 , 273.84ms, 27.4%,|@@@ | 1096, (LGWR) , WAIT, events in waitclass Other , 1035172 , 1.04s , 103.5%,|@@@@@@@@@@| -- End of snap 1, end=2010-03-23 12:46:04, seconds=1
WWW.E2SN.COM
LGWR and Asynch IO

oracle@linux01:~$ strace -cp `pgrep -f lgwr` Process 12457 attached - interrupt to quit ^CProcess 12457 detached % time seconds usecs/call calls errors This is what the log ------ ----------- ----------- --------- --------file263 parallel write wait 100.00 0.010000 38 3 0.00 0.000000 213 event0measures AIO 0.00 0.000000 0 8 reaping duration 0.00 0.000000 0 701 0.00 0.000000 0 41 0.00 0.000000 0 41 This system call is not 0.00 0.000000 0 2 0.00 0.000000 0 37 instrumented by wait ------ ----------- ----------- --------- --------Interface! 100.00 0.010000 1081 3
syscall -------------semtimedop times getrusage gettimeofday io_getevents io_submit semop semctl -------------total
WWW.E2SN.COM
10
Warning
The (background processes) IO instrumentation has quite a few bugs
Different IO modes, sync, asynd, direct, buffered etc
On some versions, the log file parallel write (and db file parallel write) arent properly instrumented
Version dependent, for example 11.2.0.1 on Linux When filesystemio_options = NONE, IO syscall waits are instrumented ok (but you dont wan to use this option) When filesystem_io_options = ASYNC, IO reaping waits are all very short
However theres unaccounted time in LGWRs wait profile
When filesystem_io_options = SETALL, IO reaping waits are instrumented properly

WWW.E2SN.COM
11
Redo, commit related latches and tuning

Redo related latches
redo allocation latches
Protect allocating space in log buffer / RBA ranges in redolog stream
redo copy latches

Used only for keeping track of whether anyones copying data into redo log buffer so that LGWR would know to wait for these memory copies to complete before it tries to write buffers to disk LGWR will wait for LGWR wait for redo copy wait event in such cases Used to be tuned by _log_simultaneous_copies
Should we tune any of these?

No, we should fix only problems which exist In other words, if wait interface doesnt show anyone waiting for them, then dont bother tuning them!
WWW.E2SN.COM
12
Instrumentation
Wait Events:
log file sync log file parallel write log file single write
Performance Counters (V$SESSTAT, V$SYSSTAT)

redo size redo writing time user commits user rollbacks transaction rollbacks
WWW.E2SN.COM
13
Wait event: log buffer space

(Not a commit problem) LGWR is too slow flushing redo log buffer contents to disk
Either because too slow IO subsystem Or LGWR not getting enough (quality) CPU time Sometimes pops up due large (unplanned) transactions
Of course, it can also be because of a too small log buffer

Which is not the case anymore in modern days Log buffer is usually multiple MB due how it is allocated from SGA You shouldnt even set the log_buffer parameter in 10g+
WWW.E2SN.COM
14
Wait event: log file single write

Single block redo IO is used mostly for logfile header block reading/writing
Log switch is the main cause Archiving as well as it updates log header Who wait: LGWR & ARCH
Example of what LGWR does during a log switch:

WAIT #0: nam='log file sequential read' ela= 12607 log#=0 block#=1 WAIT #0: nam='log file sequential read' ela= 21225 log#=1 block#=1 WAIT #0: nam='control file sequential read' ela= 358 file#=0 WAIT #0: nam='log file single write' ela= 470 log#=0 block#=1 WAIT #0: nam='log file single write' ela= 227 log#=1 block#=1
WWW.E2SN.COM
15
LGWR trace warnings

Starting from 10.2.0.3 (or was it 10.2.0.4) LGWR is trying to be helpful and dump warnings when the actual log write IO takes too long:
New parameter: _side_channel_batch_timeout_ms timeout before shipping out the batched side channelmessages in milliseconds
LGWR trace file:

*** 2010-03-10 11:36:06.759 Warning: log write time 690ms, size 19KB *** 2010-03-10 11:37:23.778 Warning: log write time 52710ms, size 0KB *** 2010-03-10 11:37:27.302 Warning: log write time 3520ms, size 144KB
WWW.E2SN.COM
16
Log file sync in Statspack / AWR

How much of the end-to-end response time goes to log file sync?
How big it is compared to the full response time of the end user? Log file sync may take 20% of your DB Time but the DB Time itself may take only 10% of the total end user response time!
WWW.E2SN.COM
17
Log file sync in Statspack / AWR

If log file sync waits take a significant part of the response time, look into the Avg wait (ms) column:
Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time ------------------------------------- ------------ ----------- ------ -----PL/SQL lock timer 57,159 8,754 153 68.8 db file sequential read 61,258 1,562 25 12.3 log file sync 5,873 1,522 259 12.0 CPU time 463 3.6 direct path write 235,606 155 1 1.2 ............ %Tim Total Wait out Time (s) ---- ---------0 108 0 39 0 4 Avg %Total wait Waits Call (ms) /txn Time ------ -------- -----8 0.9 .8 11 0.2 .3 16 0.0 .0
Event Waits ------------------------ -----------log file parallel write 13,292 db file parallel write 3,470 db file sequential read 257
WWW.E2SN.COM
18
Better breakdown of wait times V$EVENT_HISTOGRAM

Instead of a single wait time average, breaks wait times into buckets
SQL> select event, wait_time_milli,wait_count 2 from v$event_histogram 3 where event = 'log file parallel write'; EVENT WAIT_TIME_MILLI WAIT_COUNT ------------------------- --------------- ---------log file parallel write 1 22677 log file parallel write 2 424 log file parallel write 4 141 log file parallel write 8 340 log file parallel write 16 1401 log file parallel write 32 812 log file parallel write 64 391 log file parallel write 128 21 log file parallel write 256 6
WWW.E2SN.COM
19
Identifying scheduling latency

Easy on Solaris prstat m
Works since Solaris 8
Timed_os_statistics
OS Wait-cpu (latency) time in v$sesstat
On other OSes, it cant be directly measured with standard tools Indirectly, you can look into system wide average CPU runqueue length and assume that LGWR was also queueing
Not a too systematic approach, huh?
WWW.E2SN.COM
20
Measure scheduling latency (Solaris) Reading thread-level microstate accounting data with prstat:
USR SYS TRP TFL/DFL LCK SLP LAT % % % % % % % Time spent on CPU in user mode Time spent on CPU in kernel mode Time spent processing system traps (CPU traps) Time spent processing text/data page faults Time spent waiting for user locks Time spent sleeping (other than user locks) CPU scheduling latency
# prstat -mLp 5124 PID USERNAME USR 5124 oracle 4.2 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0 5124 oracle 0.0
SYS 1.6 0.6 0.6 0.6 0.6 0.0 0.0 0.0 0.0
TRP 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
TFL 0.6 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
DFL 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
LCK 0.0 99 99 99 99 0.0 100 100 100
SLP 94 0.0 0.0 0.7 0.0 100 0.0 0.0 0.0
LAT VCX ICX SCL SIG PROCESS/LWPID 0.1 412 20 3K 0 oracle/1 0.0 44 3 90 0 oracle/11 0.0 44 0 90 0 oracle/7 0.0 46 0 90 0 oracle/9 0.0 44 1 90 0 oracle/5 0.0 24 0 7 0 oracle/2 0.0 1 0 5 0 oracle/3 0.0 1 0 5 0 oracle/10 0.0 1 0 5 0 oracle/8
WWW.E2SN.COM
21
Bugs, problems
No instrumentation
On some version/platform/IO configuration the wait interface doesnt record log file parallel write waits at all
The same goes for db file parallel writes (Ive noticed it on 9.2-10.2.0.x on Solaris for example)
For LGWR you can use V$SESSTAT redo write time statistic instead
Its in centiseconds
1-second log file sync bug

Most log file syncs took ~1 second to complete The posts sent back by LGWR were missed by foreground process Thus the FG always waited until the 1 second log file sync wait timeout happened
WWW.E2SN.COM
22
Tuning
No need for tuning!
Log buffer is quite large by default
All memory remaining in a granule after the allocation for fixed SGA is given to log buffer
Oracle used to have a single redo log buffer until v9.0

Redo allocation latch could become the ultimate contention point
Since 9.2, Oracle can have the log buffer split into multiple buffers
Each protected by a separate redo allocation latch
From 10g, Oracle can keep lots of small private redo strands in shared pool
Each protected by a separate redo allocation latch @rs.sql Show redo strands available
WWW.E2SN.COM
23
Evil tuning
If you dont care about the D in ACID (and want to occasionally lose data for fun), then:
10gR1:
commit_logging transaction commit log write behavior
10gR2:
commit_write commit_wait transaction commit log write behavior transaction commit log wait behavior
Old undocumented stuff

_wait_for_sync wait for sync on commit MUST BE ALWAYS TRUE
Old: Put redologs to /tmp (on Solaris) or in-memory disks (/dev/shm) for duration of a migration/upgrade
If your OS / server crashes, youll need to restore from a backup!
WWW.E2SN.COM
24
Optimizations for working around bad applications

Commit optimization
In PL/SQL since Oracle 9i The log file sync is deferred until the end of the PL/SQL call!
SQL> exec while true loop update t set a=a+1 ; commit ; end loop;
No log file sync waits log buffer space / log file switch completion waits more likely!
WWW.E2SN.COM
25
LGWR configuration CPU

Prevent priority decay
Put LGWR into fixed priority scheduling class (FX60 on Solaris) LGWR should get onto CPU faster when waking up LGWR isnt thrown off CPU as likely
If LGWR is still experiencing significant scheduling latency

You can put LGWR into a higher priority class
You should not put LGWR into the highest real-time class
Real time is tricky your process can monopolize a CPU for itself You dont want to make LGWR pre-empt the OS kernel! Note that Oracle sets some processes into higher priority by default:
_high_priority_processes
LMS*|VKTM 26
WWW.E2SN.COM
LGWR configuration - IO
Reduce the amount of work and waiting a log file parallel write has to do
Unbuffered concurrent IO
Verify with truss/strace whether proper flags are used (O_DIRECT, O_DIO, O_CIO etc)
Or use raw devices

ASM is essentially a raw device
Or ODM for some cases
And optimize the whole IO hardware stack, of course!

Note shat mid-large size storage arrays do have write cache built in So, moving redo log files to SSD may not give any advantage! Verify whats your current log file parallel write latency using v$event_histogram
WWW.E2SN.COM
27
log file sync magic tuning super-secret!!!
COMMIT LESS!!!
Commit when your business transaction ends, not after every single update!
WWW.E2SN.COM
28
Summary
Application: Commit less!
Ideally only when your logical business transaction ends
Troubleshooting: Measure log file sync at session level detail CPU: If waits for log file sync are significant - see whether LGWR gets:
Enough (quality) CPU time Onto the CPU fast enough
IO: See how much LGWR waits for log file parallel write event
Whats the log file parallel write completion time V$EVENT_HISTOGRAM for better detail
WWW.E2SN.COM
29
Thanks!
Download slides from:
http://tech.e2sn.com/oracle-slides-and-whitepapers
Download Snapper from:

http://tech.e2sn.com/oracle-scripts-and-tools/session-snapper
Blog:
http://blog.tanelpoder.com
Email:
tanel@tanelpoder.com
WWW.E2SN.COM
30

Log File Sync

Uploaded by

Copyright:

Available Formats

Log File Sync

Uploaded by

Document Information

Copyright

Available Formats

Share this document

Share or Embed Document

Sharing Options

Did you find this document useful?

Is this content inappropriate?

Copyright:

Available Formats

Log File Sync

Uploaded by

Copyright:

Available Formats

Understanding LGWR, Log File Sync Waits and Commit Performance

Tanel Pder http://blog.tanelpoder.com http://tech.e2sn.com

Enterprise 2.0 Service Networks

Consulting, Training, Seminars tanel@tanelpoder.com http://tech.e2sn.com/oracle-training-seminars

Enterprise 2.0 Service Networks

Reasons for too long log file sync waits

How to measure wheres the problem?

Enterprise 2.0 Service Networks

Reasons for log file sync waits

Recursive data dictionary DML

Rollbacks wait too!

Enterprise 2.0 Service Networks

Commit & log file sync flow idealistic overview

4) The physcical write syscall completes

log file parallel write log file sync

Log file sync performance -> disk IO speed

Enterprise 2.0 Service Networks

Log file sync performance -> scheduling latency

1) User issues a COMMIT

2) LGWR waits in CPU runqueue

6) Foreground proc gets posted, gets onto CPU runqueue

3) LGWR submits the IO, goes to sleep

4) IO completes, OS puts LGWR to CPU runqueue

5) LGWR gets onto CPU, posts foreground proc.

Enterprise 2.0 Service Networks

Log file sync flow

2. LGWR wakes up, gets onto CPU

3. Hardware completes the IO and OS wakes up LGWR

4. Foreground process is woken up by LGWR post

Measuring LGWR "speed"

Enterprise 2.0 Service Networks

LGWR and Asynch IO

Enterprise 2.0 Service Networks

When filesystem_io_options = SETALL, IO reaping waits are instrumented properly

Redo, commit related latches and tuning

redo copy latches

Should we tune any of these?

Enterprise 2.0 Service Networks

Performance Counters (V$SESSTAT, V$SYSSTAT)

Enterprise 2.0 Service Networks

Wait event: log buffer space

Of course, it can also be because of a too small log buffer

Enterprise 2.0 Service Networks

Wait event: log file single write

Example of what LGWR does during a log switch:

Enterprise 2.0 Service Networks

LGWR trace warnings

LGWR trace file:

Log file sync in Statspack / AWR

Enterprise 2.0 Service Networks

Log file sync in Statspack / AWR

Enterprise 2.0 Service Networks

Better breakdown of wait times V$EVENT_HISTOGRAM

Enterprise 2.0 Service Networks

Identifying scheduling latency

Enterprise 2.0 Service Networks

LCK 0.0 99 99 99 99 0.0 100 100 100

SLP 94 0.0 0.0 0.7 0.0 100 0.0 0.0 0.0

Enterprise 2.0 Service Networks

1-second log file sync bug