--- Arup Nanda 의 사이트에 자주 들어가봅니다. DBA 로서의 장애 Case 를 대응하는 절차가 비교적 자세히 나와있더군요. 요즘 일이 많아서 빠르게 쓰다보니 오역과 중간중간 빼먹는게 많은건 이해해주시길...아래는 실제로 DMA (direct memory access)를 사용해서 처리한 사례더군요..
Diagnosing Library Cache Latch Contention: A Real Case Study
어느날 DW 서버가 갑자기 다운됐다. 그래서 데이타베이스를 올리고 다시 구동했지만 모든 접속을 시도하면
hang 이 걸리는 것이였다. 따라서 접속은 실패하고 DBA는 접속된 세션들이 구동되고 있는지 어떤지를 확인할 수 조차도
없었다. DBA 는 WAIT 이벤트를 체크했다 (그러나 로긴조차도 안되기 때문에 실행할수 없었다)
흥미롭게도 CPU는 70% 정도의 수준이였고 이는 낮시간대의 일반적인 수치이다. 그리고 I/O또한 약 90%로서 이또한
일반적인 수치였다.
따라서 전형적인 방법인 system 관리자에게 보고하고 재부팅을 하는 방법을 사용했다. 재부팅은 30분정도
소요되었고 그 후로 10여분간은 모든것이 정상적으로 보였다. 그러나 얼마되지 않아 아까와같은 똑같은 문제에 부딪쳤다- 데이타베이스가 먹통이 되어버린 것이였다.
이것 때문에 DBA가 나에게 도움을 요청하였다. 이 블로그에서는 내가 이후의 30분동안에 어떻게 수행했고 문제를
해결했는지에 대해서 기술해보도록 하겠다.
증상
(1) 데이타베이스 접속 Hanging
(2) SQL*PLUS AS SYSDBA 로 접속해도 동일한 HANGING 현상: 증상을 확인할 수도 없는 상태
(3) 시스템은 아무때나 리부팅할 수 없는 상태
Action
여기서 접속이 불가능할 때 데이타베이스 인스턴스에서 바로 써먹을 수 있는 꼼수가 존재한다.
대부분의 사람들은 SQL*Plus 에서 "prelim" 이라고 불리는 옵션을 잘알지 못한다. 이 옵션은 세션을 열지 않고
SGA에 바로 접속한수 있는 옵션이다. (10g 이상에서만 가능)
(1) 먼저 SQL*plus 를 실행시키고 아래의 명령문을 실행했다.
$ sqlplus -prelim / AS SYSDBA
SQL>
명심하라. "Oracle Database 10.2.0.3 에 접속" 과 다르다. 지금 보이는 SQL> 프롬프트는 실제로는
데이타베이스에 접속한 상태가 아니다.
(2) 그다음 SGA 를 분석하기 위한 "oradebug" 를 사용하였다.
SQL> oradebug setmypid
SQL> oradebug hanganalyze 12
이 명령은 USER_DUMP_DEST 에 trace파일을 생성한다. 이 파일을 가장 최근에 생겨났기 때문에
쉽게 찾을 수 있다. 심지어는 내가 파일을 찾지 못해도 process ID를 사용해서 파일을 찾을 수 있다.
내가 찾은 파일은 프로세스ID 가 13392인 crmprd1_ora_13392.trc 였다.
(3) 파일을 조사하니 다음과 같았다.
*** 2008-08-23 01:21:44.200
==============
HANG ANALYSIS:
==============
Found 163 objects waiting for
<0/226/17/0x1502dab8/16108/no>
Open chains found:
Chain 1 : :
<0/226/17/0x1502dab8/16108/no>
<0/146/1/0x1503e898/19923/latch:>
이 파일을 많은 것을 말해준다. SID 146 에 Serial# 1 이 library cache latch 를 대기하고 있는 것을 보여준다.(맨마지막줄)
그리고 blocking 세션은 SID 226 Serial# 17 로 나와있다.
나는 일단 이 OS process ID 인 16108 과 19923 을 기록해두었다.
(4) 다음으로 위의 두개의 OS PID 명으로 되어 있는 TRACE 파일을 체크했다.
crmprd1_ora_16108.trc
crmprd1_ora_19923.trc
(5) 먼저 BLOCKER인 첫번째 파일을 열었다. 다음 몇줄의 예이다.
*** 2008-08-23 01:08:18.840
*** SERVICE NAME:(SYS$USERS) 2008-08-23 01:08:18.781
*** SESSION ID:(226.17) 2008-08-23 01:08:18.781
LIBRARY OBJECT HANDLE: handle=c0000008dc703810 mtx=c0000008dc703940(8000) cdp=32737
name=UPDATE DW_ETL.FRRS_PROFILER SET CONSUMER_LINK = :"SYS_B_0", ADDRESS_LINK = :"SYS_B_1", ADDRESS_MATCH = :"SYS_B_2", PROC
ESSED=:"SYS_B_3" WHERE RNUM = :"SYS_B_4"
hash=a029fce7bb89655493e7e51a544592a4 timestamp=08-23-2008 00:10:23
namespace=CRSR flags=RON/KGHP/TIM/OBS/PN0/MED/KST/DBN/MTX/[504100d0]
kkkk-dddd-llll=0000-0001-0001 lock=N pin=0 latch#=10 hpc=0058 hlc=0058
lwt=c0000008dc7038b8[c0000008dc7038b8,c0000008dc7038b8] ltm=c0000008dc7038c8[c0000008dc7038c8,c0000008dc7038c8]
pwt=c0000008dc703880[c0000008dc703880,c0000008dc703880] ptm=c0000008dc703890[c0000008dc703890,c0000008dc703890]
ref=c0000008dc7038e8[c0000008dc7038e8,c0000008dc7038e8] lnd=c0000008dc703900[c0000008dc703900,c0000008dc703900]
LOCK OWNERS:
lock user session count mode flags
---------------- ---------------- ---------------- ----- ---- ------------------------
c0000008d079f1b8 c0000006151744d8 c0000006151744d8 16 N [00]
c0000008d4e90c40 c0000006151bcb58 c0000006151bcb58 16 N [00]
c0000008d0812c40 c0000008151a0438 c0000008151a0438 16 N [00]
(6) 이것은 디버깅을 위해 보물과 같았다. 첫번째에 SID와 Serial#(226,17) 를 확인할수 있다.
이를 사용해서 정확한 SQL문장을 볼수 있다. 또한 락에 대한 전체적인 상황을 볼 수 있다. 락의 자세한 사항은 신경쓰지 않아도 되지만 SID 226 이 전체 세션의 대기를 유발시키는 것이라는 충분한 정보를 제공해주었다.
(7) 나의 조사는 여기서 그치지 않고 이 대기를 유발하는 세션을 찾기를 시도했다. 따라서 나는 파일의 "PROCESS STATE" 이라는 섹션을 조사했다. 다음은 이 파일의 일부분이다.
PROCESS STATE
-------------
Process global information:
process: c00000081502dab8, call: c000000817167890, xact: 0000000000000000, curses: c00000081519ef88, usrses: c000000815
19ef88
----------------------------------------
SO: c00000081502dab8, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
(process) Oracle pid=370, calls cur/top: c000000817167890/c000000817167890, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 115 0 4
last post received-location: kslpsr
last process to post me: c000000615002038 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: c000000615002038 1 6
(latch info) wait_event=0 bits=20
holding (efd=4) c0000008d7b69598 Child library cache level=5 child#=10
Location from where latch is held: kglhdgc: child:: latch
Context saved from call: 13
state=busy, wlstate=free
waiters [orapid (seconds since: put on list, posted, alive check)]:
291 (197, 1219468295, 197)
279 (197, 1219468295, 197)
374 (197, 1219468295, 197)
267 (197, 1219468295, 197)
372 (197, 1219468295, 197)
... several lines sniped ...
307 (15, 1219468295, 15)
181 (6, 1219468295, 6)
waiter count=58
Process Group: DEFAULT, pseudo proc: c0000008e03150d8
O/S info: user: oracrmp, term: UNKNOWN, ospid: 16108
OSD pid info: Unix process pid: 16108, image: oracle@sdwhpdb1
(8) 이파일은 내가 알기를 원하는 것을 모두 말해준다. 여기에 SID 226 에 의해서 발생하는 CACHE LATCH
로 인해서 대기하는 58 session들이 있다. 여기서 OS PROCESS ID 와 BLOCKING 세션의 SQL 문장을 알 수 있다.
(9) 나는 application 사용자가 어떠한 것을 실행했는지를 조사해봤더니 사용자는 loop를 돌면서 처리하는
update 문장을 실행시킨 것이였다. 그리고 그게 다가 아니라 다른 8개의 thread 에서 실행을 하였다.(역: 아마도 화면상에서 처리 가 되지 않으니 화면을 새로고쳐서 계속해서 8번을 처리 버튼을 누른것으로 생각됨)
의심할 여지가 없이 library cache latch 경합에 걸렸다. 모든 세션은 각각의 덤프 정보를 남겼다.
그리고 나는 같은 문장을 실행한 파일을 디렉토리에서 조사해보기로 했다.
$ grep “UPDATE DW_ETL” *.trc
(10) 나는 9개 이상의 세션(프로세스) 파일을 찾았다. 이중 한개의 파일의 일부분이다.
350 (167, 1219470122, 167)
197 (167, 1219470122, 167)
waiter count=185
Process Group: DEFAULT, pseudo proc: c0000008e03150d8
O/S info: user: oracrmp, term: UNKNOWN, ospid: 16114
이 프로세스 한개가 185개 waiter 를 가졌다!!!
$ kill -9
(12) 위의 명령으로 몇개의 프로세스를 죽인 후에야 데이타베이스는 응답하기 시작했다. 모든 프로세스를 죽인 후에는 데이타베이스 wait event 가 완벽히 정상적으로 돌아왔다.
참고사항
(1) Hang 이라고 생각되면 너무 그것에 대해 불안해하지 마라. 세션은 언제나 어떤것을 대기한다. 드물게 행을 만날 뿐이다.
v$session (10g) 이나 v$session_wait 의 EVENT 컬럼을 조회해서 대기하는 것이 무엇인지를 먼저 체크하라.
(2) 데이타베이스에 로긴하지 못해 정보를 얻을 수 없을 때는 oradebug 명령을 사용한다.
(3) oradebug 를 사용할때 SQL*Plus 를 이용한다. 로긴하지 못할때 "sqlplus -prelim " 로 SQL prompt 를 얻을 수 있을 것이다.
(4) oradebug setmypid 이용해서 oradebug 세션을 시작하고 oradebug hanganalyze 로 모든 hang 과 관련되어 있는
문제에 대한 덤프를 생성한다.
(5) oradebug help 를 사용해서 oradebug 커맨드의 모든것을 볼 수 있다.
