웹 개발과 관련된 모든 것들

--- 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 커맨드의 모든것을 볼 수 있다.

 

 

Oradebug 사용법
- 적절한 권한을 가진 DB USER 로 sqlplus 로 접속
- 반드시 덤프할 오라클 프로세스를 지정한 후 사용
- SYNTAX : SQL>oradebug command <option>

일반 유저도 Try

SQL> show user
USER is "SCOTT"
SQL> oradebug setmypid
ORA-01031: insufficient privileges

 

SQL> conn / as sysdba
Connected.
SQL> show user
USER is "SYS"
SQL> oradebug setmypid
Statement processed.

==> 자신의 process ID 지정 해서 dump

 

일반 유저를 찾아서 지정 해보기

보통은[AIX 환경] ps aux | sort -k3 으로 cpu 과도 사용 Unix process ID 를 찾은 후

지정 해서 dump 를 떨군 후 분석을 하면 될듯

 

## Scott User 의 Process ID 찾기
SQL> select username, sid, serial#,PADDR from v$session where username ='SCOTT';

USERNAME                              SID    SERIAL# PADDR
------------------------------ ---------- ---------- --------
SCOTT                                  28         54 46CB5768

SQL> select * from v$process where addr = '46CB5768';

ADDR            PID SPID      USERNAME           SERIAL#
-------- ---------- --------- --------------- ----------
TERMINAL                       PROGRAM
------------------------------ ------------------------------------------------
TRACEID
--------------------------------------------------------------------------------
B LATCHWAI LATCHSPI
- -------- --------
46CB5768         29 283314    oracle                   2
pts/8                          oracle@seldw (TNS V1-V3)

 

## Unix 환경에서 파악

