案例: checkpoint hang等待log file switch(checkpoint incomplete) 11.2.0.4 on Solaris OS 5.11
前段时间遇到的一个案例，朋友开始给我说是数据库连接数很高，让我帮分析一下。这是一套 11.2.0.4 2nodes RAC on Sun OS 5.11环境， 问题发现已经过去几个小时， 等我到时客户反应现在连接数已经平稳，刚才看到的大多数会话等待enq: sq – contention. 相信根据这点信息，不知你是否觉的这就是一个高并发的sequence cache不足问题？当然没有这么简单。不过还了解到节点1 有问题，节点2正常。
常常我们会问题现象所迷惑，如果这已经是个病入膏肓的人，当然病因不会只是当前症状， 现在所见多数是果。先说说什么情况下会enq:sq – contention.
1. 什么是ENQ:SQ -CONTENTION
ENQ 是数据库一种队列机制，SQ 是SeQuence相关的队列， 当进程从内存中申请SEQUENCE的nextval时，如果发现内存已用完，需要从磁盘的字典表seq$ 读一批到内存的sequence cache. 当填充或初始化SEQUENCE CACHE序列缓存时需要申请该SQ Enqueue, 同时更新SEQ$基表， 这也就是为什么当时看到的SQL 是update seq$的内部递归SQL.
产生enq:sq -contention的原因有：
sequence cache过小，应用使用频繁导致Seq 对象需要频繁填充cache;
RAC 上的order sequence;
shared pool 过小导致sequence cache被刷出shared pool;
申请seq enq时间过长被其它进程堵塞等。
排查seq: sq- contention的sequence的具体对象可以从v$session 该事件的P2值得到。 P2值就是sequence 的object_id .
wait event: 'enq: SQ - contention'
p1: 'name|mode'=0x53510006
p2: 'object #'=0x16a
p3: '0'=0x0
SQL> @hex 16a
DEC HEX
----------------------------------- --------------------
362.000000 16A
SQL> select owner,object_name from dba_objects where object_id=362;
OWNER OBJECT_NAME
----- -----------
SYS AUDSES$
Note:
可以看出当时应用是在以排它方式申请sys.audses$ 序列时遇到堵塞。 该序列是会话登录时在没有禁用审计时调用。11.2的审计默认是启用的。当然会想是不是这个sequence过小，又遇到LOGON STORM呢？不是的，这个可以从listener log确认。最快的方法是找一下blocker chains (堵塞链条)。
2. 查找阻塞链条
SQL> select event,BLOCKING_SESSION,BLOCKING_INSTANCE,count(*)
from v$session
where status<>'INVALID'
group by event,BLOCKING_SESSION,BLOCKING_INSTANCE;
EVENT BLOCKING_SESSION BLOCKING_INSTANCE COUNT(*)
------------------------------ ---------------- ----------------- ---------------
VKTM Logical Idle Wait 1
gc buffer busy release 608 1 1
Streams AQ: waiting for time m 1
anagement or cleanup tasks
Space Manager: slave idle wait 1
write complete waits 871 1 1
rdbms ipc message 54
SQL*Net message to client 1
enq: SQ - contention 608 1 605
PING 1
buffer busy waits 4685 1 1
SQL*Net message from client 4
enq: SQ - contention 7382 1 7
DIAG idle wait 2
log file switch (checkpoint in 1771 1 5
complete)
...
GCR sleep 1
VKRM Idle 1
enq: SQ - contention 1
buffer busy waits 7298 1 2
26 rows selected.
SQL> select BLOCKING_SESSION,BLOCKING_INSTANCE from v$session where sid=608;
BLOCKING_SESSION BLOCKING_INSTANCE
---------------- -----------------
1771 1
SQL> select BLOCKING_SESSION,BLOCKING_INSTANCE from v$session where sid=1771;
BLOCKING_SESSION BLOCKING_INSTANCE
---------------- -----------------
Note:
block chaints: enq:SQ – contention (N个)>>> enq:SQ – contention(sid=608)>>> log file switch (checkpoint incomplete)(sid=1711 LGWR),
大部分enq:SQ – contention（600多个）会话是被sid: 608堵塞 ，608又是被sid:1771 堵塞， sid:1771是后台进程LGWR 日志写进程, 等待事件是log file switch (checkpoint incomplete)。
3. 什么是log file switch (checkpoint incomplete)
这个等待事件几年前log file switch (checkpoint incomplete) event 简单总结过， 当Oracle会话更改buffer cache中的Oracle buffer block时，它们的进程将足够的redo 信息复制到redo buffer中。 出于多种原因(3s\commit\…)，LGWR会将其redo 从redo buffer写入到联机重做日志文件中。 在线重做日志文件是串联连接写入一个接下一个创建一个闭环。 当LGWR写入在线重做日志时，如果当前日志文件写满以后，LGWR必须切换到下一个联机重做日志，然后开始写入。 切换log file switch等待事件“log file switch (checkpoint incomplete)”。
Oracle 必须等到 checkpoint position 已经写入 在线日志文件. 当数据库等待 checkpoints时， redo产生将会停止，直到log switch完成. 此刻Oracle所有会话会 被等待, 直到checkpoint 完成. 这也是为什么当前会话稳定的假象，因为非sysdba用户已经无法登录。 当checkpoint事件发生时DBWn会将脏块写入到磁盘中，同时数据文件和控制文件的文件头也会被更新以记录checkpoint信息。 When a checkpoint occurs, Oracle must update the headers of all datafiles to record the details of the checkpoint. This is done by the CKPT process. The CKPT process does not write blocks to disk, DBWn (DB Writer Process) always performs that task. 更多信息参考Master Note: Overview of Database Checkpoints (文档 ID 1490838.1)
不能日志切换了，那下一步可以检查:是否为归档模式? 归档路径，空间使用率，日志当前状态，日志大小，日志切换频率，IO情况…
SQL> select group#,thread#,SEQUENCE# ,STATUS,FIRST_CHANGE# from v$log;
GROUP# THREAD# SEQUENCE# STATUS FIRST_CHANGE#
--------------- --------------- --------------- ---------------- ---------------
1 1 10821 ACTIVE 29794542995
2 1 10822 ACTIVE 29795882841
3 1 10823 ACTIVE 29797766437
4 1 10824 CURRENT 29798824118
5 1 10820 ACTIVE 29792473826
11 2 13634 INACTIVE 29794540448
12 2 13635 INACTIVE 29796006289
13 2 13636 INACTIVE 29798244262
14 2 13637 INACTIVE 29799746620
15 2 13638 CURRENT 29801862030
set lines 120;
set pages 999;
SELECT
to_char(first_time,'YYYY-MON-DD') day,
to_char(sum(decode(to_char(first_time,'HH24'),'00',1,0)),'99') "00",
to_char(sum(decode(to_char(first_time,'HH24'),'01',1,0)),'99') "01",
to_char(sum(decode(to_char(first_time,'HH24'),'02',1,0)),'99') "02",
to_char(sum(decode(to_char(first_time,'HH24'),'03',1,0)),'99') "03",
to_char(sum(decode(to_char(first_time,'HH24'),'04',1,0)),'99') "04",
to_char(sum(decode(to_char(first_time,'HH24'),'05',1,0)),'99') "05",
to_char(sum(decode(to_char(first_time,'HH24'),'06',1,0)),'99') "06",
to_char(sum(decode(to_char(first_time,'HH24'),'07',1,0)),'99') "07",
to_char(sum(decode(to_char(first_time,'HH24'),'08',1,0)),'99') "0",
to_char(sum(decode(to_char(first_time,'HH24'),'09',1,0)),'99') "09",
to_char(sum(decode(to_char(first_time,'HH24'),'10',1,0)),'99') "10",
to_char(sum(decode(to_char(first_time,'HH24'),'11',1,0)),'99') "11",
to_char(sum(decode(to_char(first_time,'HH24'),'12',1,0)),'99') "12",
to_char(sum(decode(to_char(first_time,'HH24'),'13',1,0)),'99') "13",
to_char(sum(decode(to_char(first_time,'HH24'),'14',1,0)),'99') "14",
to_char(sum(decode(to_char(first_time,'HH24'),'15',1,0)),'99') "15",
to_char(sum(decode(to_char(first_time,'HH24'),'16',1,0)),'99') "16",
to_char(sum(decode(to_char(first_time,'HH24'),'17',1,0)),'99') "17",
to_char(sum(decode(to_char(first_time,'HH24'),'18',1,0)),'99') "18",
to_char(sum(decode(to_char(first_time,'HH24'),'19',1,0)),'99') "19",
to_char(sum(decode(to_char(first_time,'HH24'),'20',1,0)),'99') "20",
to_char(sum(decode(to_char(first_time,'HH24'),'21',1,0)),'99') "21",
to_char(sum(decode(to_char(first_time,'HH24'),'22',1,0)),'99') "22",
to_char(sum(decode(to_char(first_time,'HH24'),'23',1,0)),'99') "23"
from
v$log_history
WHERE first_time>SYSDATE-7
GROUP by
to_char(first_time,'YYYY-MON-DD');
DAY 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
----- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- --- -- --- --- --- --- ---
2018-4月 -15 0 0 0 0 0 0 0 0 0 0 0 0 0 1 1 2 2 1 2 1 1 1 1 1
2018-4月 -16 1 4 1 2 0 2 2 1 2 3 4 4 3 3 2 4 3 2 3 1 1 1 2 0
2018-4月 -17 2 3 2 0 2 1 2 1 2 3 4 4 2 3 2 3 4 2 2 2 1 1 1 1
2018-4月 -18 1 4 1 2 0 2 2 4 3 3 4 3 2 1 4 3 3 2 2 1 2 0 2 1
2018-4月 -19 1 5 1 2 0 2 1 3 3 4 3 4 2 2 3 3 3 3 2 1 2 0 2 0
2018-4月 -20 2 5 1 1 1 2 2 2 3 3 4 3 4 2 2 4 3 3 2 0 2 2 0 2
2018-4月 -21 0 2 2 2 1 1 3 0 0 1 0 0 0 0 1 0 0 0 0 3 2 28 2 2
2018-4月 -22 2 2 2 1 1 3 3 2 3 3 2 1 0 0 0 0 0 0 0 0 0 0 0 0
SQL> SELECT EVENT,BLOCKING_SESSION,STATUS FROM V$SESSION WHERE PADDR IN(select ADDR from v$process WHERE PNAME LIKE 'CKP%')
2 ;
EVENT BLOCKING_SESSION STATUS
---------------------------------------------------------------- ---------------- --------
rdbms ipc message ACTIVE
SQL>SELECT EVENT,BLOCKING_SESSION,STATUS FROM V$SESSION WHERE PADDR IN(select ADDR from v$process WHERE PNAME LIKE 'DBW%')
EVENT BLOCKING_SESSION STATUS
---------------------------------------------------------------- ---------------- --------
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
...
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
rdbms ipc message ACTIVE
32 rows selected.
Note:
当前的日志thread 1,也就是实例1的所有log file都是活动状态，无法覆盖reuse, 根据日志组切换频率判断大小和online redo log组数不是瓶颈。手动发起检查点hang 半小时不动，快速恢复手段也是先加上几组日志确保日志可以生成，让当前实例恢复业务，再分析原因。
4. 临时解决办法
SQL> alter database add logfile thread 1 '+DATA' size 2g; Database altered.
给thread 1(实例1) 临时增加了几组日志后，实例已经可以连接，并且业务恢复正常。
5. 日志收集和hanganalyze 和 systemstate dump，short_stack
OS 无报错，CPU,内存资源空闲， （使用了多路径，也曾怀疑是否有个别存储链路的有IO挂起，但主机无法确认。）
alert log文件无错误日志， 只是曾经有ORA-20的错误； AWR 几个小时已无数据收集； 查看LGWR, DBWR,CKPT Trace 文件；
SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug dump hanganalyze 3;
Statement processed.
SQL> oradebug dump hanganalyze 3;
Statement processed.
SQL> oradebug dump hanganalyze 3;
Statement processed.
SQL> oradebug tracefile_name;
-- Hanganalyze trace
Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'rdbms ipc message'<='log file switch (checkpoint incomplete)'
Chain 1 Signature Hash: 0xfb14fb68
[b] Chain 2 Signature: 'rdbms ipc message'<='write complete waits'<='buffer busy waits'
Chain 2 Signature Hash: 0x768e7402
[c] Chain 3 Signature: 'rdbms ipc message'<='log file switch (checkpoint incomplete)'<='buffer busy waits'
Chain 3 Signature Hash: 0x4110dae0
同时可以快速做几个进程的short_stack,如CKPT
SQL> oradebug setorapid 60 Oracle pid: 60, Unix process pid: 8931, image: oracle@fwptdb01 (CKPT) SQL> oradebug short_stack; ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3592<-sspuser()+140<-__sighndlr()+12<-call_user_handler()+868<-sigacthandler()+92<-_syscall6()+32<-sskgpwwait()+236<-ksliwat()+1952<-kslwait()+240<-ksarcv()+212<-ksbabs()+764<-ksbrdp()+1720<-opirip()+1680<-opidrv()+748<-sou2o()+88<-opimai_real()+512<-ssthrdmain()+324<-main()+316<-_start()+380
这个问题是这个环境第一次出现，同时对数据库检查确认，AMM 未启用， ASMM 使用，并且SGA TARGET给了500G, buffer cache给了400G, shared pool 96G, 这么大的内存还是比较少， 不过大内存有大内存的麻烦。
并且确认已禁用了Solaris OS DISM.
当时手动多次checkpoint 都无法完成， 并且新加的日志组只能临时缓解还是无法reuse, 于时当晚重启了数据库实例，重启后恢复正常。
怀疑是BUG ，但从已知BUG 未找到。 但后期得知该数据库使用了FLASH BUFFER，flash buffer很少使用，并且BUG较多，与这个案例现象相同的有个bug,
Bug 22083366 CKPT hang blocked by flash buffer in RAC. 但无法确认， 仅记录一下，不过还是建议禁用flash buffer.
总结
因为当前的实例无法checkpoint ，导致在redo log 一直处于active状态，在所有日志组都active后，所有事务会挂起，新会话无法连接。常用的手段是确认日志组足够大；增长日志组；调优checkpoint;确保I/O 性能稳定或使用更快的I/O设备.或确认是否有相关BUG, 针对当前现象, 临时增加日志组争取时间，重启实例释放数据库的所有进程资源恢复。
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。