什么是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峰值

alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';select BEGIN_TIME,END_TIME,METRIC_NAME,metric_unit,maxvalfrom DBA_HIST_SYSMETRIC_SUMMARYwhere METRIC_NAME in ('User Commits Per Sec') and instance_number=1 and begin_time between timestamp '2021-02-20 20:29:00' and timestamp '2021-02-20 20:31:00'order by BEGIN_TIME,METRIC_NAME;

3 查看用户的提交次数

SELECT sid, value
FROM   v$sesstat
WHERE  statistic# = (SELECT statistic# FROM   v$statname WHERE  name = 'user commits')
ORDER  BY value DESC;

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

set linesize 200 pagesize 200
col execount for 99999999
col BEGIN_INTERVAL_TIME for a30
col PARSING_SCHEMA_NAME for a10
col LOGCIAL_READ_PER_EXEC for 99999999999
col ELAPSED_TIME_DELTA for 999999999999
select c.* from
(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'),
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,
trunc(a.CPU_TIME_DELTA/a.EXECUTIONS_DELTA) cpu_per_exec,EXECUTIONS_DELTA execount
from DBA_HIST_SQLSTAT a,DBA_HIST_SNAPSHOT  b
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
where rownum <= 10 ;

IO问题导致:

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

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

查询lgwr进程写等待

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

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

#wait_time_milli 为毫秒
set pagesize 20
set linesize 400
select event, wait_time_milli,wait_count,last_update_time
from v$event_histogramwhere event = 'log file parallel write'
;

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

select b.BEGIN_INTERVAL_TIME,b.END_INTERVAL_TIME,a.event_name, a.wait_time_milli,a.wait_count
from DBA_HIST_EVENT_HISTOGRAM a, dba_hist_snapshot  b
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'
order by BEGIN_INTERVAL_TIME,wait_time_milli
;

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

LINUX查看命令

io使用情况;io -dmx 1或者iotop
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参数分析:

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

Log file sync 堵塞分析:

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

查询log file sync 的堵塞源。

---通过内存ash视图获取
set linesize 400
set pagesize 20
col sample_time for a40
col program for a30
col event for a30
SELECT sample_time,program,sql_id,session_id,session_serial#,event,blocking_session,BLOCKING_SESSION_SERIAL#,p1,p2,p3
FROM V$ACTIVE_SESSION_HISTORY
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%'
order by sample_time;
---通过历史ash视图获取
set linesize 300
col sample_time for a30
select sample_time,session_id,session_serial#,blocking_session,blocking_session_serial#,instance_number,SESSION_TYPE,SESSION_state
FROM DBA_HIST_ACTIVE_SESS_HISTORY
where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')
and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')
and event like '%log file sync%'
and rownum<200
order by sample_time;

查看堵塞会话信息。

---通过内存ash视图获取
set linesize 400
set pagesize 20
col sample_time for a40
col program for a30
col event for a30
SELECT sample_time,SQL_EXEC_START,sql_id,session_id,session_serial#,event,blocking_session,BLOCKING_SESSION_SERIAL#,p1,p2,p3,session_state
FROM V$ACTIVE_SESSION_HISTORY
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
order by SQL_EXEC_START;
---通过历史ash视图获取
select session_id,session_serial#,blocking_session,blocking_session_serial#,PROGRAM,MODULE,MACHINE,event
FROM DBA_HIST_ACTIVE_SESS_HISTORY
where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')and session_id=1093 and session_serial#=order by sample_time;select sample_time,session_id,session_serial#,d.sql_id,t.sql_text,blocking_session,blocking_session_serial#
FROM DBA_HIST_ACTIVE_SESS_HISTORY d,dba_hist_sqltext t
where SAMPLE_TIME > to_date('2021-03-21 00:30:00','yyyy-mm-dd hh24:mi:ss')and SAMPLE_TIME < to_date('2021-03-21 00:40:00','yyyy-mm-dd hh24:mi:ss')and session_id= and session_serial#=and d.sql_id=t.sql_id(+)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卡有问题导致的。

Oracle-log file sync等待事件分析相关推荐

oracle commit_log,Oracle log file sync 等待事件与 COMMIT_WAIT，COMMIT_LOGGING 参数说明
在Oracle 数据库中,log file sync是一个非常常见的等待事件,导致该事件的原因主要有2个因素:一是commit提交过于频繁,二是redo log 对应的IO根不上. 所以对于log f ...
生产环境 direct path read 与log file sync等待事件问题处理
1. 2018-09-26 前7天awr报告(此期间 oracle 使用率为 4,022.34/6,179.76/24=2.71%) 由此看出最显著问题是 log file sync 等待事件,查看后 ...
提交优化Oracle Tuning Log File Sync 等待事件的几种策略
发一下牢骚和主题无关: 在一个繁频 commit/rollback 或盘磁 I/O 有问题.量大物理读写争用那么.我们便会经常瞧见 LOG FILE SYNC 待等事件出现在 TOP EVE ...
log file sync(日志文件同步) 与 Log file parallel write 等待事件
log file sync(日志文件同步)等待事件具有一个参数:buffer#.在Oracle Database 10g中,这种等待事件位于Commit等待下面.当处理log file sync等待事 ...
log file sync
log file sync等待时间发生在redo log从log buffer写入到log file期间. 下面对log file sync做个详细的解释. 何时发生日志写入: 1.commit或者r ...
自适应log file sync影响案例
Oracle最吸引人的地方,就是有些答案,隐藏在种种现象之中,扑朔迷离,朦朦胧胧,就像侦探办案,首先要有思路,其次要有证据,再者就是扎实的基础知识,另外就是些运气. 例如最近碰见了一个案例,一套3节点 ...
匪夷所思：罕见的 Oracle 全局事务锁等待事件分析
数据技术嘉年华等你来活动预告:11.16-17日,北京市东三环中路61号富力万丽酒店,相聚数据技术嘉年华,(99元票务)免费购票倒计时,点击查看大会详情. 杨长老带来主题"深入内核-Ora ...
Oracle-enq: TX - row lock contention 等待事件分析
什么是enq:TX - row lock contention等待: 等待事件enq:TX - row lock contention 是Oracle常见的几大等待事件之一,在开启的事务中,为了维护事 ...
oracle的reliable message等待事件
生产环境在上线前进行了插入测试,结果最开始的结果在50000iops左右,但随后测试数据下降到10000左右. 查看awr报告发现是等待事件:reliable message. 查询文档,确认需要确认 ...

Oracle-log file sync等待事件分析

commit的过程:

commit消耗分析:

原因分析:

Oracle-log file sync等待事件分析相关推荐

最新文章

热门文章