理解LGWR,Log File Sync Waits以及Commit的性能问题[转] 

理解LGWR,Log File Sync Waits以及Commit的性能问题
一．概要：
1.  Commit和log filesync的工作机制
2.  为什么log file wait太久
3.   如何去度量问题出在那里呢？
二．log file sync等待的原因
1.  默认情况下我们commit一个事务是要等待logfile sync,这其中包括：
(1)User  commit(用户提交的统计信息可以通过v$sesstat来查看)
(2)DDL-这一部分主要是由于递归的事务提交所产生
(3)递归的数据字典DML操作
2. Rollbacks导致log file sync等待
   (1)Userrollbacks-用户或者由应用发出的rollback操作所致
   (2)Transactionrollbacks:1,由于一些失败的操作导致oracle内部的rollback 2.空间分配,或者ASSM相关的问题,以及用户取消的长查询,被kill掉的session等等。
下图为Commit和log file sync相关的流程图：


Log file sync performance>disk IO speed

****大多数log file sync的等待时间其实都是花费在logfile parallel write,类似与DBWR会等待db file parallel write
****其它的log file sync等待花费在调度延迟，IPC通信延迟等等

1.  前台进程对LGWR发出调用,然后到sleep状态下面看看Log file sync等待的整个流程：
此时log file sync等待开始记数
次调用在Unix平台是通过信号量来实现
2.  LGWR被唤醒,得到CPU时间片来工作
LGWR发出IO请求
LGWR转去sleep,并且等待log file parallel write
3.  当在存储级别完成IO调用后OS唤醒LGWR进程
LGWR继续去获得CPU时间片
此时标记log file parallel write等待完成,Post相关信息给前台进程
4.  前台进程被LGWR唤醒,前台进程得到CPU时间片并且标记log file sync等待完成
通过snapper脚本来度量LGWR的速度：
 
[html] view plaincopy
  1. <span style="font-family:'Comic Sans MS';">---------------------------------------------------------------------------------  
  2. SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH  
  3. ---------------------------------------------------------------------------------  
  4. 1096, (LGWR) , STAT, messages sent , 12 , 12,  
  5. 1096, (LGWR) , STAT, messages received , 10 , 10,  
  6. 1096, (LGWR) , STAT, background timeouts , 1 , 1,  
  7. 1096, (LGWR) , STAT, physical write total IO requests , 40, 40,  
  8. 1096, (LGWR) , STAT, physical write total multi block request, 38, 38,  
  9. 1096, (LGWR) , STAT, physical write total bytes, 2884608 , 2.88M,  
  10. 1096, (LGWR) , STAT, calls to kcmgcs , 20 , 20,  
  11. 1096, (LGWR) , STAT, redo wastage , 4548 , 4.55k,  
  12. 1096, (LGWR) , STAT, redo writes , 10 , 10,  
  13. 1096, (LGWR) , STAT, redo blocks written , 2817 , 2.82k,  
  14. 1096, (LGWR) , STAT, redo write time , 25 , 25,  
  15. 1096, (LGWR) , WAIT, LGWR wait on LNS , 1040575 , 1.04s, 104.1%, |@@@@@@@@@@|  
  16. 1096, (LGWR) , WAIT, log file parallel write , 273837 , 273.84ms, 27.4%,|@@@ |  
  17. 1096, (LGWR) , WAIT, events in waitclass Other , 1035172 , 1.04s , 103.5%,|@@@@@@@@@@|</span>  

 LGWR和Asynch IO 
 
 
