log file sync等待事件

skzhuga發表於2018-11-06

事務提交的過程大致為:

 1.使用者程式發出commit命令

 2.使用者程式通知LGWR寫Redo buffer資料到Redo檔案

 3.LGWR寫Redo到檔案

 4.LGWR寫完通知使用者程式

 5.使用者程式收到寫完成通知,提交完成。

 6.CPU喚醒使用者程式

從步驟1開始,使用者程式開始等待log file sync,到步驟6結束。步驟3與步驟4中,LGWR等待log file parallel write。


一般來說,造成log file sync的原因有如下幾點:

  1.頻繁commit或者rollback

  2.IO緩慢 ,判斷是否由於緩慢的日誌I/O造成的,可以檢視log file sync與log file parallel write兩個等待事件的等待時間,如果比較接近,說明可能是日誌I/O比較緩慢或重做日誌過多

  3.過大的日誌緩衝區(Log Buffer)

  過大的log_buffer,允許LGWR變得懶惰,因為log buffer中的資料量無法達不到_LOG_IO_SIZE,導致更多的重做條目堆積在日誌緩衝區中。當事務提交或者3s時,LGWR才會把所有資料都寫入到redo log file中。由於資料很多,LGWR要用更多時間等待redo寫完畢。這種情況,可以調小引數_LOG_IO_SIZE引數,其預設值是LOG_BUFFER的1/3或1MB,取兩者之中較小的值。

  4.CPU負載高。 在系統負載高時(尤其是CPU高的情況,看vmstat r值),步驟5和6會變得非常明顯。因為前臺收到LGWR寫入完成的通知後,作業系統需要消耗一些時間排程Foreground/user session程式喚醒(也就是CPU排程)

  5.RAC私有網路效能差,導致LMS同步commit SCN慢


模擬迴圈提交的情景:

--建立測試表

SQL> create table scott.tb_test (id int,age int,name varchar2(20));

--手動採集報告

exec dbms_workload_repository.create_snapshot();

--模擬多次提交

SQL> begin

 for i in 1..5000000 loop

  insert into scott.tb_test values(1,10,'test');

  commit work write wait immediate; --pl/sql中如果只寫commit預設是批次提交,並不會模擬出log file sync

 end loop;

end;

/

--執行完後再次採集報告

SQL> exec dbms_workload_repository.create_snapshot();


在插入的過程中檢視等待事件:

SQL>  select inst_id 

  2  ,event 

  3  ,count(0) 

  4  from gv$session where wait_class != 'Idle' group by inst_id,event order by inst_id,count(0) desc;


   INST_ID EVENT                                                          COUNT(0)

---------- ------------------------------------------------------------ ----------

         1 log file parallel write                                               1

         1 log file sync                                                         1

         1 SQL*Net message to client                                             1

可看到 log file sync 與log file parallel write等待事件都出現了


檢視log file sync總等待次數與總等待時間:

SQL> SET LINES 200 PAGES 100 

SQL> SELECT   INST_ID

  2  ,SID

  3  ,EVENT

  4  ,TOTAL_WAITS WAITS_CNT

  5  ,TIME_WAITED

  6  ,AVERAGE_WAIT/100 "AVERAGE_WAIT(S)"

  7  ,MAX_WAIT/100 "MAX_WAIT(S)"

  8    FROM   GV$SESSION_EVENT 

  9   WHERE SID=&INPUT_SID

 10  ORDER BY TOTAL_WAITS DESC;

Enter value for input_sid: 812

old   9:  WHERE SID=&INPUT_SID

new   9:  WHERE SID=812


   INST_ID        SID EVENT                                                         WAITS_CNT TIME_WAITED AVERAGE_WAIT(S) MAX_WAIT(S)

