Oracle-log file sync等待事件

什么是log file sync等待事件：

当用户会话进行提交时，会话事务锁产生的全部日志都需要从log buffer 刷入到redo logfile，以保证事务对数据库的更改成为永久性。

在commit的时候，用户会话会通知lgwr进程去写log buffer(包含当前未写入的redo,会话当前的redo)到red logfile，一旦lgwr进程完成写入请求，就会通知会话已完成。而log file sync就是用户commit操作等待lgwr进程通知确认以及lgwr完成写请求所花费的时间。

在11.2以及更高版本中，LGWR可能会从默认的post/wait模式切换到轮询模式，在轮询模式下，LGWR进程会在内存结构中维护写入的进度，等待"log file sync"的会话可以定期检查这个内存结构(即poll)，以确认lgwr进程的写进度以及会话的事务是否已经写入log file，在这种情况下，等待时间将从通知lgwr进程写到lgwr进程完成写入会话当前的日志。

什么操作会产生log file sync等待？

1 commit操作

2 rollback操作

3 DDL操作（DDL操作实施前都会首先进行一次commit）

4 DDL操作导致的数据字典修改所产生的commit

5 某些能递归修改数据字典的操作：比如查询SEQ的next值，可能会导致修改数据字典。一个典型的情况是，SEQ的cache属性设置为nocache，那么会导致每次调用SEQ都要修改数据字典，产生递归的commit。

commit的过程:

1 用户进程发起commit

2 用户进程通知lgwr写日志

3 lgwr接收到请求开始写red log file ,同时rac集群会将COMMIT SCN 同步/传播给远程的数据库实例的LMS 进程。(RAC节点需要同步COMMIT SCN)

4 远程数据库实例的LMS将commit SCN同步到本地SCN，然后通知commit实例的LMS，表示SCN 同步已经完(RAC)

5 当commit 实例的LMS接收到所有远程数据库实例的LMS的通知后，commit 实例的LMS再通知本地的LGWR(RAC) 所有节点SCN同步已经完成。(RAC)

6 LGWR 在完成了IO写 操作和LMS进程通知

7 LGWR通知user session commit 成功

8 用户进程获得通知，继续做其他事

commit消耗分析:

1,2阶段的时间，主要是post/wait的时间，典型的这种post/wait一般利用的是操作系统的信号量（IPC)实现，如果系统CPU资源充足，一般不会出现大的延迟。前台进程post lgwr后，就开始等待log file sync;

3-6阶段的时间，主要是真正的物理io时间，lgwr通知os把log buffer的内容写入到磁盘，然后lgwr进入睡眠（等待log file parallel write），这个时间正常情况下的延迟占整个log file sync的大部分时间。还需要指出，lgwr在获取cpu资源后，可能并不能马上通知os写磁盘，只有在确保所有的redo copy latch都已经被释放，才能开始真正的IO操作。对应RAC集群还需要考虑集群间的网络延迟;

7,8阶段的时间，前台进程接收到lgwr的通知，返回cpu运行队列，处理其他事务（log file sync结束）。

log file sync 产生的原因:

1 commit操作 造成的log file sycn等待，某些异常的系统，比如频频rollback、seq的cache设置为nocache的系统，也可能会造成比较多的log file sycn等待。

2 log file parallel write 瓶颈，通常为磁盘IO瓶颈

3 log file sync被堵塞，如控制文件正在备份可能会堵塞日志同步写控制文件

4 log file sync受参数的影响_use_adaptive_log_file_sync, 日志写法导致的post/wait

5 集群间网络延迟，丢包

6 bug导致

原因分析:

频繁的commit导致:

分析的思路:查询数据库每秒的commit次数，确认是否存在高频率的commit以及commit次数过多的sql，分析高频率的commit是否合理以及是否是代码逻辑错误导致的。

1 通过awr获取平均的commit次数

2 通过历史视图获取最大的commit峰值

1.  
   alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';
2.  
   select
3.  
   BEGIN_TIME,
4.  
   END_TIME,
5.  
   METRIC_NAME,
6.  
   metric_unit,
7.  
   maxval
8.  
   from DBA_HIST_SYSMETRIC_SUMMARY
9.  
   where METRIC_NAME in ('User Commits Per Sec') and instance_number=1 and
10.  
    begin_time between timestamp '2021-02-20 20:29:00' and timestamp '2021-02-20 20:31:00'
11.  
    order by BEGIN_TIME,METRIC_NAME;

3 查看用户的提交次数

1.  
   SELECT sid,
2.  
   value
3.  
   FROM v$sesstat
4.  
   WHERE statistic# = (SELECT statistic#
5.  
   FROM v$statname
6.  
   WHERE name = 'user commits')
7.  
   ORDER BY value DESC;

4 查看执行次数过多的语句

1.  
   set linesize 200 pagesize 200
2.  
   col execount for 99999999
3.  
   col BEGIN_INTERVAL_TIME for a30