[html] view plaincopy
  1. oracle@linux01:~$ strace -cp `pgrep -f lgwr`  
  2. Process 12457 attached - interrupt to quit  
  3. ^CProcess 12457 detached  
  4. % time seconds     usecs/call  calls     errors    syscall  
  5. ------ ----------- ----------- --------- --------- --------------  
  6. 100.00  0.010000    263        38        3          semtimedop  
  7. 0.00    0.000000    0          213                  times  
  8. 0.00    0.000000    0          8                    getrusage  
  9. 0.00    0.000000    0          701                  gettimeofday  
  10. 0.00    0.000000    0          41                   io_getevents  
  11. 0.00    0.000000    0          41                   io_submit  
  12. 0.00    0.000000    0          2                    semop  
  13. 0.00    0.000000    0          37                   semctl  
  14. ------ ----------- ----------- --------- --------- --------------  
  15. 100.00  0.010000               1081      3          total  

***io_getevents是在AIO阶段log file parallel write等待事件度量
Redo,commit相关的latch tuning
1.redo allocation latches-故名思议,在私有现成写redo到log buffer时保护分配空间的latch
2.redo copy latches-当从私有内存区域copy redo到log buffer时需要的latch直到相关redo流被copy到log buffer，,那么LGWR进程
  直到已经copy完成可以写buffers到磁盘,此时LGWR将等待LGWR wait for redo copy事件,相关的可以被调整的参数:_log_simultaneous_copies
等待事件：
1.log file sync
2.log file parallel write
3.log file single write
可以获取相关的统计信息(v$sesstat,v$sysstat)
(1.redo size 2.redo writing time 3.user commits 4 user rollbacks 5.transaction rollbacks)
下面看一个非commit问题的等待事件：log buffer space-此事件主要是由于redo log buffer太小,LGWR刷出redo导致争用,或者由于IO子系统太慢.根据很多人的经验,相对log buffer设置大一点能够缓解log file sync,这只是相对而言.如果你滴业务类型,每次commit都是比较大的写入,而且系统的整个IO已经达到存储子系统的瓶颈,那么增大log buffer将是无济于事的。根据MOS的很多文档参考,在10g中还是不建议设置次参数。
log file single write：
单块写redo IO大多数情况下仅仅用于logfile header block的读和写,其中log switch是主要的情况,当归档发生时需要update log header,所以可能是LGWR和ARCH等待此事件。
如下是log switch发生时的trace文件：
[html] view plaincopy
  1. WAIT #0: nam='log file sequential read' ela= 12607 log#=0  
  2. block#=1  
  3. WAIT #0: nam='log file sequential read' ela= 21225 log#=1  
  4. block#=1  
  5. WAIT #0: nam='control file sequential read' ela= 358 file#=0  
  6. WAIT #0: nam='log file single write' ela= 470 log#=0 block#=1  
  7. WAIT #0: nam='log file single write' ela= 227 log#=1 block#=1  

从10.2.0.3+开始如果log write等待太久,oracle将dump相关的信息：
[html] view plaincopy
  1. LGWR trace file:  
  2. *** 2012-06-10 11:36:06.759  
  3. Warning: log write time 690ms, size 19KB  
  4. *** 2012-06-10 11:37:23.778  
  5. Warning: log write time 52710ms, size 0KB  
  6. *** 2012-06-10 11:37:27.302  
  7. Warning: log write time 3520ms, size 144KB  
看下面我们某库的AWR信息：
[html] view plaincopy
  1. Load Profile              Per Second    Per Transaction   Per Exec   Per Call  
  2. ~~~~~~~~~~~~         ---------------    --------------- ---------- ----------  
  3.        Redo size:       15,875,849.0          121,482.8  
  4.    Logical reads:           42,403.5              324.5  
  5.    Block changes:           34,759.1              266.0  
  6.   Physical reads:               46.0                0.4  
  7.  Physical writes:            3,417.9               26.2  
  8.       User calls:              569.6                4.4  
  9.           Parses:              292.3                2.2  
  10.      Hard parses:                0.1                0.0  
  11. W/A MB processed:                0.5                0.0  
  12.           Logons:               10.7                0.1  
  13.         Executes:              552.8                4.2  
  14.        Rollbacks:               42.9                0.3  
  15.     Transactions:              130.7  