---------- ---------- ------------------------------------------------------------ ---------- ----------- --------------- -----------

         1        812 log file sync                                                     1812509       54140           .0003          .5

         1        812 db file sequential read                                            2183         289           .0013         .13

         1        812 db file scattered read                                             1285          65           .0005         .03

         1        812 control file sequential read                                       1266           1               0           0

         1        812 SQL*Net message from client                                         918      581782          6.3375     1866.37

         1        812 SQL*Net message to client                                           918           0               0           0

         1        812 events in waitclass Other                                           179           2           .0001           0

         1        812 direct path read                                                    152           1           .0001         .01

         1        812 latch: shared pool                                                   27           0           .0001           0

         1        812 SQL*Net more data to client                                          25           0               0           0

         1        812 direct path write                                                    25           0               0           0

         1        812 Disk file operations I/O                                             16           0           .0001           0

         1        812 log file switch completion                                           16           8           .0048         .01

         1        812 Data file init write                                                 13           1           .0005           0

         1        812 local write wait                                                     13           1           .0007           0

         1        812 enq: RO - fast object reuse                                           9           2            .002         .01

         1        812 SQL*Net break/reset to client                                         9           0               0           0

         1        812 control file parallel write                                           6           0           .0004           0

         1        812 buffer busy waits                                                     4           0           .0001           0

         1        812 undo segment extension                                                3           2           .0065         .02

         1        812 db file parallel read                                                 3           1           .0027         .01

         1        812 db file single write                                                  2           0           .0004           0

         1        812 latch: cache buffers chains                                           1           0               0           0

         1        812 direct path sync                                                      1           0           .0016           0


24 rows selected.


SQL> /

Enter value for input_sid: 812

old   9:  WHERE SID=&INPUT_SID

new   9:  WHERE SID=812


   INST_ID        SID EVENT                                                         WAITS_CNT TIME_WAITED AVERAGE_WAIT(S) MAX_WAIT(S)

---------- ---------- ------------------------------------------------------------ ---------- ----------- --------------- -----------

         1        812 log file sync                                                    1825671       54541           .0003          .5

         1        812 db file sequential read                                            2183         289           .0013         .13

         1        812 db file scattered read                                             1285          65           .0005         .03

         1        812 control file sequential read                                       1266           1               0           0

         1        812 SQL*Net message from client                                         918      581782          6.3375     1866.37

         1        812 SQL*Net message to client                                           918           0               0           0

         1        812 events in waitclass Other                                           179           2           .0001           0

         1        812 direct path read                                                    152           1           .0001         .01

         1        812 latch: shared pool                                                   27           0           .0001           0

         1        812 SQL*Net more data to client                                          25           0               0           0

         1        812 direct path write                                                    25           0               0           0

         1        812 Disk file operations I/O                                             16           0           .0001           0

         1        812 log file switch completion                                           16           8           .0048         .01

         1        812 Data file init write                                                 13           1           .0005           0

         1        812 local write wait                                                     13           1           .0007           0

         1        812 enq: RO - fast object reuse                                           9           2            .002         .01

         1        812 SQL*Net break/reset to client                                         9           0               0           0

         1        812 control file parallel write                                           6           0           .0004           0

         1        812 buffer busy waits                                                     4           0           .0001           0

         1        812 undo segment extension                                                3           2           .0065         .02

         1        812 db file parallel read                                                 3           1           .0027         .01

         1        812 db file single write                                                  2           0           .0004           0

         1        812 latch: cache buffers chains                                           1           0               0           0

         1        812 direct path sync                                                      1           0           .0016           0


24 rows selected.

可看到等待次數與等待時間 一直在增長


待插入完成後,拉取awr報告與ash報告,可看到在Top 10 Foreground Events by Total Wait Time中,log file sync等待時間為908s,佔了總DB Time的71%;在Background Wait Events中,log file parallel write等待時間為554s,佔整個Background Time的53%。

檢視ash報告,再Top SQL with Top Events中可看到引起log file sync的SQL語句,檢視完整指令碼,正好是我們發出的語句

將迴圈提交改為批次提交後,重新實驗

SQL> create table scott.tb_test (id int,age int,name varchar2(20));


Table created


exec dbms_workload_repository.create_snapshot();


begin

 for i in 1..5000000 loop

  insert into scott.tb_test values(1,10,'test');

 end loop;

 commit work write wait immediate;

end;

/

exec dbms_workload_repository.create_snapshot();

拉取awr報告後,可看到log file sync只等待了一次,佔比已經降下來了。log file parallel write佔比仍比較高,這是因為我們的事務太大造成的。


注意:

 1.log file sync等待次數基本和資料庫事務數持平。log file sync等待是無法避免,但高事務量的系統容易引起大量的log file sync的等待事件。

2.平均等待時間不應高於7ms, 如果平均等待時間比較高,則說明IO有問題。

3.如果log file sync等待時間如果明顯大於log file parallel write,則可能有幾方面原因:

 1)CPU資源緊張

 2)同時提交的程式比較多

 3)遭遇Bug.

4.如果log file sync等待時間小於log file parallel write,則應該是事務比較大,在使用者commit之前LGWR已經多次寫Log Buffer到log檔案了。


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/31544156/viewspace-2218952/,如需轉載,請註明出處,否則將追究法律責任。

相關文章