LOG FILE SYNC概述
來新公司工作，很大的一段時間都在調優日志寫，提升系統的TPS，在這方面也積累了一些理論知識和實踐經驗，之前零零散散在微網誌上也發了很多關于log file sync的文章，篇幅都很短，有些是自己優化系統過程中的一個心得，有些是看書過程中的一點感悟，這次把他們彙集起來，變得也更有可讀性一些，作為自己的一個總結，也希望裡面的内容也或多或少能夠幫助到你。
log file sycn是ORACLE裡最普遍的等待事件之一，一般log file sycn的等待時間都非常短 1-5ms，不會有什麼問題，但是一旦出問題，往往都比較難解決。什麼時候會産生log file sync等待？
常見有以下幾種：
1)commit操作
2)rollback操作
3)DDL操作（DDL操作實施前都會首先進行一次commit）
4)DDL操作導緻的資料字典修改所産生的commit
5)某些能遞歸修改資料字典的操作：比如查詢SEQ的next值，可能會導緻修改資料字典。一個典型的情況是，SEQ的cache屬性設定為nocache，那麼會導緻每次調用SEQ都要修改資料字典，産生遞歸的commit。
一個正常的系統裡，絕大多數的log file sycn等待都應該是上面描述的1）commit操作 造成的log file sycn等待，某些異常的系統，比如頻頻rollback、seq的cache設定為nocache的系統，也可能會造成比較多的log file sycn等待。
我們要是能知道log file sync包含哪些環節，再有針對性的優化各個環節，就能事半功倍了。
<ignore_js_op>
上面是Tanel Ponder畫的log file sync等待事件的延遲圖，在某些關鍵環節上打了點。我對其中打點的環節，稍作翻譯如下：
1)使用者程序發起commit
2)使用者程序通知lgwr寫日志
3)lgwr接收到請求開始寫
4)lgwr寫完成
5)lgwr通知使用者程序寫完成
6)使用者程序獲得通知，繼續做其他事
1,2階段的時間，主要是post/wait的時間，典型的這種post/wait一般利用的是作業系統的信号量（IPC)實作，如果系統CPU資源充足，一般不會出現大的延遲。前台程序post lgwr後，就開始等待log file sync。
2,3階段的時間，主要是lgwr為了擷取cpu資源，等待cpu排程的時間，如果系統cpu資源充足，一般不會出現大的延遲。這裡我們需要知道，lgwr隻是作業系統的一個程序，它需要作業系統的排程擷取cpu資源後才可以工作
3,4階段的時間，主要是真正的實體io時間，lgwr通知os把log buffer的内容寫入到磁盤，然後lgwr進入睡眠（等待log file parallel write），這個時間正常情況下的延遲占整個log file sync的大部分時間。還需要指出，lgwr在擷取cpu資源後，可能并不能馬上通知os寫磁盤，隻有在確定所有的redo copy latch都已經被釋放，才能開始真正的IO操作。
4,5階段的時間，os排程lgwr 重新獲得cpu資源，lgwr post前台程序寫完成。lgwr可能會post很多前台程序(group commit的副作用)
5,6階段的時間，前台程序接受到lgwr的通知，傳回cpu運作隊列，處理其他事物（log file sync結束）。
/*************************************************什麼是group commit************************************************/
不止一次的看到過一些對log file sync調優的建議裡寫着：打開ORACLE的組送出功能。
group commit預設就是開啟的，而且你沒有任何手段可以關閉它!
我一直認為group commit這個東東起的名字不是太過恰當，應該起組重新整理更恰當，僅僅代表個人意見。
什麼是組送出？
上圖是log buffer的抽象圖，log buffer此時是非常繁忙的。
給大家設定這樣一個場景。
c1作為一個commit record已經被copy到了log buffer裡，接着前台程序通知lgwr去寫日志，根據我前面的描述，在前台程序post lgwr去寫，到lgwr真正開始寫之前，非常可能存在着時間差，就在這個時間差裡，c2,g1,c3也已經把相應的日志拷貝到了log buffer裡，其中c1,c2,c3是commit的記錄，g1僅僅是普通的事務日志，不是commit日志。在lgwr真正開始寫之前，它會去檢查目前log buffer的最高點，發現在c3位置處，把這個點作為此次重新整理日志的目标，把c1,c2,g1,c3的日志都重新整理到磁盤。雖然重新整理日志這個操作是由c1出發的，但是c2,g1,c3也是受惠者搭了便車，日志也被重新整理到了日志檔案裡，這個功能叫組送出，對于一些不太熟悉ORACLE的人容易把組送出誤解為，把送出的事物打包重新整理到日志裡，其實LGWR是不管你的事務日志有沒送出的，它隻按照log buffer配置設定的最高點來重新整理，是以我覺得叫組重新整理更好點。
圖中c1,c2,g1的日志已經拷貝完成，我用filled表示，c3的日志空間已經配置設定，但是還沒完成拷貝，我用allo表示，這個情況下，其實lgwr需要等待c3日志拷貝完成，才能真正的開始重新整理操作。
我們剖析了log file sycn的各個階段後，可以看出，正常情況下，最慢的環節應該在3,4階段（如上圖），典型的io操作，這個環節對應的資料庫等待叫做log file parallel write。其他的階段如排程延遲、IPC時間一般都是極短的。網上、論壇上、包括不少書籍裡，很多在log file sync出現問題後，往往都把責任推卸到IO慢的原因上。絕大多數情況下，這樣的推斷可能都是正确的，但是，事情不總是這樣的，就像我們分析的，log file sync的快慢也是很依賴cpu資源是否富足、系統的負載是不是過大。我們再看下一幅圖，這副圖描述了，在CPU資源不足的情況下，各個階段占取整個log file sycn的比重。
如你所見，由于CPU資源的不足、系統負載過大，導緻作業系統排程出現了較大的延遲，3,4階段的IO部分的延遲已經不是整個log file sync時間的最大的罪魁禍首！
/*********************************************小插曲*****************************************************************************/
lgwr會post哪些前台程序？
當lgwr重新整理完日志後，會post相應的前台程序(wakeup）繼續工作，那麼lgwr怎麼判斷應該wakeup哪些前台程序呢？
log file sync等待的p1參數的含義為：P1 = buffer# in log buffer that needs to be flushed
當lgwr重新整理完buffer後，會掃描活躍會話清單，檢視哪些會話在等待log file sync，而且會話的buffer#小于等于它所重新整理的log buffer的最大值，這些會話會被wakeup。
/*********************************************小插曲****************************************************************************/
LOG FILE SYNC調優
作為通用的log file sync的診斷、調優方法，一般可以通過診斷系統的IO延遲為多大，cpu資源是否充足來判斷哪裡出現了問題。
IO延遲的診斷、調優:可以通過log file parallel write這個背景程序等待事件來輔助判斷。如果這個等待時間過大，那麼你系統的IO很可能出現了問題。優化IO的手段一般為：RAID的方式不要為RAID5，最好為RAID10，關閉RAID卡的讀CACHE，全部用作寫CACHE，可以用2-4塊盤作為日志的磁盤組，如果使用的是存儲，一般存儲機頭的CACHE也比較大，IO上基本能得到保障。使用ssd作為日志組來提升IO并沒有什麼好的效果。可以通過 v$event_histogram視圖擷取log file sycn、log file parallel write等待事件的時間分布圖（後面有介紹）來輔助診斷。
cpu資源的診斷、調優:如果log file sync的時間與log file parallel write的時間差異過大，則可能系統的CPU資源出現了不足。solaris下還可以通過作業系統工具prstat來診斷lgwr程序的延遲時間，見下圖的LAT列。其他平台不能直接針對程序進行跟蹤診斷，可以通過系統LOAD，CPU使用率來輔助診斷，如CPU使用率超過百分之六十可能就會造成一定程度的排程延遲、CPU運作隊列超過實體CPU的CORE數就有排程延遲的風險等等。如果系統的CPU資源出現瓶頸是比較棘手的，因為換硬碟尚且還算是執行起來不算費勁的，但是換CPU難度一般會比較大，最終可能的結果就是換主機。不過也有一些手段可以嘗試：調高LGWR的優先級，可以通過資料庫參數_high_priority_processes進行，或者作業系統指令renice指令進行（前者可能更好點）。調整LGWR優先級的目的是為了讓LGWR盡可能的容易獲得CPU資源，減少排隊排程時間。
調優應用：不過有時候更為有效的手段可能不是拼命的調優資料庫、調優硬體，比如：是不是可以合并事物，也就降低了LOG FILE SYNC的次數，變相的提高了系統事務的效率。
資料庫調優：通過設定ORACLE的REDO LOG 塊大小為4K來提升日志寫的性能.11GR2的版本可以指定REDO LOG的塊大小。在我的版本11.2.0.3下修改會報錯，說修改值與實際扇區大小不比對。通過修改隐含參數_disk_sector_size_override為true，可以強制改成功。修改的辦法是在alter database add log file xxxx blocksize 4096。如果拿PL/SQL壓測，采取commit write immediate wait方式送出，優化前後的差距接近4倍，非常驚人。但是拿我們的業務壓測，隻是提升了1500+的TPS，也非常的不錯了。
記憶體調優：在AIX下，如果開啟記憶體預讀，對于提升TPS也是非常的明顯 dscrctl -n -b -s 1 。見http://space.itpub.net/22034023/viewspace-751590。
/*****************************************************************************可憐的LGWR****************************************************************************/
如果有大量程序在等待LOG FILE SYCN，一旦LGWR寫完成，它将POST這些程序蘇醒，使它們重新進入CPU運作隊列，而LGWR會被當初post它寫日志的程序push off出cpu運作隊列。這個情形下，由于LGWR已經工作了一段時間了（剛剛寫完日志），而前台程序已經等待了一段時間了（等待LOG FILE SYNC)，根據作業系統的預設的排程政策，這種情況下，前台程序将會有更高的優先級擷取CPU資源，而LGWR将可能由于CPU資源突發式的緊張而沒有擷取到CPU資源，導緻系統 的事務數有很大的降低：因為LGWR已經不工作了(雖然時間很短）。是以我前面所建議的調高LGWR程序優先級的手段是值得嘗試的。
擷取log file sync、log file parallel write時間分布
如果我們僅僅觀察AWR報告，擷取log file sync、log file parallel write某一段時間的平均等待時間，有時候是不夠的，我們可能想更精細化的知道，10000次等待裡，有多少次等待是在1ms以内，有多少次是在2ms以内，等等。查詢V$EVENT_HISTOGRAM可以告訴我們這些資訊，對于我們診斷性能問題非常有幫助。
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
如上，我們可以知道log file parallel write等待時間在1ms以内的有22677次，2ms以内的有424次，等等。
我們可以簡單的取兩次V$EVENT_HISTOGRAM的快照，來判斷間隔時間内，名額的變化次數來輔助我們診斷問題。（AWR思想）
LOG BUFFER 需要調優？
一般情況下，是不需要調優的！
10G以後，LOG BUFFER一般情況下已經比較大，一般為1到多個granules大小，除非你看到了比較多的log buffer space等待事件，否則不需要調整log buffer的大小。
9.2以後， LOG BUFFER根據你系統CPU的多少，已經被拆分成多個LOG BUFFER，很大程度上緩解了redo allocatoin latch的争用，除非看到了明顯的redo allocation latch的争用，否則不用調整log buffer的數量。
10G以後，私有redo和imu的出現，進一步降低了redo allocation latch的争用。每一個私有redo都由一個私有的redo allocation latch保護。同上，一般情況不用調整。
redo相關latch需要調優？
redo copy latch：僅僅用來跟蹤是否有程序正在往log buffer裡拷貝資料。lgwr在真正開始寫之前，必須等待相關的程序拷貝完畢，在此期間,lgwr會等待LGWR wait for redo copy等待。可以同時向log buffer裡進行拷貝的程序的數量由_log_simultaneous_copies決定。
redo allocation latch：保護程序在redo buffer裡配置設定空間用的，保證各個程序間彼此配置設定的空間不重疊。
redo writing latch：這個latch其實保護的是一個标志位，程序擷取這個latch後，修改标志位，比如把0改為1，代表lgwr正在寫，這樣後續的送出程序，獲得這個latch後讀取标志位，就知道目前LGWR是不是正在寫了，避免了很多不需要的重複通知。
我們知道了這幾個latch的作用，那麼我們需要調優他們嗎？
一般是不需要的，除非他們相關的等待已經引起了你的注意，而且ORACLE各個版本也一直在優化相關的latch的擷取和釋放，比如redo allocation latch，這一塊已經做的非常高效了。關于redo allocation latch發展史，檢視我的另一篇文章：http://www.itpub.net/thread-1803010-1-1.html
新的調優手段
10GR1的時候，ORACLE公司默默的推出了一個參數：commit_logging，這個參數可以有四種組合：
commit write [batch|immediate][wait|nowait]
10GR2版本釋出的時候，這個參數被拆成了2個參數，commit_logging，commit_write，個人認為10GR2拆分後的參數，更能準确表達參數的意圖。
我們先着重的看下commit_write這個參數，它的參數值可以為wait/nowait，代表：前台程序事務送出的時候，通不通知LGWR去重新整理日志。wait為通知，前台程序會等待log file sync。nowait為不通知，僅僅等待其他操作觸發lgwr去寫日志（如3秒，1M大小，1/3滿）。如果你的業務對資料的一緻性的要求不高，對ACID的D沒有要求，為了提高事物數、提高性能，你可以選擇commit_write為nowait方式。而在10G以前，ACID的D是必須滿足的，也就是說，前台程序在送出的時候，是必須要等待LOG FILE SYNC，等待LGWR重新整理日志到磁盤的。
我們來簡單的看下commit_logging參數，參數可以選擇的值有batch/immediate，這個參數極其容易引起人的誤解，讓人誤以為batch的含義是，控制着事物以group commit的方式打包送出。immediate方式是代表讓事物一個個的送出，一次送出重新整理一次log buffer，但是不是這樣的！
immediate與batch相比，commit的改變向量（修改復原段頭的事務槽）将作為單獨的redo record産生，跟9I的commit記錄日志的方式是一樣的。batch 模式下commit日志的記錄方式是合并進事務的redo record裡，這個batch模式依賴使用私有redo和imu，如果他們關閉的情況下，batch的設定也就沒了作用。
我們對insert into a values(1111);commit;來進行dump log file，闡述一下batch/immediate方式的差別 :
DUMP LOG FILE：啟用私有redo和imu，設定commit_logging為immediate，commit的日志作為單獨的redo record産生，一共2條redo record，第二個redo record為commit産生的，見紅色部分(OP:5.4,代表為UNDO段頭的修改）
REDO RECORD - Thread:1 RBA: 0x00044d.00000002.0010 LEN: 0x0230 VLD: 0x05
SCN: 0x0000.041b921c SUBSCN: 1 06/25/2013 11:27:32
(LWN RBA: 0x00044d.00000002.0010 LEN: 0002 NST: 0001 SCN: 0x0000.041b921c)
CHANGE #1 TYP:0 CLS:51 AFN:3 DBA:0x00c04c80 OBJ:4294967295 SCN:0x0000.041b91d1 SEQ:1 OP:5.2 ENC:0 RBL:0
ktudh redo: slt: 0x0016 sqn: 0x00002bee flg: 0x0012 siz: 136 fbi: 0
uba: 0x00d1a78d.0068.2c pxid: 0x0000.000.00000000
CHANGE #2 TYP:2 CLS:1 AFN:9 DBA:0x024002c5 OBJ:15750 SCN:0x0000.041b916a SEQ:1 OP:11.2 ENC:0 RBL:0
省略
REDO RECORD - Thread:1 RBA: 0x00044d.00000004.0010 LEN: 0x00d0 VLD: 0x05
SCN: 0x0000.041b921e SUBSCN: 1 06/25/2013 11:27:34
(LWN RBA: 0x00044d.00000004.0010 LEN: 0001 NST: 0001 SCN: 0x0000.041b921d)
CHANGE #1 TYP:0 CLS:51 AFN:3 DBA:0x00c04c80 OBJ:4294967295 SCN:0x0000.041b921c SEQ:1 OP:5.4 ENC:0 RBL:0
ktucm redo: slt: 0x0016 sqn: 0x00002bee srt: 0 sta: 9 flg: 0x2 ktucf redo: uba: 0x00d1a78d.0068.2c ext: 104 spc: 2050 fbi: 0
DUMP LOG FILE：啟用私有redo和imu，設定commit_logging為batch，commit作為一個改變向量合并進了事物的redo record裡，作為一條redo record，change #3為commit産生的。
CHANGE #3 TYP:0 CLS:51 AFN:3 DBA:0x00c04c80 OBJ:4294967295 SCN:0x0000.041b921c SEQ:1 OP:5.4 ENC:0 RBL:0
個人感覺commit_logging參數的作用不大，可能有助于減少ACID的異常時間，對日志量的size在batch模式下有輕微的減少。ACID異常見我的另一個文章：http://www.itpub.net/thread-1803010-1-1.html
PL/SQL commit優化
傳統情況下，當使用者發出commit後，使用者會話會等待log file sync直到lgwr寫完成。LGWR寫完成後，通知處于前台程序繼續處理後面的操作。這個機制保障了事務的持久性，滿足了事務ACID的D。但是PL/SQL不是這麼工作的：PL/SQL裡的commit 操作不會等待lgwr寫完成就可以繼續處理後面的操作。簡單的看個例子：
begin
for r in (select id from t1 where mod(id, 20) = 0) loop
update t1 set small_no = small_no + .1 where id = r.id;
commit;
end loop;
end;
/
檢視session 和 sys相關的統計資訊如下：
user commits (session statistic) 25
messages sent (session statistic) 6
redo synch writes(session statistic) 1
log file sync (session events) 1
messages received (lgwr statistic) 6
redo writes (lgwr statistic) 6
log file parallel write (lgwr events) 6
Lgwr僅僅寫了6次（log file parallel write），使用者會話僅僅等待了log file sync一次。那意味着會話發出commit指令後，并沒有停下來等待lgwr寫完成，就繼續處理後面的事務了。使用者會話沒有遵守事務的持久化原則！！如果執行個體在PL/SQL處理的過程中crash，那麼某些送出的事務是不可恢複的。Oracle對此有一個貌似合理的解釋，在PL/SQL沒有處理完畢之前，你不知道已經送出了多少次，Oracle不會使他們可恢複，隻有在PL/SQL結束的時候，增加redo sync writes次數和前台程序進入log file sync等待。在進行PL/SQL處理期間，不停的檢視等待事件，背景看不到任何的log file sync等待。還有就是統計資料裡顯示了會話總共向lgwr發送了6次message sent請求（請求寫日志），lgwr也接受到了6次message recived資訊，并且寫了6次（log file parallel write）。你可能會問，到底多久，會話發送一次寫請求？每次前台程序給LGWR發送寫請求前，會去持有redo writing latch，然後檢查lgwr是不是已經在處理寫請求了，如果lgwr已經在寫了，前台程序不會向LGWR發送請求，也不會等待log fil sync，直接繼續完成後續的操作，如果lgwr沒在寫，前台程序通知lgwr去寫，但是不會等待log file sycn，還是繼續完成後續的操作，隻有在PL/SQL結束的時候，才會最終等待一次log file sync。是以如果你的磁盤寫的速率足夠快，那麼lgwr就會被post的次數越多，成正比的關系。還有如果你的cpu足夠強，那麼PL/SQL塊loop的時間就足夠小，時間小了，那麼lgwr被post的次數也就少了，成反比的關系（在磁盤寫速率一定的情況下）。
值得注意的是，如果PL/SQL裡包含了DBLINK，那麼就會使用傳統的送出方式，不會産生出這樣的“異常”。
最後提醒一句：雖然PL/SQL隻有在結束的時候才會等待lgwr寫完成，産生log file sync等待，但是不要認為，在PL/SQL運作過程中，執行個體crash掉，此次PL/SQL處理的所有事務就會丢失，不是這樣的，隻是丢失部分，pl/sql在運作過程中，會話是一直檢查lgwr是不是在工作的，如果沒在工作，就發送寫請求給lgwr的（message sent），lgwr接收到寫請求後，就要寫日志，隻要是被寫進了日志檔案的事務就是可恢複的。也就是說，雖然前台沒有等待log file sync，但是背景其實一直是在忙着處理你的事務日志的。
發現問題的手段
方式一：從awr裡去發現，依據avg wait(ms）去判斷系統的log file sync和log file parallel write是否存在問題。
方式二：通過moats工具去診斷目前資料庫的top wait有哪些，是否有log file sync、log file parallel write，工具下載下傳位址：http://www.oracle-developer.net/utilities.php。
方式三：通過lewis的snap_events腳本，獲得系統級别等待事件的等待次數、平均等待時間。
rem execute snap_events.start_snap
rem execute snap_events.end_snap
方式四：通過tanel poder的snap腳本采樣lgwr背景程序的等待事件分布以及lgwr程序相關的統計資訊。
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
複制代碼
相關的等待事件
1）log file sync（前台程序的等待事件）
2）log file parallel write（背景程序lgwr的等待事件）
3）log buffer space
lgwr重新整理太慢可能會導緻這個問題，導緻lgwr重新整理慢也有幾種情況
1.IO子系統太慢
2.lgwr不能獲得足夠的cpu資源
3.遭遇了大事務(expdp,insert /*+ append */ as ,imp,create as )
也可能是log buffer設定的太小了，不過在現在已經不太可能。預設的尺寸已經很大了。
4）log file single write
這個等待産生的原因是對日志檔案頭塊的讀寫。一般在如下情況下會産生：
1)日志切換
2)歸檔
log file sync與buffer busy waits
事物在進行送出的時候，對事物修改的，還在記憶體裡的塊做commit cleanout，其實主要就是設定ITL槽位裡的commit scn，不會去清楚lb資訊。ORACLE在進行commit cleanout期間，會擷取相關buffer的buffer pin，而且是排他模式擷取，這個pin直到lgwr把日志刷入到磁盤才釋放，如果在此期間，有程序對相關的buffer進行select/update/insert就會造成buffer busy waits。是以如果你的系統log file sync名額很高，也可能會導緻一定程度的buffer busy waits等待事件。
參考文獻：
oracle core :第二章、第六章
tanel poder:Understanding LGWR, Log File Sync Waits and Commit Performance
vage :http://www.itpub.net/thread-1593488-1-1.html
劉相兵：http://www.askmaclean.com/archives/why-slow-redo-write-cause-buffer-busy-wait.html
Riyaz Shamsudeen:http://orainternals.wordpress.com/2008/07/07/tuning-log-file-sync-wait-events/
Kevin Closson:http://kevinclosson.wordpress.com/2007/07/21/manly-men-only-use-solid-state-disk-for-redo-logging-lgwr-io-is-simple-but-not-lgwr-processing/
https://sites.google.com/site/embtdbo/wait-event-documentation/oracle-redo-log-waits#TOC-Log-file-Sync