[html] view plaincopy
  1. Top 5 Timed Foreground Events  
  2. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  3.                                                            Avg  
  4.                                                           wait   % DB  
  5. Event                                 Waits     Time(s)   (ms)   time Wait Class  
  6. ------------------------------ ------------ ----------- ------ ------ ----------  
  7. DB CPU                                           37,301          76.5  
  8. log file sync                     1,665,900       7,732      5   15.9 Commit  
  9. db file sequential read             711,221       6,614      9   13.6 User I/O  
  10. buffer busy waits                   366,589         440      1     .9 Concurrenc  
  11. gc current multi block request      192,791         230      1     .5 Cluster  
这是某库的2号节点,还不算太忙,只是由于业务类型每次写入的量都很大,log file sync等待占用DB time的16%
看看后台进程等待：
[html] view plaincopy
  1. <span style="font-family:Comic Sans MS;">                                                             Avg  
  2.                                         %Time Total Wait    wait    Waits   % bg  
  3. Event                             Waits -outs   Time (s)    (ms)     /txn   time  
  4. -------------------------- ------------ ----- ---------- ------- -------- ------  
  5. db file parallel write       11,968,325     0     24,481       2      5.7   71.2  
  6. log file parallel write       1,503,192     0      3,863       3      0.7   11.2</span>  
