ANBOB™

最近一个客户的数据库出现了短暂1分钟左右的高负载，环境为oracle 11.2.0.4 2nodes RAC , 看当时的top event主要是buffer busy wait和log file sync, 关于buffer busy wait 在Troubleshooting Oracle wait event ‘buffer busy wait’ 有记录过分析方法，是一种hot block现象， 而log file sync又是提交类的，当两者同时发生时，可能是后者影响前者，首先建议排查I/O， 而另1个节点此时正在做RMAN增量备份，简单记录该问题.

ASH 报告

— Instance 2

Top User Events

Top Background Events

Top Event P1/P2/P3 Values

Top Blocking Sessions

— Instance 1

Top User Events

Top Background Events

Top Event P1/P2/P3 Values

Top Blocking Sessions

诊断脚本

当然可以使用ASH,DASH,根据sample_time或snap_id再结合blocking_session和blocking_inst_id手动递归的查等待链条，Top 1 Event并不一定是问题的根源，而是现象。

使用  Tanel’s ash_wait_chains.sql

@ash_wait_chains <grouping_cols> <filters> <fromtime> <totime>

@ash_wait_chains username||':'||program2||event2 session_type='FOREGROUND'  "to_date('20250307 13:40','yyyymmdd hh24:mi')" "to_date('20250307 13:50','yyyymmdd hh24:mi')"

@ash_wait_chains username||':'||event  1=1 "to_date('20250307 13:40','yyyymmdd hh24:mi')" "to_date('20250307 13:50','yyyymmdd hh24:mi')"

@ash_wait_chains instance_number||':'||session_id  1=1 "to_date('20250307 13:40','yyyymmdd hh24:mi')" "to_date('20250307 13:50','yyyymmdd hh24:mi')"

通过ASH

-- ASH TEMP table
create table system.ash_20250307  as
select * from gv$active_session_history 
where sample_time between to_date('20250307 13:40','yyyymmdd hh24:mi') and to_date('20250307 13:50','yyyymmdd hh24:mi'); 

-- Diag wait chains
with t as
    (select * from system.ash_20250307),
   t2 as
    (select 
	 sample_time ts
      , level lv,
            session_id,
            session_serial#,
            program,
            event,
            connect_by_iscycle iscycle,
            connect_by_isleaf leaf,
            LEVEL,
            SYS_CONNECT_BY_PATH('[' || program || ']' || '(' || nvl(event, session_state) || ')','->') wait_chain
       from t
     connect by NOCYCLE prior blocking_session = session_id
            and prior blocking_session_serial# = session_serial#
			and prior blocking_inst_id = inst_id
            and prior to_char(sample_time, 'hh24miss') =
                 to_char(sample_time, 'hh24miss')
      start with session_state = 'WAITING')
   select wait_chain, count(*), max(iscycle) iscycle, TO_CHAR(MIN(ts), 'YYYY-MM-DD HH24:MI:SS') first_seen
      , TO_CHAR(MAX(ts), 'YYYY-MM-DD HH24:MI:SS') last_seen
     from t2
    where leaf = 1   AND LV > 1
    group by wait_chain
    order by count(*) desc;

Note:

返回的堵塞链条

->[proc1#SRV31](buffer busy waits)->[proc1#SRV21](buffer busy waits)->[proc2#svr31](log file sync)->[oracle@anbob2 (LGWR)](enq: CF – contention)->[rman@anbob1 (TNS V1-V3)](ON CPU)

目前可以看到最终是有RMAN进程备份时，持有的Control File 队列,堵塞了另一个节点的BG进程LGWR，又导致提前的FG进程logfile sync，和未提交FG进程的buffer busy waits。

buffer busy waits
   ===>
      log file sync
                  ===>
                     enq: CF - contention [lgwr]
                                         ===>
                                             RMAN

网上一个案例,因为应用调用sequence比较多，TOP 1 是enq: SQ – contention, 可能给人的错觉是seq出了问题，比如cache不足等，但那不是问题的根源。

@dash_wait_chains username||':'||event  1=1 1596 1596

%This     SECONDS WAIT_CHAIN
------ ---------- ----------------------------------------------------------------------------------------------------------------------------------------------------
  70%   105023520 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   9%    13698720 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read

另一案例

SQL> select * from (
2  with sf_sql as
3   (select distinct sql_id, plan_hash_value from v$sql_plan where operation = 'TEMP TABLE TRANSFORMATION'
4    union
5    select distinct sql_id, plan_hash_value from dba_hist_sql_plan where operation = 'TEMP TABLE TRANSFORMATION')
6  select PROGRAM, EVENT, ash.sql_id, nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities') AS CF_ENQUEUE_REASON, count(*)
7    from v$active_session_history ash, sf_sql p
8   where EVENT in ('enq: CF - contention',
9                   'control file sequential read')
10     and SESSION_STATE = 'WAITING'
11     and ash.SQL_ID = p.sql_id(+)
12     and ash.SQL_PLAN_HASH_VALUE = p.plan_hash_value(+)
13   group by PROGRAM, EVENT, ash.sql_id, nvl2(p.sql_id, 'TEMP TABLE TRANSFORMATION', 'Other CF activities')
14   order by count(*) desc
15  ) where rownum <= 5
16  /
 
PROGRAM                                          EVENT                         SQL_ID        CF_ENQUEUE_REASON           COUNT(*)
------------------------------------------------ ----------------------------- ------------- ------------------------- ----------
JDBC Thin Client                                 enq: CF - contention          0cufxa3h8bp1b TEMP TABLE TRANSFORMATION       1132
JDBC Thin Client                                 enq: CF - contention          60tftk50vu96h TEMP TABLE TRANSFORMATION        266

检查control file sequential read等待分布

@event_hist  control.*read session_id=1262 1596 1596
                                 Wait time    Num ASH   Estimated    Estimated    % Event  Estimated
Wait Event                      bucket ms+    Samples Total Waits    Total Sec       Time  Time Graph
------------------------------ ----------- ---------- ----------- ------------ ---------- ------------
control file sequential read           < 1         17     66149.3         66.1       88.3 |######### |
                                      < 16          2       171.8          2.7        3.6 |          |
                                      < 32          3       128.2          4.1        5.5 |#         |
                                     < 128          1        15.6          2.0        2.7 |          |

关于 ‘enq: CF – contention’的等待可以去我另1个之前另一篇《 Troubleshooting performance event ‘enq: CF – contention’》，CF lock通常发生在：

— checkpointing
— switching logfiles
— archiving redologs
— performing crash recovery
— logfile manipulation
— begin/end hot backup
— DML access for NOLOGGING objects

持有CF lock的常见进程

SQL> select p.program, s.event
 from v$lock l, v$session s, v$process p
 where l.sid = s.sid
 and s.paddr = p.addr
 and l.type='CF'
 and l.lmode >= 5;
 
oracle@hostname.ru (CKPT)    control file sequential read
oracle@hostname.ru (ARC2)    control file sequential read
oracle@hostname.ru (LGWR)    control file sequential read

这个案例继续可以排查control file 大小，和当时的备份进程状态，如是否因为RMAN备份磁带问题而挂起，是否当时ASM层有问题? 是否控制文件读取较慢，尝试asmcmd cp CF文件。

打赏

微信扫一扫，打赏作者吧～