Oracle-log file sync等待事件分析

最新推荐文章于 2024-04-26 16:31:32 发布

牛牛的笔记

最新推荐文章于 2024-04-26 16:31:32 发布

阅读量4.9k

点赞数 7

分类专栏： Oracle 文章标签： dba linux mysql oracle 性能优化

本文链接：https://blog.csdn.net/sinat_36757755/article/details/124233897

版权

Oracle 专栏收录该内容

98 篇文章 13 订阅

订阅专栏

什么是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,
  maxval
 from DBA_HIST_SYSMETRIC_SUMMARY
 where 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_histogram
 where 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.1
  adpative 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.049
  kcrfw_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.050
  Log file sync switching to polling
  Current scheduling delay is 234 usec

  Switch to post/wait:

  ***2012-10-02 08:16:23.325
  kcrfw_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/wait
  Current 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日志写进程