***如上信息log file sync占用了DB time的16%,avg wait(5),那么LGWR等待占用的比例为多少呢？占用了平均每次相应的40%.那么这主要是因为业务原因,已经达到我们存储的IO瓶颈.
***此库平均每s的吞吐量在200M左右
下面看看我使用脚本lfsdiag.sql收集的部分信息：
[html] view plaincopy
  1.    INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT  
  2. ---------- ---------------------------------------- --------------- ----------  
  3.          1 wait for scn ack                                       1    4243024  
  4.          1 wait for scn ack                                       2     728196  
  5.          1 wait for scn ack                                       4    1133400  
  6.          1 wait for scn ack                                       8    1157120  
  7.          1 wait for scn ack                                      16      88333  
  8.          1 wait for scn ack                                      32       3883  
  9.          1 wait for scn ack                                      64        429  
  10.          1 wait for scn ack                                     128         80  
  11.          1 wait for scn ack                                     256         34  
  12.          1 wait for scn ack                                     512         48  
  13.          2 wait for scn ack                                       1   55024800  
  14.          2 wait for scn ack                                       2    6658764  
  15.          2 wait for scn ack                                       4    6802492  
  16.          2 wait for scn ack                                       8    4400949  
  17.          2 wait for scn ack                                      16     564950  
  18.          2 wait for scn ack                                      32      21712  
  19.          2 wait for scn ack                                      64       3190  
  20.          2 wait for scn ack                                     128        912  
  21.          2 wait for scn ack                                     256        390  
  22.          2 wait for scn ack                                     512        508  
  23.          1 log file sync                                          1   49708644  
  24.          1 log file sync                                          2    4285471  
  25.          1 log file sync                                          4    3929029  
  26.          1 log file sync                                          8    2273533  
  27.          1 log file sync                                         16     709349  
  28.          1 log file sync                                         32     257827  
  29.          1 log file sync                                         64      10464  
  30.          1 log file sync                                        128       2371  
  31.          1 log file sync                                        256       1582  
  32.          1 log file sync                                        512       1979  
  33.          1 log file sync                                       1024       1200  
  34.          2 log file sync                                          1  647580137  
  35.          2 log file sync                                          2   56421028  
  36.          2 log file sync                                          4   42559988  
  37.          2 log file sync                                          8   26002340  
  38.          2 log file sync                                         16   12821558  
  39.          2 log file sync                                         32    4429073  
  40.          2 log file sync                                         64     229397  
  41.          2 log file sync                                        128      42685  
  42.          2 log file sync                                        256      22693  
  43.          2 log file sync                                        512      23922  
  44.          2 log file sync                                       1024     215090  
  45.          1 log file switch completion                             1        141  
  46.          1 log file switch completion                             2         27  
  47.          1 log file switch completion                             4         35  
  48.          1 log file switch completion                             8         72  
  49.          1 log file switch completion                            16        237  
  50.          1 log file switch completion                            32        453  
  51.          1 log file switch completion                            64        387  
  52.          1 log file switch completion                           128         31  
  53.          2 log file switch completion                             1        956  
  54.          2 log file switch completion                             2        508  
  55.          2 log file switch completion                             4       1005  
  56.          2 log file switch completion                             8       1858  
  57.          2 log file switch completion                            16       4506  
  58.          2 log file switch completion                            32       5569  
  59.          2 log file switch completion                            64       6957  
  60.          2 log file switch completion                           128        319  
  61.          2 log file switch completion                           256         24  
  62.          2 log file switch completion                           512        108  
  63.          2 log file switch completion                          1024          1  
  64.          1 log file parallel write                                1   56713575  
  65.          1 log file parallel write                                2    2952904  
  66.          1 log file parallel write                                4    1832942  
  67.          1 log file parallel write                                8     785097  
  68.          1 log file parallel write                               16     386755  
  69.          1 log file parallel write                               32     229099  
  70.          1 log file parallel write                               64       8552  
  71.          1 log file parallel write                              128       1461  
  72.          1 log file parallel write                              256        914  
  73.          1 log file parallel write                              512        231  
  74.          1 log file parallel write                             1024         21  
  75.          1 log file parallel write                             2048          3  
  76.          2 log file parallel write                                1  708078642  
  77.          2 log file parallel write                                2   31616460  
  78.          2 log file parallel write                                4   16087368  
  79.          2 log file parallel write                                8    5656461  
  80.          2 log file parallel write                               16    3121042  
  81.          2 log file parallel write                               32    1995505  
  82.          2 log file parallel write                               64      44298  
  83.          2 log file parallel write                              128       7506  
  84.          2 log file parallel write                              256       2582  
  85.          2 log file parallel write                              512        536  
  86.          2 log file parallel write                             1024        464  
  87.          2 log file parallel write                             2048         26  
  88.          2 log file parallel write                             4096          0  
  89.          2 log file parallel write                             8192          0  
  90.          2 log file parallel write                            16384          0  
  91.          2 log file parallel write                            32768          0  
  92.          2 log file parallel write                            65536          0  
  93.          2 log file parallel write                           131072          0  
  94.          2 log file parallel write                           262144          0  
  95.          2 log file parallel write                           524288          1  
  96.          1 gcs log flush sync                                     1    4366103  
  97.          1 gcs log flush sync                                     2      72108  
  98.          1 gcs log flush sync                                     4      52374  
  99.          1 gcs log flush sync                                     8      23374  
  100.   
  101.    INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT  
  102. ---------- ---------------------------------------- --------------- ----------  
  103.          1 gcs log flush sync                                    16      13518  
  104.          1 gcs log flush sync                                    32      12450  
  105.          1 gcs log flush sync                                    64      11307  
  106.          1 gcs log flush sync                                   128          4  
  107.          2 gcs log flush sync                                     1    9495464  
  108.          2 gcs log flush sync                                     2     263718  
  109.          2 gcs log flush sync                                     4     222876  
  110.          2 gcs log flush sync                                     8     148562  
  111.          2 gcs log flush sync                                    16      68586  
  112.          2 gcs log flush sync                                    32      33704  
  113.          2 gcs log flush sync                                    64       5231  
  114.          2 gcs log flush sync                                   128          1  
  115.          1 gc current block 2-way                                 1   30064919  
  116.          1 gc current block 2-way                                 2     353563  
  117.          1 gc current block 2-way                                 4     239425  
  118.          1 gc current block 2-way                                 8      29994  
  119.          1 gc current block 2-way                                16       3203  
  120.          1 gc current block 2-way                                32       1661  
  121.          1 gc current block 2-way                                64       1501  
  122.          1 gc current block 2-way                               128        273  
  123.          1 gc current block 2-way                               256        153  
  124.          1 gc current block 2-way                               512         22  
  125.          1 gc current block 2-way                              1024        119  
  126.          2 gc current block 2-way                                 1   36168617  
  127.          2 gc current block 2-way                                 2     303236  
  128.          2 gc current block 2-way                                 4     148934  
  129.          2 gc current block 2-way                                 8      13304  
  130.          2 gc current block 2-way                                16       2140  
  131.          2 gc current block 2-way                                32       1635  
  132.          2 gc current block 2-way                                64       1114  
  133.          2 gc current block 2-way                               128        210  
  134.          2 gc current block 2-way                               256         28  
  135.          2 gc current block 2-way                               512         12  
  136.          2 gc current block 2-way                              1024         12  
  137.          2 gc current block 2-way                              2048          3  
  138.          2 gc current block 2-way                              4096          2  
  139.          1 gc cr grant 2-way                                      1   76502000  
  140.          1 gc cr grant 2-way                                      2     476023  
  141.          1 gc cr grant 2-way                                      4     564802  
  142.          1 gc cr grant 2-way                                      8      61560  
  143.          1 gc cr grant 2-way                                     16       5657  
  144.          1 gc cr grant 2-way                                     32       3011  
  145.          1 gc cr grant 2-way                                     64        440  
  146.          1 gc cr grant 2-way                                    128        217  
  147.          1 gc cr grant 2-way                                    256          6  
  148.          2 gc cr grant 2-way                                      1  155966394  
  149.          2 gc cr grant 2-way                                      2     740788  
  150.          2 gc cr grant 2-way                                      4     748834  
  151.          2 gc cr grant 2-way                                      8      59464  
  152.          2 gc cr grant 2-way                                     16       9889  
  153.          2 gc cr grant 2-way                                     32       7236  
  154.          2 gc cr grant 2-way                                     64        937  
  155.          2 gc cr grant 2-way                                    128        463  
  156.          2 gc cr grant 2-way                                    256         14  
  157.          2 gc cr grant 2-way                                    512          5  
  158.          2 gc cr grant 2-way                                   1024         10  
  159.          2 gc cr grant 2-way                                   2048          2  
  160.          2 gc cr grant 2-way                                   4096          4  
  161.          2 gc cr grant 2-way                                   8192          1  
  162.          1 gc buffer busy                                         1   34252868  
  163.          1 gc buffer busy                                         2   18723990  
  164.          1 gc buffer busy                                         4    9528539  
  165.          1 gc buffer busy                                         8    4351426  
  166.          1 gc buffer busy                                        16    3691918  
  167.          1 gc buffer busy                                        32     755331  
  168.          1 gc buffer busy                                        64      68712  
  169.          1 gc buffer busy                                       128      10869  
  170.          1 gc buffer busy                                       256       2553  
  171.          1 gc buffer busy                                       512        337  
  172.          1 gc buffer busy                                      1024       2933  
  173.          2 gc buffer busy                                         1    7881434  
  174.          2 gc buffer busy                                         2    2083189  
  175.          2 gc buffer busy                                         4    1372486  
  176.          2 gc buffer busy                                         8    1957290  
  177.          2 gc buffer busy                                        16    1417604  
  178.          2 gc buffer busy                                        32     448992  
  179.          2 gc buffer busy                                        64     544446  
  180.          2 gc buffer busy                                       128     202888  
  181.          2 gc buffer busy                                       256      58584  
  182.          2 gc buffer busy                                       512      16470  
  183.          2 gc buffer busy                                      1024      91266  
  184.          2 gc buffer busy                                      2048         14  
  185.          1 LGWR wait for redo copy                                1     278115  
  186.          1 LGWR wait for redo copy                                2       3698  
  187.          1 LGWR wait for redo copy                                4       8498  
  188.          1 LGWR wait for redo copy                                8        220  
  189.          1 LGWR wait for redo copy                               16          6  
  190.          1 LGWR wait for redo copy                               32          1  
  191.          2 LGWR wait for redo copy                                1    7935371  
  192.          2 LGWR wait for redo copy                                2      29915  
  193.          2 LGWR wait for redo copy                                4      58179  
  194.          2 LGWR wait for redo copy                                8       2472  
  195.          2 LGWR wait for redo copy                               16        204  
  196.          2 LGWR wait for redo copy                               32         47  