[CRAFT]seldw:/app/oracle/tg> ps -ef| grep 283314
  oracle 282448 290026   0 10:45:26  pts/7  0:00 grep 283314
  oracle 283314 284036   0 10:42:54      -  0:00 oracleCRAFT (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

 

SQL> oradebug unlimit
Statement processed.
==> Dump 화일 무제한으로 설정
SQL> oradebug setospid 283314
Oracle pid: 29, Unix process pid: 283314, image: oracle@seldw (TNS V1-V3)

==> Scott Process ID 를 지정 해서 dump
SQL> oradebug tracefile_name
Statement processed.
==> dump 화일명 체크

==> 나오지 않는다.

SQL> oradebug dump errorstack 3
Statement processed.
==> dump 화일에 실제 Write 되도록 command 를 날리기

SQL> oradebug tracefile_name
/app/oracle/admin/CRAFT/udump/ora_283314_craft.trc
==> 이제 화일명이 보임

 

# Event 로 Trace 걸기
SQL> oradebug setospid 283314
Oracle pid: 29, Unix process pid: 283314, image: oracle@seldw (TNS V1-V3)

# 10046 Event 에 대해서 Trace 생성도록 설정 하기
SQL> oradebug event 10046 trace name context forever, level 12
Statement processed.
SQL> oradebug event 10046 trace name context off
Statement processed.
SQL> oradebug tracefile_name
/app/oracle/admin/CRAFT/udump/ora_283314_craft.trc

 

CASE 1 : 특정 프로세스가 SPIN 또는 HANG
SQL> oradebug dump errorstack 3 .. 3분단위 3번수행
SQL> oradebug dump processstate 10 .. 비교1
SQL> oradebug event 942 errorstack 10 .. 비교2

 

CASE 1 은 특정 프로세스가 SPIN 또는 HANG 으로 보이는 경우입니다.
(1) Oradebug setospid 해당 프로세스를 덤프대상으로 지정하고
(2) Oradebug dump errorstack 3 으로 ERRORSTACK 을 2-3번 떠서
(3) CALL STACK 부분이 변하고 있는지 비교해봅니다.
변하고 있으면 SPIN 이고, 변하지 않고 있으면 HANG 이라고 결론 내릴 수 있습니다.
ERRORSTACK LEVEL 3 에 PROCESSSTATE DUMP 가 포함되므로
PROCESSSTATE DUMP 를 별도로 수행할 필요가 없습니다.
EVENT Command 에서 ERRORSTACK 를 설정할 때와 비교해보면, EVENT Command 는 해당 에러가 발생하는
시점에 에러스택이 생성되는 것이고, DUMP Command 는 Oradebug Command 를 수행하자마자 에러스택이
생성됩니다.

 

CASE 2 : 데이터베이스 SPIN 또는 HANG
SQL> oradebug dump systemstate 10 .. 3분간격 3번수행
= alter session set events 'immediate trace name SYSTEMSTATE level 10';

케이스 두번째, 드디어 SYSTEMSTATE DUMP 입니다.
이 Command 는 아마도 oradebug 에서 가장 많이 사용되는 명령어로
alter session set events 'immediate trace name SYSTEMSTATE level 10'; 과 같습니다.
보시다시피 Oradebug Command 가 훨씬 간단하고 Rule 만 알면 외울 필요도 없습니다.
인스턴스 HANG 시 3분 간격으로 3번을 수행한 결과가 있어야 Slow Performance 인지,

진짜 HANG 이였는지 판단할 수 있습니다.

SQL> oradebug dump systemstate 10
ORA-00074: no process has been specified
SQL> alter session set events 'immediate trace name systemstate level 10';

Session altered.

 

CASE 3 : 프로세스 메모리가 비정상 증가하는 경우
SQL> oradebug dump heapdump 5 .. PGA+UGA

CASE 4 : SGA 부족으로 ORA-4031 가 발생하는 경우
SQL> oradebug dump heapdump 2 .. SGA
event="4031 trace name HEAPDUMP level 2" in initSID.ora

 

CASE 6 : 리커버리시 데이터파일 상태 불일치 에러시
SQL> oradebug dump controlf 10
SQL> oradebug dump file_hdrs 10
==>테스트시  임의의 프로세스 지정을 해야 trace 화일이 생성 된다.

SQL> oradebug dump controlf 10
ORA-00074: no process has been specified
SQL> oradebug setospid 283314
Oracle pid: 29, Unix process pid: 283314, image: oracle@seldw (TNS V1-V3)
SQL> oradebug dump controlf 10
Statement processed.
SQL> oradebug tracefile_name
/app/oracle/admin/CRAFT/udump/ora_283314_craft.trc
SQL> oradebug dump file_hdrs 10
Statement processed.
SQL> exit

 

SQL> oradebug hanganalyze 3
Hang Analysis in /app/oracle/admin/CRAFT/udump/ora_89222_craft.trc
프로세스 또는 인스턴스 HANG 진단 및 분석시 유용
HANGANALYZE [level]
1-2 Only HANGANALYZE output, no process dump
3 Level 2 + HANG 으로 추정되는 프로세스 덤프
4 Level 3 + WAIT CHAIN 의 BLOCKER 프로세스
5 Level 4 + WAIT CHAIN 의 모든 프로세스
10 모든 프로세스 덤프

SQL> oradebug hanganalyze 3 .. 권장레벨, 또는 1
Hang Analysis in /home/ora920/ora920_1190.trc
HANGANALYZE TRACEFILE SECTIONS 설명
 CYCLES : Deadlock 관계 세션들의 CHAIN
 BLOCKER OF MANY SESSIONS : 10개 이상의 세션을 blocking 하는 BLOCKER 제시
 OPEN CHAINS : 1개 이상의 타 세션들을 blocking 하는 세션이 포함된 WAIT CHAIN
 OTHER CHAINS : OPEN CHAIN 의 세션들과 간접적으로 관련있는 프로세스 리스트

EXTRA INFORMATION : 덤프 레벨에 따른 프로세스 Errorstack 등의 추가 정보
STATE OF NODES : 모든 세션들 DEPENDENCY GRAPH
  IN_HANG - HANG
  IGN - IGNORE
  LEAF - A waiting leaf node
  LEAF_NW - A running leaf node
  NLEAF - STUCK
세션 STATE 설명입니다.
IN_HANG : 심각한 상태로, 이 상태의 세션은 DEADLOCK 가능성이 있습니다 .
IGN and IGN_DMP : IDLE 상태이므로 무시하셔도 됩니다.
LEAF and LEAF_NW : 이 상태로 Wait Chain 의 가장 앞에 있으면,

                             바로 이 세션이 Blocker 세션입니다.
NLEAF : STUCK 세션으로, 다른 세션이 리소스를 잡고 안 놓아 주는 상태

           로 Performance 이슈일가능성이 높습니다.
 
DB HANG 이것만은 알아두세요!!!
데이터베이스 HANG : DB 연결될 때
SQL> oradebug setmypid

자신의 Process ID 지정 아마도, trace file 생성을 위해서 임의로 지정하는 듯
SQL> oradebug unlimit

Trace file 무한으로 설정
SQL> oradebug hanganalyze 1 

빨리 Blocker 찾으세요

Trace 화일을 통해서 문제의 Process ID 를 서치

심도 있게 더 깊이 분석시 아마도 setospid를 통해서 Blocker ID 를 찾은수

다시 trace 를 시도 하면 될듯
SQL> oradebug dump systemstate 10 ..

다른세션에서 3분3번

 

데이터베이스 HANG : DB 연결안 될 때
$ dbx .a PID $ORACLE_HOME/bin/oracle .. Oracle PID
dbx) call ksudss(10) or print ksudss(10)
dbx) detach

RAC에서 다른 Instance와의 연관된 내용까지 분석하려면 다음과 같은 명령문을 사용해야 한다.

SQL> oradebug setinst all
SQL> oradebug --g def hanganalyze 1

 

SQL> oradebug hanganalyze <level> -- 예: oradebug hanganalyze 3
Level에 따른 출력 내용은 다음과 같다.

    * 10 - Dump all processes (IGN state)
    * 5 - Level 4 + Dump all processes involved in wait chains (NLEAF state)
    * 4 - Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state)
    * 3 - Level 2 + Dump only processes thought to be in a hang (IN_HANG state)
    * 1-2 - Only HANGANALYZE output, no process dump at all