4.  
   col PARSING_SCHEMA_NAME for a10
5.  
   col LOGCIAL_READ_PER_EXEC for 99999999999
6.  
   col ELAPSED_TIME_DELTA for 999999999999
7.  
   select c.* from
8.  
   (select a.instance_number,a.sql_id,to_char(b.BEGIN_INTERVAL_TIME,'yyyy-mm-dd hh24:mi:ss'),to_char(b.END_INTERVAL_TIME,'yyyy-mm-dd hh24:mi:ss'),
9.  
   plan_hash_value,ELAPSED_TIME_DELTA,PARSING_SCHEMA_NAME,trunc(a.BUFFER_GETS_DELTA/a.EXECUTIONS_DELTA) logcial_read_per_exec,trunc(a.ELAPSED_TIME_DELTA/EXECUTIONS_DELTA)/1000000 elapsed_time_per_exec,
10.  
    trunc(a.CPU_TIME_DELTA/a.EXECUTIONS_DELTA) cpu_per_exec,EXECUTIONS_DELTA execount
11.  
    from DBA_HIST_SQLSTAT a,DBA_HIST_SNAPSHOT b
12.  
    where a.instance_number=b.instance_number and a.snap_id=b.snap_id and a.EXECUTIONS_DELTA>0 order by a.EXECUTIONS_DELTA desc) c
13.  
    where rownum <= 10 ;

IO问题导致:

分析思路:分析瓶颈是不是由lgwr进程导致以及lgwr进程的写速度，io是否存在瓶颈或者问题。

1 通过awr 去查看log file parallel write 的瓶颈等待，但这个值是平均值，要结合写等待的histogram直方图去分析

 查询lgwr进程写等待

1.  
   #time_waited、average_wait的单位为百分之一秒（in hundredths of a second）
2.  
   select s.event as event_name
3.  
   ,s.time_waited/100 as time_waited
4.  
   ,s.average_wait as averge_wait
5.  
   from v$system_event s
6.  
   where s.event in ('log file parallel write','log file sync');

查询lgwr进程写等待的时间直方图

1.  
   #wait_time_milli 为毫秒
2.  
   set pagesize 20
3.  
   set linesize 400
4.  
   select event, wait_time_milli,wait_count,last_update_time
5.  
   from v$event_histogram
6.  
   where event = 'log file parallel write'
7.  
   ;

查询lgwr进程写等待历史直方图

1.  
   select b.BEGIN_INTERVAL_TIME,b.END_INTERVAL_TIME,a.event_name, a.wait_time_milli,a.wait_count
2.  
   from DBA_HIST_EVENT_HISTOGRAM a, dba_hist_snapshot b
3.  
   where a.event_name = 'log file parallel write' and a.snap_id=b.snap_id and b.BEGIN_INTERVAL_TIME between timestamp '2021-04-17 17:00:00' and timestamp '2021-04-17 18:00:00'
4.  
   order by BEGIN_INTERVAL_TIME,wait_time_milli
5.  
   ;

2  通过监控去获取IO,CPU的性能情况，一般可以通过OSW去获取IO,CPU的负载情况，主要关注io队列是否已经满载以及是否存在hang住的情况。

 

LINUX查看命令

1.  
   io使用情况;io -dmx 1或者iotop
2.  
   cpu使用情况:top 再输入1 或者 mpstat -P ALL 1

3 磁盘配置建议

• 日志与数据盘分开存放，避免IO竞争

• 日志盘的raid 一般推荐1 0 或者RAID 0 

• 磁盘的IO 调度为deadline

cat /sys/block/sdb/queue/scheduler

Lgwr_trc文件分析:

分析思路:通过查看lgwr的日志内容协助分析$ORACLE_BASE/diag/rdbms/$DB_UNIQUE_NAME/$ORACLE_SID/*lgwr*.trc

1 若日志出现以下信息可能存在IO写缓慢或者大的IO写

2 若出现以下，可能是"_use_adaptive_log_file_sync"设置为true导致adpative sync会在两种方法post/wait,poll不同日志提交方法中提交，这可能产生不必要的资源消耗。

 

_use_adaptive_log_file_sync参数分析: 

1.  
   ----11.2.0.3之后
2.  
   ----参数默认设置为TRUE
3.  
   ----详情看mos 1541136.1
4.  
   adpative sync会在两种方法post/wait,poll不同日志提交方法中提交，这可能产生不必要的资源消耗
5.  
   参数可以动态调整
6.  
   ALTER SYSTEM SET "_use_adaptive_log_file_sync"= <FALSE/TRUE> scope=<both/spfile/memory>;
7.  
   ALTER SYSTEM SET "_use_adaptive_log_file_sync"= FALSE scope=both;
8.  
    
9.  
   --切换记录可以在lgrw的trace日志里面看到
10.  
    All switches are recorded in LGWR's trace file with a time stamp and the string "Log file sync switching to ...":
11.  
     
12.  
    Switch to polling:
13.  
     
14.  
    *** 2012-10-02 08:15:47.049
15.  
    kcrfw_update_adaptive_sync_mode: post->poll long#=316 sync#=1719 sync=247657
16.  
    poll=12382 rw=6191 rw =13890 ack=0 min_sleep=10023
17.  
     
18.  
     
19.  
    *** 2012-10-02 08:15:47.050
20.  
    Log file sync switching to polling
21.  
    Current scheduling delay is 234 usec
22.  
     
23.  
    Switch to post/wait:
24.  
     
25.  
    ***2012-10-02 08:16:23.325
26.  
    kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0
27.  
    switch_sched_delay=234 current_sync_count_delta=2275
28.  
    switch_sync_count_delta=1719
29.  
     
30.  
    *** 2012-10-02 08:16:23.325
31.  
     
32.  
    ---polling数据库中的记录
33.  
    select name,value from v$sysstat where name in ('redo synch poll writes','redo synch polls');
34.  
     
35.  
    Log file sync switching to post/wait
36.  
    Current approximate redo synch write rate is 758 per sec

Log file sync 堵塞分析:

分析思路:查出log file sync等待事件的堵塞源以确认堵塞的原因。

查询log file sync 的堵塞源。

1.  
   ---通过内存ash视图获取
2.  
   set linesize 400
3.  
   set pagesize 20
4.  
   col sample_time for a40
5.  
   col program for a30
6.  
   col event for a30
7.  
   SELECT sample_time,program,sql_id,session_id,session_serial#,event,blocking_session,BLOCKING_SESSION_SERIAL#,p1,p2,p3
8.  
   FROM V$ACTIVE_SESSION_HISTORY
9.  
   WHERE sample_time between timestamp '2021-03-21 00:30:00' and timestamp '2021-03-21 00:40:00' and event like '%log file sync%'
10.  
    order by sample_time;
11.  
    ---通过历史ash视图获取
12.  
    set linesize 300
13.  
    col sample_time for a30
14.  
    select sample_time,session_id,session_serial#,blocking_session,blocking_session_serial#,instance_number,SESSION_TYPE,SESSION_state
15.  
    FROM DBA_HIST_ACTIVE_SESS_HISTORY
16.  
    where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')
17.  
    and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')
18.  
    and event like '%log file sync%'
19.  
    and rownum<200
20.  
    order by sample_time;

查看堵塞会话信息。

1.  
   ---通过内存ash视图获取
2.  
   set linesize 400
3.  
   set pagesize 20
4.  
   col sample_time for a40
5.  
   col program for a30
6.  
   col event for a30
7.  
   SELECT sample_time,SQL_EXEC_START,sql_id,session_id,session_serial#,event,blocking_session,BLOCKING_SESSION_SERIAL#,p1,p2,p3,session_state
8.  
   FROM V$ACTIVE_SESSION_HISTORY
9.  
   WHERE sample_time between timestamp '2021-03-21 00:30:00' and timestamp '2021-03-21 00:40:00' and session_id=9810 and session_serial#=38334
10.  
    order by SQL_EXEC_START;
11.  
    ---通过历史ash视图获取
12.  
    select session_id,session_serial#,blocking_session,blocking_session_serial#,PROGRAM,MODULE,MACHINE,event
13.  
    FROM DBA_HIST_ACTIVE_SESS_HISTORY
14.  
    where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')
15.  
    and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')
16.  
    and session_id=1093 and session_serial#=
17.  
    order by sample_time;
18.  
     
19.  
    select sample_time,session_id,session_serial#,d.sql_id,t.sql_text,blocking_session,blocking_session_serial#
20.  
    FROM DBA_HIST_ACTIVE_SESS_HISTORY d,dba_hist_sqltext t
21.  
    where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')
22.  
    and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')
23.  
    and session_id= and session_serial#=
24.  
    and d.sql_id=t.sql_id( )
25.  
    order by sample_time;

案例分析:

问题背景:

应用反馈业务查询SQL偶尔出现操作超时。

问题分析:

在应用反馈SQL超时的时间段，数据库发生大量的log file sync等待，堵塞会话来自lgwr日志写进程

lgwr日志写进程显示状态为log file parallel write 日志写等待。

用户每秒最大commit次数为57.1,这里可以确认log file sync等待的性能瓶颈在lgwr进行写操作，不是commit过多操作。

查看存储资源使用情况(iostat)

存储cpu iowait 等待很高,asm所在的共享存储繁忙100%，磁盘读写几乎为0,磁盘疑似出现hang住的情况。

通过集群自身磁盘ping进程进一步确认，磁盘I/0出现了hang住的情况，超过8000ms。

 

问题总结:

根据业务操作超时时间追踪定位，超时期间数据库等待log file sync异常激增，造成等待的原因为磁盘IO hang住导致lgwr日志写进程等待，后续经过存储管理员分析是HBA卡有问题导致的。

这篇好文章是转载于：学新通技术网