此信息主要来自于V$EVENT_HISTOGRAM,对于判断到底是什么引起的问题,有助于参考。
***Oracle有个bug：log file sync等待1s,cursor:pin s wait on x也有个bug,莫名等待10ms.
如何tuning sql log file：
对于log buffer size的大小,前面已经提到过,默认的就已经足够大了,但是从经验来看(主要是前辈们,我也尝试过,效果不太明显),所以在allocate相关latch等待,比较多的时候可以考虑增大log buffer size.9.2以后oracle使用多个log buffer,也在很大程度上缓解了相关latch等待(每个latch保护自己的buffers).10g出现新功能：private redo strand,每一个allocate latch保护自己的redo strand,也出现了IMU的概念,所以log buffer相关latch的争用已经很少出现.
下面看看相关的参数调整：
10g R1：commit_logging
10g R2：commit_write
 
Option
 
Effect
 
Wait(default)
 
Ensures that the commit returns only after the corresponding redo information is persistent in the online redo log. When the client receives a successful return from this COMMIT statement, the transaction has been committed to durable media.
A failure that occurs after a successful write to the log might prevent the success message from returning to the client, in which case the client cannot tell whether or not the transaction committed.
 
Nowait
 
The commit returns to the client whether or not the write to the redo log has completed. This behavior can increase transaction throughput.
 
