Last Updated on 11월 14, 2021 by Jade(정현호)
안녕하세요
이번 포스팅은 log file switch (checkpoint incomplete) 관련된 사례를 확인 해보려고 합니다.
Contents
장애 상황
먼저 장애 발생 시스템 현황은 아래와 같습니다.
OS : Linux 7.x
Version: 11gR2(11.2.0.4)
PSU : 11.2.0.4.181016
RAC Y/N : 2Node RAC
Storage Type: ASM
장애시점의 상황은
갑자기 다량의 세션들이 아래의 대기 이벤트로 대기를 하기 시작하면서 문제가 발생되기 시작 하였습니다.
gc buffer busy acquire
buffer busy waits
log file switch (checkpoint incomplete)
등등..
선행 세션이 대기로 인하여 계속 Active(활성) 인 상태로 다시 신규 세션이 유입되게 되고, 그러나 세션의 처리는 계속 지연이 발생 되면서 Active Session 수가 수백개 까지 늘어나게 되었습니다.
그로 인하여 CPU 사용률도 매우 높은 상태가 발생되었습니다.
[Node 1 CPU Utilization]
[Node 2 CPU Utilization]
원인 파악 - 로그 확인
장애 발생 시스템에서 수집된 성능 지표나 세션 정보 그리고 장애시 생성된 trace 파일이나 incident 파일로 확인 해야 했습니다.
문제 시점에 수집된 세션들의 대기이벤트 수 정보입니다.
event inst_id Wait_Count --------------------------------------------------------------- buffer busy waits 2 369 buffer busy waits 1 322 log file switch (checkpoint incomplete) 2 202 gc buffer busy acquire 1 183 gc current request 1 37 gc buffer busy release 2 14 enq: TX - row lock contention 1 9 enq: TX - index contention 1 3
대부분이 Buffer 와 CKPT 또는 체크포인트와 관련된 대기이벤트로 대기하고 있었습니다.
문제 시점에 발생된 Hang analyze 를 통해 조금 더 자세하게 확인 할 수 있었습니다.
Verified Hangs in the System
Root Chain Total Hang
Hang Hang Inst Root #hung #hung Hang Hang Resolution
ID Type Status Num Sess Sess Sess Conf Span Action
----- ---- -------- ---- ----- ----- ----- ------ ------ -------------------
11 HANG VICSELTD 2 1111 5 2228 HIGH GLOBAL IGNRD:InstKillNotA
Hang Ignored Reason: Since instance termination is not allowed, automatic
hang resolution cannot be performed.
inst# SessId Ser# OSPID PrcNm Event
----- ------ ----- --------- ----- -----
1 5555 102 33333 FG buffer busy waits
1 4444 101 22222 FG gc buffer busy acquire
1 3333 789 11111 FG gc current request
2 2222 456 67891 FG log file switch (checkpoint incomplete)
2 1111 123 12345 LGWR rdbms ipc message
* SessID 와Serial#, OSPID 정보는 임의(dummy) 값으로 편집되어 있습니다. (실제 정보 아님)
생성된 Hang analyze 트레이스 파일에서 Verified Hang 정보의 경우 Hang의 시작 또는 관련된 세션은 루트가 맨 아래에 있고 각 대기 세션이 그 위에 나열되는 출력입니다.
그래서 대기의 순서는 rdbms ipc message 이 Root Blocker(Cause) 로서 아래 순서와 같이 대기이벤트를 동반하여 대기가 발생된 내역 입니다.
'rdbms ipc message'<='log file switch (checkpoint incomplete)'<='gc current request'<='gc buffer busy acquire'<='buffer busy waits'
rdbms ipc message 로 인하여 CKPT 프로세스가 수행하는 체크포인트가 지연 되었거나 되지 않은 상황이며, 통상 체크포인트의 문제는 DBWR의 내려써짐에서의 문제가 있는경우가 많습니다.
그 다음 구성된 모든 Redo log 그룹 모두 Log Switch 를 수행하였지만 여전히 체크포인트가 완료가 안되고 있는 상황을 맞이하게 됩니다.
구성된 Redo Log 그룹에 대해서 한 싸이클(처음 그룹에서 마지막 그룹까지)을 로그 스위치 할때까지 체크포인트가 완료 되지 못하게 된다면 Log Switch 작업은 앞에서 마무리 되지 못한 체크포인트에 의해 대기 하게 됩니다 (log file switch (checkpoint incomplete))
체크포인트와 관련되어있는 Buffer Cache 내 dirty buffer 를 DBWR 에 의해서 기록되는 부분이 지연이 되면서 사용할 수 있는 버퍼의 확보가 늦어지고 또는 누적 세션이 증가함에 따라서 결과적으로 쿼리 수행시 DB Buffer Cache 에 대한 경합 과 로그파일 스위치에 관련된 대기 이벤트로 대기 하게 되는 순으로 진행된다고 예상할 수 있을 것 같습니다
결론 - 원인
대기시 발생된 대기이벤트 등으로 확인하였을 때 아래 bug이 유사하게 매칭 된다고 예상할 수 있을 것 같습니다.
Bug 22083366 - CKPT hang blocked by flash buffer in RAC (Doc ID 22083366.8)
장애 발생시스템의 PSU 는 11.2.0.4.181016 이며 해당 패치는 11.2.0.4.200114 에 포함되어 있지만, 11.2.0.4.200114 패치는 ES 계약이 있어야 다운로드가 가능한 패치 입니다.
해당 패치는 별도의 One-Off Interim 패치로도 있기 때문에 Interim 패치로 적용하면 됩니다.
Reference Note
CKPT hang blocked by flash buffer in RAC (Doc ID 22083366.8)
관련된 다른 글
Principal DBA(MySQL, AWS Aurora, Oracle)
핀테크 서비스인 핀다에서 데이터베이스를 운영하고 있어요(at finda.co.kr)
Previous - 당근마켓, 위메프, Oracle Korea ACS / Fedora Kor UserGroup 운영중
Database 외에도 NoSQL , Linux , Python, Cloud, Http/PHP CGI 등에도 관심이 있습니다
purityboy83@gmail.com / admin@hoing.io
