二、分析与方法

1、COMMIT次数过多（即图中的1-2，5-6阶段）

既然log file sync是由于commit导致的，那么commit次数过多自然会导致log file sync等待次数的增加，导致比较严重的等待。反之，如果log file sync的次数很高，但是等待的平均时间不高，则很可能是由于commit过于频繁导致的。

我们可以到数据库分析commit次数的变化量是否有突增：

--历史user commits变化情况

select * from (select snap_id,END_INTERVAL_TIME from dba_hist_snapshot order by snap_id desc) where rownum<=500;

select b.end_interval_time ,
value-lag(value,1) over(order by a.snap_id) "user commits"
from DBA_HIST_SYSSTAT a,dba_hist_snapshot b
where a.snap_id=b.snap_id and a.snap_id >=&begin_snapid and a.stat_name in('user commits')

--当前内存中commits较高的语句
SELECT SYSDATE,
       SE.USERNAME,
       SE.SID,
       SE.SERIAL#,
       SE.SQL_ID,
       SE.STATUS,
       SE.MACHINE,
       SE.OSUSER,
       ROUND(ST.VALUE) "COMMIT TIMES",
       SA.SQL_TEXT
  FROM V$SESSION SE, V$SESSTAT ST, V$SQLAREA SA
 WHERE SE.SID = ST.SID
   AND ST.STATISTIC# =
       (SELECT STATISTIC# FROM V$STATNAME WHERE NAME = 'user commits')
      --AND SE.USERNAME IS NOT NULL
   AND ST.VALUE > 1000
   AND SE.SQL_ADDRESS = SA.ADDRESS
   AND SE.SQL_HASH_VALUE = SA.HASH_VALUE
 ORDER BY "COMMIT TIMES" DESC;

如果commit次数过多，则建议解决异常commit语句，考虑合并commit

2、IO性能问题（即图中的3-4阶段）

概述的最后面有说明到，可以与log file parallel write进行比较：

如果log file sync突增期间，log file parallel write也突增，则很可能是IO问题导致。可以排查这几个方面：

（1）存储端整体性能问题（这就不多解释了，通常都建议使用IO性能较好存储，而且是写性能优先）

（2）IO尖刺：如果log file parallel write的等待时间比较高，而log file sync的平均等待时间恰好在正常的I/O范围内，请注意这可能是因为I/O中存在峰值，而平均值是没法显示出来的，这种情况就可以借助等待事件直方图，或者直接看AWR、OSWatcher等来进行分析。

（3）高IO消耗sql/应用（导致IO瓶颈，自然整体效率下降）：分析服务器，是什么导致了高IO消耗。大部分数据库服务器只有数据库，所以一般情况下都是SQL导致的。

（4）IO争用：redolog和其他文件防止一起，存在IO争用。此时就建议将online redo log分离出来，放到独立的磁盘上。

--iowait 检查log file sync、log file parallel write以及各类等待事件的耗时

with t as (
select s.snap_id,
s.instance_number,
s.end_interval_time,
total_waits - lag(total_waits, 1) over(partition by s.instance_number order by s.snap_id) waits,
(time_waited_micro - lag(time_waited_micro, 1) over(partition by s.instance_number order by s.snap_id)) / 1000 twt
from dba_hist_system_event ev, dba_hist_snapshot s
where ev.instance_number = s.instance_number
and ev.snap_id = s.snap_id
and event_name = 'log file sync'    --带入所需的等待事件名
and s.end_interval_time BETWEEN sysdate - 3 AND sysdate)
select to_char(end_interval_time, 'YYYYMMDD HH24:MI'),
instance_number,
sum(waits),
sum(twt),
round(sum(twt) / sum(waits), 2) wt
from t
group by to_char(end_interval_time, 'YYYYMMDD HH24:MI'), instance_number
order by 1, instance_number;

--iowait直方图 检查各类等待事件在对应毫秒区间的触发次数

select b.end_interval_time,
sum(decode(a.wait_time_milli,1,a.wait_count,null))-sum(decode(c.wait_time_milli,1,c.wait_count,null)) wait_time_milli_1,
sum(decode(a.wait_time_milli,2,a.wait_count,null))-sum(decode(c.wait_time_milli,2,c.wait_count,null)) wait_time_milli_2,
sum(decode(a.wait_time_milli,4,a.wait_count,null))-sum(decode(c.wait_time_milli,4,c.wait_count,null)) wait_time_milli_4,
sum(decode(a.wait_time_milli,8,a.wait_count,null))-sum(decode(c.wait_time_milli,8,c.wait_count,null)) wait_time_milli_8,
sum(decode(a.wait_time_milli,16,a.wait_count,null))-sum(decode(c.wait_time_milli,16,c.wait_count,null)) wait_time_milli_16,
sum(decode(a.wait_time_milli,32,a.wait_count,null))-sum(decode(c.wait_time_milli,32,c.wait_count,null)) wait_time_milli_32,
sum(decode(a.wait_time_milli,64,a.wait_count,null))-sum(decode(c.wait_time_milli,64,c.wait_count,null)) wait_time_milli_64,
sum(decode(a.wait_time_milli,128,a.wait_count,null))-sum(decode(c.wait_time_milli,128,c.wait_count,null)) wait_time_milli_128,
sum(decode(a.wait_time_milli,256,a.wait_count,null))-sum(decode(c.wait_time_milli,256,c.wait_count,null)) wait_time_milli_256,
sum(decode(a.wait_time_milli,512,a.wait_count,null))-sum(decode(c.wait_time_milli,512,c.wait_count,null)) wait_time_milli_512,
sum(decode(a.wait_time_milli,1024,a.wait_count,null))-sum(decode(c.wait_time_milli,1024,c.wait_count,null)) wait_time_milli_1024,
sum(decode(a.wait_time_milli,2048,a.wait_count,null))-sum(decode(c.wait_time_milli,2048,c.wait_count,null)) wait_time_milli_2048,
sum(decode(a.wait_time_milli,4096,a.wait_count,null))-sum(decode(c.wait_time_milli,4096,c.wait_count,null)) wait_time_milli_4096,
sum(decode(a.wait_time_milli,8192,a.wait_count,null))-sum(decode(c.wait_time_milli,8192,c.wait_count,null)) wait_time_milli_8192
from dba_hist_event_histogram a ,dba_hist_snapshot b,dba_hist_event_histogram c
where a.event_name='log file sync' and a.snap_id=b.snap_id        --带入所需的等待事件名
and b.end_interval_time BETWEEN sysdate - 3 AND sysdate
and a.snap_id=c.snap_id + 1
and a.wait_time_milli=c.wait_time_milli
and a.event_name=c.event_name
group by b.end_interval_time
order by end_interval_time desc;
 
 
 

3、日志/日志量问题（全面阶段）

（1）redo log 大小/组数量不合理，一般伴随着各类log file switch等待

（2）异常SQL语句导致了大量的日志生成：

日志量激增，导致日志频繁切换（一般同样伴随着各类log file switch等待）。而日志切换期间无法写日志，又阻塞commit引起的日志写，所以之前的1,2步变慢。

日志切换期间lgwr要做更多的工作，比如通知arch进行归档，从控制文件中找出新日志组，打开新的日志组，在新日志组中写入初始化信息等等，导致3-5步变慢，总体自然更慢

4、log buffer问题（全面阶段）

log buffer不足：

（1）前台进程需要等待lgwr释放log buffer才能继续分配。

（2）log buffer较小也会导致频繁的日志写操作

5、隐含参数问题（lgwr工作机制问题）

ORACLE从11gR2开始，为lgwr写日志引入了polling机制，而在以前只有post/wait机制。【官方文档说明请参考：Adaptive Log File Sync Optimization (Doc ID 1541136.1)】
同时引入了一个隐含参数，“_use_adaptive_log_file_sync”即通过定义该参数来确定使用哪个机制。
在11.2.0.3以下，该参数的默认值为false，即只启用post/wait机制。
从11.2.0.3开始，该参数的默认值为true，即ORACLE会在post/wait和polling机制之间自适应切换。
Post/wait机制下：lgwr执行写入操作完成后，会立刻通知前台进程已经写入完成，因此log file sync等待时间短，但lgwr/cpu的负担会稍重一点。
Polling机制下：lgwr执行写入操作完成后，不再通知前台进程已经写入完成。而前台进程会sleep并timeout后去检查log buffer中的内容是否被写入了磁盘。该机制下，解放了一部分lgwr的工作，并节约CPU资源，但是会导致待commit的进程较长时间处于log file sync等待下。

查看隐含参数值：

select a.ksppinm name,b.ksppstvl value, a.ksppdesc description from x$ksppi a, x$ksppcv b where a.indx = b.indx and a.ksppinm in ('_use_adaptive_log_file_sync');

--我们可以在lgwr进程的trace文件中看到一些切换记录：

cd $ORACLE_BASE/diag/rdbms/$DB_UNIQUE_NAME/$ORACLE_SID/trace

ls -ltr | grep lgwr

egrep -i "polling|post" bspdb_lgwr_29068.trc

Log file sync switching to polling 或者 Log file sync switching to post/wait 

建议：在11.2.0.3.0以及后续的版本上，调整该参数，设置为false：

alter system set "_use_adaptive_log_file_sync"=false;

6、CPU问题

在网上甚至不少书里，都把log file sync等待的责任推到IO问题上。在大多数情况下，这样的推断是没有问题的，不过并不能一概而论。从一开始官方文档以及我们分析得出的6个阶段和图表来看，log file sync也是很依赖CPU资源的。这里为了证明这个理论，再次引用上面举例出来官方文档的那句话“The surplus time is CPU activity and is most commonly contention caused by over committing.”

个人认为这句话最重要的并不是后面那段“大部分是由于过量commit导致的”。而应该是前面那一句“（排除IO消耗的时间后，log file sync等待的）剩余时间是CPU的动作”。这就表明了CPU也是造成log file sync慢的一个重要原因，只不过commit次数太多在这种场景下比较显眼而已。

（1）CPU资源瓶颈：比如load average较高（top命令），CPU使用率较高（top命令）、CPU运行队列过长（vmstat命令）。导致了进程间的通信、调度延迟。

检查导致CPU瓶颈的原因，到底是硬件问题，还是业务（大部分情况下应该都是SQL）导致。然后根据结论反馈问题给对应的人员进行处理（硬件厂商/应用研发）

（2）lgwr优先级不够：_high_priority_processes隐含参数，或者$ORACLE_HOME/bin/oradism文件属主和权限异常（一般是由于root.sh未执行/执行出错），都会影响lgwr进程是否可以运行在高优先级。

正确权限/属主为：

cnsz17pl7300:fina > ls -l $ORACLE_HOME/bin/oradism
-rwsr-x--- 1 root oinstall 71758 Sep 17 2011 /dba/oracle/product/11.2.0.3.15/bin/oradism

7、其他场景/优化

（1）参数commit_logging：了解即可，极不推荐修改。类似mysql的双1模式。

（2）BUG，略。。。

三、实际案例

1、问题排查

值班期间收到告警：bspdb库很多行锁等待enq: TX - row lock contention
但是检查发现，很多行锁等待确实有问题。但是更为严重的是log file sync。

20:27:03 sf01396777@bspdb> @event

EVENT                                                                     COUNT(*)

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

SQL*Net message from client                                         1520

log file sync                                                                       235

rdbms ipc message                                                             29

enq: TX - row lock contention                                            19

发现异常等待事件中，大量都在等待log file parallel write和log file sync
检查iowait、log_buffer、redolog和commit次数发现：log file sync并非是由于io性能导致的，而是CPU问题，而CPU调度可以细化下去，大致分为几项：

（1）commit频率过量

检查高频commit的语句，反馈研发整改。

（2）cpu资源瓶颈

检查cpu使用率：平均20%，高峰期40%

cpu运行队列：平均30，高峰期150

高消耗SQL：略。。。

（3）lgwr进程优先级问题

检查操作系统与数据库参数（若变更则影响较大，风险较高，方案待定）

（4）隐含参数导致进程调度模式变化有关系：_use_adaptive_log_file_sync

lgwr模式之间的切换会记录到lgwr进程的trace当中，如下所示。
cnsz17pl1323:bspdb > pwd
/dba/oracle/diag/rdbms/bspdb/bspdb/trace
cnsz17pl1323:bspdb > ls -ltr | grep lgwr
-rw-r----- 1 oracle oinstall   160284 Aug 10 20:49 bspdb_lgwr_29068.trm
-rw-r----- 1 oracle oinstall   804848 Aug 10 20:49 bspdb_lgwr_29068.trc
cnsz17pl1323:bspdb > 
cnsz17pl1323:bspdb > 
cnsz17pl1323:bspdb > egrep -i "polling|post" bspdb_lgwr_29068.trc
kcrfw_update_adaptive_sync_mode: post->poll long#=3177 sync#=25097 sync=5553 poll=2150 rw=1075 rw+=4192 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=7675 switch_sync_count_delta=25097
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=2507 sync#=14491 sync=5983 poll=2904 rw=1452 rw+=1452 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=6632 switch_sync_count_delta=14491
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=3190 sync#=23329 sync=6219 poll=4098 rw=2049 rw+=2049 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=10829 switch_sync_count_delta=23329
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=1804 sync#=4233 sync=149590 poll=34934 rw=17467 rw+=17472 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=1805 switch_sync_count_delta=4233
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=4891 sync#=33191 sync=4212 poll=3712 rw=1856 rw+=1856 ack=0 min_sleep=1073

查看隐含参数：
SQL> select a.ksppinm name,b.ksppstvl value, a.ksppdesc description from x$ksppi a, x$ksppcv b where a.indx = b.indx and a.ksppinm in ('_use_adaptive_log_file_sync');

NAME                                                                                                            VALUE                    DESCRIPTION
-------------------------------------------------------------------------------- -------------------- ------------------------------------------------------------
_use_adaptive_log_file_sync                                                                          TRUE                      Adaptively switch between post/wait and polling

log file parallel write耗时：单位毫秒

log file sync耗时：单位毫秒

commit次数：

user calls/(user commits + user rollbacks) 比较低，说明commit频率占用户调用次数比重较高

2、优化建议

（1）反馈高频commit语句与高消耗SQL（包括cpu和日志量）语句到研发整改优化

（2）调整_use_adaptive_log_file_sync参数为false。

（3）待隐含参数效果明确后，逐步下发到所有oracle 11.2.0.3.0 及以上版本的数据库中，减少log file sync等待对性能的影响。

（4）调整新建库标准手册/自动化任务，将该隐含参数默认调整为false，做到从数据库规范初始化与交付工作中就提前预防这类问题。

由于该库重要程度很高，随即找一个log file sync也比较高，但即将下线且重要性不太高的库进行变更操作：

2020-09-10 10:30对 fina 库进行变更：alter system set "_use_adaptive_log_file_sync"=false;

3、变更完成后复查

log file sync等待耗时：单位毫秒

log file sync等待出现次数：

调整完成后的结果如下：

根据优化前后的性能对比，以及稳定性来看。该参数效果显著且稳定，可逐步调整到log file sync压力比较大的库中并调整标准化建库手册/自动化任务。

4、后续

fina库调整后效果显著且稳定，随即对bspdb库也进行隐含参数优化。

不过得到的效果并没有fina库那么显著，提升只在5%-10%之间。虽然效果没有预期的大，但也证明这个操作是有一定效果的。不过这个系统整理压力较大，并非是一个简单参数就能做到优化成功的，还需要配合业务SQL调整优化。