Batch
 
The redo information is buffered to the redo log, along with other concurrently executing transactions. When sufficient redo information is collected, a disk write to the redo log is initiated. This behavior is called group commit, as redo information for multiple transactions is written to the log in a single I/O operation.
 
Immediate(default)
 
LGWR writes the transaction's redo information to the log. Because this operation option forces a disk I/O, it can reduce transaction throughput.
 
 
以上来自于Online Document,如果你不关心ACID的D(持久性),也就是不关心instance crash后丢失数据的风险,完全可以采用nowait,但我目前没有见过系统使用该参数,都为默认值.
可能在很多情况下,我们从单纯的DB的层面去tuning,并不能得到很好的效果,从应用层面能够得到很好的效果,但是推动应用修改代码又是一件难而又难的事情。
1.PLSQL,这包括Procedure导致的log file sync,看下面例子：
[html] view plaincopy
  1. SW_SID  STATE     SW_EVENT       SEQ#     SEC_IN_WAIT   SQL_ID        SQL_TEXT  
  2. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  3. 2962     WAITING    log file sync    60440    0         773b3nqmcvwf4    BEGIN P_MS_UPDATE_SENDTASK       (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17); END;  
  4. 2962     WAITING    log file sync    60440    0         773b3nqmcvwf4    BEGIN P_MS_UPDATE_SENDTASK(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17); END;  
对于这种类型的存过,里面有各种update,insert,delete,每次的处理量比较大,所以我们只能去修改,分散相应的业务逻辑.是每次提交尽可能以合理的批量来做
CPU方面：
也有种可能是在CPU的配置上来优化,LGWR消耗大量的CPU,做法是如果LGWR等待的延迟相当严重,那么可以把LGWR调整到高优先级
IO方面：
如果你的存储IO存在瓶颈,那么log file parallel write事件会比较明显,所以这个调整还是从存储级别,比如采用raw device,ASM,更加快速的存储设备等等
下面是如上Begin....End执行的系统的log file sync曲线,当此过程大量执行的时候,平均等待的时间有所增加,如下图：
posted @ 2013-11-14 11:32  胡.杰  阅读(1163)  评论(0)  编辑  收藏  举报