技术博客 数据库、运维与工程实践笔记

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

2026-04-28Oracle / RAC / RMAN / 性能优化

一．概要：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相关的流程图：!1756815342501-391792be-68b5-4f1f-a935-170c150c1086.png

Log file sync performance>disk IO speed!1756815342574-ddfca2e7-545b-4fb1-856c-50afce9f77af.png

**大多数log file sync的等待时间其实都是花费在logfile parallel write,类似与DBWR会等待db file parallel write**其它的log file sync等待花费在调度延迟，IPC通信延迟等等!1756815342668-834a4c4f-19f2-4fce-9f80-24ad73d64624.png

  1. 前台进程对LGWR发出调用,然后到sleep状态下面看看Log file sync等待的整个流程：此时log file sync等待开始记数次调用在Unix平台是通过信号量来实现2. LGWR被唤醒,得到CPU时间片来工作LGWR发出IO请求LGWR转去sleep,并且等待log file parallel write3. 当在存储级别完成IO调用后OS唤醒LGWR进程LGWR继续去获得CPU时间片此时标记log file parallel write等待完成,Post相关信息给前台进程4. 前台进程被LGWR唤醒,前台进程得到CPU时间片并且标记log file sync等待完成通过snapper脚本来度量LGWR的速度：

    2. [html] view plaincopy

  2. ———————————————————————————
  3. SID, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH
  4. ———————————————————————————
  5. 1096, (LGWR) , STAT, messages sent , 12 , 12,
  6. 1096, (LGWR) , STAT, messages received , 10 , 10,
  7. 1096, (LGWR) , STAT, background timeouts , 1 , 1,
  8. 1096, (LGWR) , STAT, physical write total IO requests , 40, 40,
  9. 1096, (LGWR) , STAT, physical write total multi block request, 38, 38,
  10. 1096, (LGWR) , STAT, physical write total bytes, 2884608 , 2.88M,
  11. 1096, (LGWR) , STAT, calls to kcmgcs , 20 , 20,
  12. 1096, (LGWR) , STAT, redo wastage , 4548 , 4.55k,
  13. 1096, (LGWR) , STAT, redo writes , 10 , 10,
  14. 1096, (LGWR) , STAT, redo blocks written , 2817 , 2.82k,
  15. 1096, (LGWR) , STAT, redo write time , 25 , 25,
  16. 1096, (LGWR) , WAIT, LGWR wait on LNS , 1040575 , 1.04s, 104.1%, |@@@@@@@@@@|
  17. 1096, (LGWR) , WAIT, log file parallel write , 273837 , 273.84ms, 27.4%,|@@@ |
  18. 1096, (LGWR) , WAIT, events in waitclass Other , 1035172 , 1.04s , 103.5%,|@@@@@@@@@@|

    19. 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

    16. ***io_getevents是在AIO阶段log file parallel write等待事件度量Redo,commit相关的latch tuning1.redo allocation latches-故名思议,在私有现成写redo到log buffer时保护分配空间的latch2.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 sync2.log file parallel write3.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

  16. WAIT #0: nam='log file sequential read' ela= 12607 log#=0
  17. block#=1
  18. WAIT #0: nam='log file sequential read' ela= 21225 log#=1
  19. block#=1
  20. WAIT #0: nam='control file sequential read' ela= 358 file#=0
  21. WAIT #0: nam='log file single write' ela= 470 log#=0 block#=1
  22. WAIT #0: nam='log file single write' ela= 227 log#=1 block#=1

    23. 从10.2.0.3+开始如果log write等待太久,oracle将dump相关的信息：[html] view plaincopy

  23. LGWR trace file:
  24. *** 2012-06-10 11:36:06.759
  25. Warning: log write time 690ms, size 19KB
  26. *** 2012-06-10 11:37:23.778
  27. Warning: log write time 52710ms, size 0KB
  28. *** 2012-06-10 11:37:27.302
  29. Warning: log write time 3520ms, size 144KB

    30. 看下面我们某库的AWR信息：[html] view plaincopy

  30. Load Profile Per Second Per Transaction Per Exec Per Call
  31. ~~~~~~~~~~~~ ————— ————— ———- ———-
  32. Redo size: 15,875,849.0 121,482.8
  33. Logical reads: 42,403.5 324.5
  34. Block changes: 34,759.1 266.0
  35. Physical reads: 46.0 0.4
  36. Physical writes: 3,417.9 26.2
  37. User calls: 569.6 4.4
  38. Parses: 292.3 2.2
  39. Hard parses: 0.1 0.0
  40. W/A MB processed: 0.5 0.0
  41. Logons: 10.7 0.1
  42. Executes: 552.8 4.2
  43. Rollbacks: 42.9 0.3
  44. Transactions: 130.7

    45. [html] view plaincopy

  45. Top 5 Timed Foreground Events
  46. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  47. Avg
  48. wait % DB
  49. Event Waits Time(s) (ms) time Wait Class
  50. —————————— ———— ———– —— —— ———-
  51. DB CPU 37,301 76.5
  52. log file sync 1,665,900 7,732 5 15.9 Commit
  53. db file sequential read 711,221 6,614 9 13.6 User I/O
  54. buffer busy waits 366,589 440 1 .9 Concurrenc
  55. gc current multi block request 192,791 230 1 .5 Cluster

    56. 这是某库的2号节点,还不算太忙,只是由于业务类型每次写入的量都很大,log file sync等待占用DB time的16%看看后台进程等待：[html] view plaincopy

  56. Avg
  57. %Time Total Wait wait Waits % bg
  58. Event Waits -outs Time (s) (ms) /txn time
  59. ————————– ———— —– ———- ——- ——– ——
  60. db file parallel write 11,968,325 0 24,481 2 5.7 71.2
  61. log file parallel write 1,503,192 0 3,863 3 0.7 11.2

    62. *如上信息log file sync占用了DB time的16%,avg wait(5),那么LGWR等待占用的比例为多少呢？占用了平均每次相应的40%.那么这主要是因为业务原因,已经达到我们存储的IO瓶颈.*此库平均每s的吞吐量在200M左右下面看看我使用脚本lfsdiag.sql收集的部分信息：[html] view plaincopy

  62. INST_ID EVENT WAIT_TIME_MILLI WAIT_COUNT
  63. ———- —————————————- ————— ———-
  64. 1 wait for scn ack 1 4243024
  65. 1 wait for scn ack 2 728196
  66. 1 wait for scn ack 4 1133400
  67. 1 wait for scn ack 8 1157120
  68. 1 wait for scn ack 16 88333
  69. 1 wait for scn ack 32 3883
  70. 1 wait for scn ack 64 429
  71. 1 wait for scn ack 128 80
  72. 1 wait for scn ack 256 34
  73. 1 wait for scn ack 512 48
  74. 2 wait for scn ack 1 55024800
  75. 2 wait for scn ack 2 6658764
  76. 2 wait for scn ack 4 6802492
  77. 2 wait for scn ack 8 4400949
  78. 2 wait for scn ack 16 564950
  79. 2 wait for scn ack 32 21712
  80. 2 wait for scn ack 64 3190
  81. 2 wait for scn ack 128 912
  82. 2 wait for scn ack 256 390
  83. 2 wait for scn ack 512 508
  84. 1 log file sync 1 49708644
  85. 1 log file sync 2 4285471
  86. 1 log file sync 4 3929029
  87. 1 log file sync 8 2273533
  88. 1 log file sync 16 709349
  89. 1 log file sync 32 257827
  90. 1 log file sync 64 10464
  91. 1 log file sync 128 2371
  92. 1 log file sync 256 1582
  93. 1 log file sync 512 1979
  94. 1 log file sync 1024 1200
  95. 2 log file sync 1 647580137
  96. 2 log file sync 2 56421028
  97. 2 log file sync 4 42559988
  98. 2 log file sync 8 26002340
  99. 2 log file sync 16 12821558
  100. 2 log file sync 32 4429073
  101. 2 log file sync 64 229397
  102. 2 log file sync 128 42685
  103. 2 log file sync 256 22693
  104. 2 log file sync 512 23922
  105. 2 log file sync 1024 215090
  106. 1 log file switch completion 1 141
  107. 1 log file switch completion 2 27
  108. 1 log file switch completion 4 35
  109. 1 log file switch completion 8 72
  110. 1 log file switch completion 16 237
  111. 1 log file switch completion 32 453
  112. 1 log file switch completion 64 387
  113. 1 log file switch completion 128 31
  114. 2 log file switch completion 1 956
  115. 2 log file switch completion 2 508
  116. 2 log file switch completion 4 1005
  117. 2 log file switch completion 8 1858
  118. 2 log file switch completion 16 4506
  119. 2 log file switch completion 32 5569
  120. 2 log file switch completion 64 6957
  121. 2 log file switch completion 128 319
  122. 2 log file switch completion 256 24
  123. 2 log file switch completion 512 108
  124. 2 log file switch completion 1024 1
  125. 1 log file parallel write 1 56713575
  126. 1 log file parallel write 2 2952904
  127. 1 log file parallel write 4 1832942
  128. 1 log file parallel write 8 785097
  129. 1 log file parallel write 16 386755
  130. 1 log file parallel write 32 229099
  131. 1 log file parallel write 64 8552
  132. 1 log file parallel write 128 1461
  133. 1 log file parallel write 256 914
  134. 1 log file parallel write 512 231
  135. 1 log file parallel write 1024 21
  136. 1 log file parallel write 2048 3
  137. 2 log file parallel write 1 708078642
  138. 2 log file parallel write 2 31616460
  139. 2 log file parallel write 4 16087368
  140. 2 log file parallel write 8 5656461
  141. 2 log file parallel write 16 3121042
  142. 2 log file parallel write 32 1995505
  143. 2 log file parallel write 64 44298
  144. 2 log file parallel write 128 7506
  145. 2 log file parallel write 256 2582
  146. 2 log file parallel write 512 536
  147. 2 log file parallel write 1024 464
  148. 2 log file parallel write 2048 26
  149. 2 log file parallel write 4096 0
  150. 2 log file parallel write 8192 0
  151. 2 log file parallel write 16384 0
  152. 2 log file parallel write 32768 0
  153. 2 log file parallel write 65536 0
  154. 2 log file parallel write 131072 0
  155. 2 log file parallel write 262144 0
  156. 2 log file parallel write 524288 1
  157. 1 gcs log flush sync 1 4366103
  158. 1 gcs log flush sync 2 72108
  159. 1 gcs log flush sync 4 52374
  160. 1 gcs log flush sync 8 23374

    161. 100.

  161. INST_ID EVENT WAIT_TIME_MILLI WAIT_COUNT
  162. ———- —————————————- ————— ———-
  163. 1 gcs log flush sync 16 13518
  164. 1 gcs log flush sync 32 12450
  165. 1 gcs log flush sync 64 11307
  166. 1 gcs log flush sync 128 4
  167. 2 gcs log flush sync 1 9495464
  168. 2 gcs log flush sync 2 263718
  169. 2 gcs log flush sync 4 222876
  170. 2 gcs log flush sync 8 148562
  171. 2 gcs log flush sync 16 68586
  172. 2 gcs log flush sync 32 33704
  173. 2 gcs log flush sync 64 5231
  174. 2 gcs log flush sync 128 1
  175. 1 gc current block 2-way 1 30064919
  176. 1 gc current block 2-way 2 353563
  177. 1 gc current block 2-way 4 239425
  178. 1 gc current block 2-way 8 29994
  179. 1 gc current block 2-way 16 3203
  180. 1 gc current block 2-way 32 1661
  181. 1 gc current block 2-way 64 1501
  182. 1 gc current block 2-way 128 273
  183. 1 gc current block 2-way 256 153
  184. 1 gc current block 2-way 512 22
  185. 1 gc current block 2-way 1024 119
  186. 2 gc current block 2-way 1 36168617
  187. 2 gc current block 2-way 2 303236
  188. 2 gc current block 2-way 4 148934
  189. 2 gc current block 2-way 8 13304
  190. 2 gc current block 2-way 16 2140
  191. 2 gc current block 2-way 32 1635
  192. 2 gc current block 2-way 64 1114
  193. 2 gc current block 2-way 128 210
  194. 2 gc current block 2-way 256 28
  195. 2 gc current block 2-way 512 12
  196. 2 gc current block 2-way 1024 12
  197. 2 gc current block 2-way 2048 3
  198. 2 gc current block 2-way 4096 2
  199. 1 gc cr grant 2-way 1 76502000
  200. 1 gc cr grant 2-way 2 476023
  201. 1 gc cr grant 2-way 4 564802
  202. 1 gc cr grant 2-way 8 61560
  203. 1 gc cr grant 2-way 16 5657
  204. 1 gc cr grant 2-way 32 3011
  205. 1 gc cr grant 2-way 64 440
  206. 1 gc cr grant 2-way 128 217
  207. 1 gc cr grant 2-way 256 6
  208. 2 gc cr grant 2-way 1 155966394
  209. 2 gc cr grant 2-way 2 740788
  210. 2 gc cr grant 2-way 4 748834
  211. 2 gc cr grant 2-way 8 59464
  212. 2 gc cr grant 2-way 16 9889
  213. 2 gc cr grant 2-way 32 7236
  214. 2 gc cr grant 2-way 64 937
  215. 2 gc cr grant 2-way 128 463
  216. 2 gc cr grant 2-way 256 14
  217. 2 gc cr grant 2-way 512 5
  218. 2 gc cr grant 2-way 1024 10
  219. 2 gc cr grant 2-way 2048 2
  220. 2 gc cr grant 2-way 4096 4
  221. 2 gc cr grant 2-way 8192 1
  222. 1 gc buffer busy 1 34252868
  223. 1 gc buffer busy 2 18723990
  224. 1 gc buffer busy 4 9528539
  225. 1 gc buffer busy 8 4351426
  226. 1 gc buffer busy 16 3691918
  227. 1 gc buffer busy 32 755331
  228. 1 gc buffer busy 64 68712
  229. 1 gc buffer busy 128 10869
  230. 1 gc buffer busy 256 2553
  231. 1 gc buffer busy 512 337
  232. 1 gc buffer busy 1024 2933
  233. 2 gc buffer busy 1 7881434
  234. 2 gc buffer busy 2 2083189
  235. 2 gc buffer busy 4 1372486
  236. 2 gc buffer busy 8 1957290
  237. 2 gc buffer busy 16 1417604
  238. 2 gc buffer busy 32 448992
  239. 2 gc buffer busy 64 544446
  240. 2 gc buffer busy 128 202888
  241. 2 gc buffer busy 256 58584
  242. 2 gc buffer busy 512 16470
  243. 2 gc buffer busy 1024 91266
  244. 2 gc buffer busy 2048 14
  245. 1 LGWR wait for redo copy 1 278115
  246. 1 LGWR wait for redo copy 2 3698
  247. 1 LGWR wait for redo copy 4 8498
  248. 1 LGWR wait for redo copy 8 220
  249. 1 LGWR wait for redo copy 16 6
  250. 1 LGWR wait for redo copy 32 1
  251. 2 LGWR wait for redo copy 1 7935371
  252. 2 LGWR wait for redo copy 2 29915
  253. 2 LGWR wait for redo copy 4 58179
  254. 2 LGWR wait for redo copy 8 2472
  255. 2 LGWR wait for redo copy 16 204
  256. 2 LGWR wait for redo copy 32 47

    257. 此信息主要来自于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_logging10g 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;

    5. 对于这种类型的存过,里面有各种update,insert,delete,每次的处理量比较大,所以我们只能去修改,分散相应的业务逻辑.是每次提交尽可能以合理的批量来做CPU方面：也有种可能是在CPU的配置上来优化,LGWR消耗大量的CPU,做法是如果LGWR等待的延迟相当严重,那么可以把LGWR调整到高优先级IO方面：如果你的存储IO存在瓶颈,那么log file parallel write事件会比较明显,所以这个调整还是从存储级别,比如采用raw device,ASM,更加快速的存储设备等等下面是如上Begin….End执行的系统的log file sync曲线,当此过程大量执行的时候,平均等待的时间有所增加,如下图：!1756815342752-1fe8d89c-a8e8-4e6c-afdd-5b86543b3c90.png

未完待续……