Oracle 12c升级后AWR里log file sync平均等待从400微秒飙到了20毫秒以上这是什么概念一个每秒有几百次commit的库相当于每笔提交都被硬生生拉长了五六十倍应用侧最先感知到的就是批处理超时和间歇性卡顿。我最近排查了这样一个案例折腾了大半天最后发现主角是12c里一个不太起眼的机制Adaptive Scalable Log WriterASLW。这篇文章就把完整过程、背后原理和最终处理方式全部记录下来希望能帮到正在被同类问题困扰的DBA。这套排障思路适合所有升级到12.1.0.2之后遇到log file sync异常升高的环境尤其是那些负载不高、磁盘IO看起来很健康、却莫名变慢的场景。读完你会明白为什么IO正常但提交很慢如何确认是不是ASLW在捣乱以及什么情况下关闭它才是合理的决定。1. 现象升级后log file sync从数百微秒涨到二十多毫秒1.1 业务侧最先感知到的异常当时某客户的一套生产库从11.2升级到12.1.0.2升级当周反馈还算平稳第二周进入正常业务周期后才出了问题。监控告警里最先亮起来的是log file sync等待时间AWR报告里它的平均等待到了23毫秒等待时间占比一度进入Top 3。业务侧的反应更直接一个高频提交的更新模块频繁出现超时批处理作业的耗时长了几倍。这个库的负载其实不算夸张用户提交数大概每秒100多次redo生成量也就在5MB/s左右。按照经验这个体量在11g时代log file sync平均等待一般只有几百微秒到1毫秒。同一套硬件、同一个应用升级后出现20倍以上的劣化直觉告诉我问题大概率不是业务量变化而是某个底层行为被改变了。第一次看到log file sync长期处于20毫秒以上时我的第一反应是怀疑提交频率是不是被开发改过了或者日志盘IO是不是出现问题了。于是按部就班地做了第一轮排查结果大部分常规嫌疑都被排除了。1.2 常规嫌疑对象被逐一排除排查的第一步是看commit量。对比升级前后一周的AWR基线user commits从每秒90次涨到120次左右涨幅约30%但绝对值依然很低。这点提交量连一个普通的OLTP库都算不上不足以解释20倍的等待增长。再看redo生成量升级前后都在4到6MB/s之间没有明显变化。第二步查IO。日志文件所在文件系统的IO延迟、设备利用率都在正常范围也没有出现队列堆积。我特意跑了log file parallel write事件平均等待在3到4毫秒这个值对机械盘和SSD混用的环境来说算正常。如果磁盘真的成了瓶颈log file parallel write的数字会非常难看但这里没有。第三步看日志切换频率和归档状态。redo log有4组每组500MB切换间隔均匀不存在频繁切换导致的额外开销。最后确认了这套库是单实例不存在RAC下log file sync伴随gc cr事件的干扰。到这里我基本确定写盘硬件没有瓶颈提交量没暴增归档也正常。那么问题只能出在LGWR写日志的路径本身。当时我顺手看了一眼后台进程就是这一眼整个过程立刻有了方向。1.3 关键线索后台进程列表里多了LGW0、LGW1用操作系统命令查看数据库后台进程时我注意到进程列表里除了熟悉的LGWR还多了LGW0和LGW1两个进程。11g时代这套库从来没有出现过这类进程它们是12c才有的东西属于Adaptive Scalable Log Writer机制下的辅助写日志进程。到这一步方向基本锁定了。ASLW设计的初衷是解决单LGWR进程的写吞吐瓶颈但在某些负载模型下它引入的协调开销远大于并行写入的收益最终会表现为log file sync等待大幅上升。接下来要搞清楚的是它到底怎么工作、为什么会影响提交确认以及怎样用数据坐实这个判断。2. Adaptive Scalable Log Writer的作用机制与潜在代价2.1 从单LGWR到可扩展写进程先简单回顾一下11g的日志写入模型。传统架构里LGWR是唯一负责把redo日志写入联机日志文件的进程所有session提交后都要等它把数据写盘。这个模型很清晰但当redo生成量极大时单进程的写带宽会成为瓶颈。就像一个快递站只有一个分拣员货量大到一定程度再快的分拣员也扛不住。Oracle在12c引入了Adaptive Scalable Log Writer核心思路是允许LGWR启用额外的辅助进程LGWn让多个进程同时写日志文件从而提升redo写入吞吐。adaptive体现在它会根据LGWR的负载情况来决定是否启用、启用几个辅助进程。这套机制在官方文档里被描述为12c的可扩展性增强算法会自动调整不需要人工干预。实际上从实现来看LGWR仍然扮演总协调者角色负责SCN分配、提交仲裁、文件切换这些核心职责LGWn辅助进程则分担特定日志文件的写入任务。多组redo log存在时理论上可以由LGWR写一组、LGWn写另一组形成并行写盘。这听起来很美但任何并行机制都有代价。2.2 并行写带来的协调成本并行写带来的第一个问题就是协调。多个进程同时写不同的日志文件时Oracle必须保证写入顺序、文件状态、SCN推进都不会错乱。LGWR和LGWn之间要通过共享内存结构做同步每一次提交相关的写操作都要经过额外的通知和确认环节。我用一个生活化的类比来理解这件事一个人坐电梯按完按钮直接走如果电梯里有一个调度员每次按按钮都要和调度员对讲确认一遍虽然调度员理论上能帮忙提高运量但楼层不高、人不多的时候这个确认动作本身就是最大的延迟来源。ASLW在高负载写场景下收益明显但负载不够高时辅助进程只是增加协同开销。更麻烦的是log file sync等待背后是提交后的确认链路。一个session执行commit需要等LGWR及其辅助进程完成相关的写入任务然后post这个session。链路里每多一个协调环节这次提交的等待时间就多一分。如果并行写带来的吞吐提升并不能覆盖协调开销那log file sync就会出现反常增长。2.3 为什么IO没变差log file sync却暴涨当时最让我困惑的地方在于磁盘本身不慢log file parallel write这个代表写盘等待的事件也很正常为什么偏偏log file sync慢到离谱后来仔细对比AWR里的两个等待事件才理清其中的逻辑。log file parallel write统计的是LGWR写redo日志时实际等待IO的部分而log file sync统计的是session从发出commit到确认完成的全过程包括LGWR获得提交请求、调度写入、等待写入完成、再post到session这一整条路径。换句话说前者只反映写盘这一个环节后者反映的是整条提交链路。当ASLW介入后写盘动作本身没有变慢但LGWR和辅助进程之间的调度、同步、确认流程多出来了。于是出现了一个非常有诊断价值的背离现象log file parallel write依然在3到4毫秒log file sync却涨到了23毫秒。正常环境下这两个等待的量级通常是接近的一旦出现数倍甚至数十倍的差距就该怀疑日志写路径本身发生了结构性变化而不是IO硬件问题。指标升级前正常期ASLW受影响期log file sync 平均等待0.4ms23mslog file parallel write 平均等待3.1ms3.6msuser commits/秒90120redo生成量5MB/s5.5MB/s这张表基本就是当时现场的真实数字。log file parallel write几乎没动log file sync出现几十倍跳升再结合LGW0/LGW1进程的存在整个问题的指向已经非常清晰了。3. 定位根因的完整排查链路3.1 用AWR与动态性能视图锁定等待特征如果你也遇到了类似的情况我建议先不要急着改参数按下面这个链路把数据取全确认问题真的是ASLW引起的。第一步从AWR历史快照里对比升级前后的等待事件。可以直接查dba_hist_system_event把log file sync和log file parallel write两个事件的时间点拉出来对比。一条SQL就能看出趋势select to_char(s.begin_interval_time, yyyy-mm-dd hh24) as snap_time, e.event, round(e.average_wait) as avg_wait_ms from dba_hist_system_event e join dba_hist_snapshot s on e.snap_id s.snap_id and e.instance_number s.instance_number where e.event in (log file sync, log file parallel write) and s.begin_interval_time date 2024-01-01 order by snap_time;重点看两个数字的比例关系。如果log file sync明显走高而log file parallel write平稳就是典型的提交链路变长不是磁盘变慢。这个判别法在绝大多数环境下都适用比单纯的绝对值判断可靠得多。第二步算一下commit频率和redo生成量的比值。可以用user commits和redo size两个统计项做粗算。如果每秒redo生成量不大、提交次数也不高说明负载没有本质变化问题出在路径上而非工作量上。3.2 确认LGWn辅助进程的存在第三步检查后台进程列表。最简单的方式是查看操作系统的进程ps -ef | grep -E LGWR|LGW0|LGW1如果出现了LGW0、LGW1之类的进程说明ASLW已经在工作状态。在数据库里面也可以查v$process视图确认辅助进程的spid与操作系统进程对应select pid, spid, program, pname from v$process where pname like LGW% or program like %LGW%;正常情况下你会看到类似LGW0、LGW1的记录pname列标注了进程角色。出现这些记录就意味着这个实例已经激活了可扩展日志写机制而不仅仅停留在配置层面。3.3 对照隐含参数与历史快照先复现再归因Oracle 12c里控制ASLW的开关是一个隐藏参数名称是_use_scalable_lgwr。普通show parameter查不到需要通过x$ksppi和x$ksppsv两张表看select x.ksppinm, y.ksppstvl from x$ksppi x, x$ksppsv y where x.indx y.indx and x.ksppinm like %scalable%;只要这个参数为TRUE并且进程列表里能看到LGW0/LGW1同时AWR历史数据显示升级后log file sync出现突破性增长那根因判断就基本成立了。不过这里我要特别提醒一点在生产环境动任何参数之前先去测试环境复现。当时我做的第一步是在一台同样版本、同样硬件规格的测试机上用压测脚本模拟高频commit场景观察log file sync是否同样异常。只有测试环境复现了再在生产变更窗口动手否则很容易被环境差异误导。4. 关闭ASLW的操作步骤与实测效果4.1 变更前准备备份、窗口、测试验证如果确认ASLW确实是元凶最常见的处理方式是把_use_scalable_lgwr设置为FALSE回到传统单LGWR写日志模式。但操作前必须做足准备不能直接改完就重启。先备份spfile防止改错后无法回退。这个动作虽然简单却经常被忽略create pfile/tmp/pfile_before_disable_aslw.ora from spfile;然后在测试环境跑一遍同样的压测脚本记录关闭前的log file sync平均值、TPS、Top事件占比。这个数据将作为后续对比的基线也是变更评审的依据。最后确认变更窗口处于业务低峰期并且有完整的回退方案。4.2 修改参数与重启验证确认无误后在测试环境执行参数修改。这个参数是静态参数必须写入spfile并重启实例才能生效alter system set _use_scalable_lgwrFALSE scopespfile;如果是RAC环境需要确保所有实例都重启并且全部使用同一个共享spfile避免出现一个节点关闭、另一个节点还开着辅助进程的不一致状态。重启后再查一次参数值和后台进程select x.ksppinm, y.ksppstvl from x$ksppi x, x$ksppsv y where x.indx y.indx and x.ksppinm _use_scalable_lgwr;参数显示FALSE并且v$process里再也查不到LGW0/LGW1说明已经回到传统模式。此时不要急着做结论最好等业务高峰过去拿下一个完整小时的真实负载数据再做对比。4.3 业务高峰对比等待从20ms降到1ms以内这套库在修改后的第二天进入了业务高峰我重新拉取了一个小时的AWR数据做对比效果非常明显指标关闭前关闭后log file sync 平均等待23ms0.8mslog file sync 最大等待89ms4.2mslog file parallel write 平均等待3.6ms2.4mslog file sync 占总DB Time比例12.6%1.1%应用批处理耗时42分钟9分钟这里有一点值得注意关闭ASLW之后log file parallel write等待反而小幅下降了从3.6ms降到2.4ms。这说明在低并发场景下单进程写的调度更直接IO路径反而更顺畅。redo生成量和提交次数都没有明显变化业务侧反馈批处理时间恢复正常整个问题闭环。5. 不要一见到LGWn就关适用场景与进阶建议5.1 两种负载画像的取舍标准虽然上面的案例是关闭ASLW后立刻见效但我并不建议所有人一看到LGW0就直接改参数。ASLW本身是用于解决真实瓶颈的特性关键判断标准是当前负载模型是否真的需要它。我一般用两个指标做判断。第一个是redo生成量与提交数的组合。如果每秒redo生成量很大比如几十MB甚至上百MB但user commits相对少说明场景是典型的大批量写入单LGWR可能确实存在吞吐瓶颈这时候ASLW存在价值甚至可以保留观察。反过来如果commit频率很高、redo量不大就是典型的小事务高并发场景ASLW的协调开销会放大log file sync关闭是合理的。第二个指标是log file parallel write的绝对值。如果这个值本身就很高说明磁盘写能力跟不上单LGWR被IO拖住了那问题在IO而非进程模型关闭ASLW解决不了。只有当log file parallel write不高、log file sync单独走高时ASLW才值得背锅。5.2 优先考虑补丁/升级而不是长期关闭关闭ASLW是可靠的绕行方案但不是唯一选项。Oracle 12.2及后续版本对自适应日志写机制做了不少改进包括辅助进程的启动阈值、协调频率和调度策略。如果你被困在12.1.0.2先查一下最新的补丁说明里有没有与ASLW相关的已知问题修复打补丁后重新评估可能就不需要永久关闭这个特性。如果决定长期保持FALSE记得在维护文档里注明原因避免几个月后另外一位同事看到这个非默认参数误操作把它改回去。这算是一个团队协作层面的小提醒实际踩过坑的DBA应该能体会。5.3 排障顺序和防误判习惯最后分享一下我现在的排障顺序。遇到log file sync异常第一步永远是对比log file sync和log file parallel write的比例关系判断是IO问题还是链路问题第二步看后台进程有没有LGWn第三步再结合commit频率和redo量确认负载画像。三步走完大多数情况下都能给出明确方向。这里也留个忠告关闭ASLW之后如果log file sync一点变化都没有说明之前的归因是错的不要强行坚持结论。继续去查commit频率、磁盘IO、锁事件、网络层甚至应用本身的提交逻辑。参数的改动是一次基准验证不是终点。我们团队后来形成了一条规则但凡遇到12c升级后的log file sync问题先查LGWn进程再谈其它这个习惯帮我们节省了大量时间。