태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

[티팩] 지능적인 대기 이벤트 분석 - Part3. (대기이벤트 프로파일링)

오라클 2010.07.13 15:06
특정 세션이 어떤 이벤트를 주로 대기하는지 직관적으로 관찰하는 가장 좋은 방법은 무엇입니까?

아마 위의 문제에 대한 가장 정확한 대답은 Oracle 10g부터 제공되는 ASH(Active Session History)일 것입니다. ASH의 가치는 이루 말할 수가 없습니다. 좀 과장하면 오라클 행(Hang) 현상을 트러블슈팅하는 오라클의 핵심 지원 엔지니어들의 10년 소원이었을 것으로 봅니다.

이것이 단순히 과장이 아닌 것이, DMA(Direct Memory Access)에 의해 Active Session History를 수집하고 보여주는 솔루션이 고가로 시장에 팔리는 것을 보면 알 수 있습니다.

Oracle 10g부터는 DMA에 의한 ASH 데이터를 기본적으로 제공하니 당연히 이것을 적극 활용해야 합니다. 사용법은 아래와 같이 매우 간단합니다.

1. Session #1에서 ALL_OBJECTS를 읽습니다. 당연히 I/O 관련 대기 이벤트들(db file sequential read나 db file scattered read와 같은)이 나타날 것입니다.

-- session #1
exec dbms_application_info.set_client_info('SESSION1');

alter system flush buffer_cache;

select count(*) from all_objects;

2. ASH를 이용하면 Session #1이 어떤 이벤트들을 대기했는지를 초(Second)단위로 알 수 있습니다.

col sid new_value sid
select sid from v$session where client_info = 'SESSION1';

-- active session history
col event format a30
select * from (
	select to_char(sample_time,'hh24:mi:ss'), session_id, session_state, sql_id, event 
	from v$active_session_history
	where session_id = &sid
	order by sample_time desc
) where rownum <= 10;

TO_CHAR( SESSION_ID SESSION SQL_ID        EVENT
-------- ---------- ------- ------------- ------------------------------
11:29:31        143 WAITING 4c1xvq9ufwcjc db file sequential read
11:29:30        143 ON CPU  9tz4qu4rj9rdp
11:29:29        143 ON CPU  9tz4qu4rj9rdp
11:29:28        143 ON CPU  9tz4qu4rj9rdp
11:29:27        143 ON CPU  9tz4qu4rj9rdp
11:29:26        143 ON CPU  9tz4qu4rj9rdp
11:29:25        143 ON CPU  9tz4qu4rj9rdp
11:29:24        143 ON CPU  9tz4qu4rj9rdp
11:29:23        143 ON CPU  9tz4qu4rj9rdp
11:29:22        143 WAITING 9tz4qu4rj9rdp db file sequential read
우리가 일반적으로 활용하는 최소 시간 단위가 초단위이기 때문에 이 정도면 충분합니다. 오라클 행(Hang) 상황이라서 접속 자체가 안되는 경우에는 아래 방법을 사용하면 됩니다.

3. 만일 초단위보다 더 정밀하게 대기이벤트를 추적하고 싶다면 프로파일링 기법을 사용할 수 있습니다. 아래와 같이 100,000번 루프를 돌면서 V$SESSION_WAIT 뷰를 탐색한 뒤 { event, p1 }에 대해 그룹핑을 수행하면 특정 이벤트의 Parameter1 값의 발생 빈도를 알 수 있습니다.

select /*+ ordered use_nl(w) */ 
	sid, 
	event, 
	p1,
	count(*) as wait_hits
from 
	(select /*+ no_merge */ level as lvl from dual connect by level <= 100000) t1,
	(select /*+ no_merge */ 
		sid, 
		decode(state, 'WAITING', event, 'ON CPU') as event, 
		decode(state, 'WAITING', seq#, 0) as seq#, 
		decode(state, 'WAITING', p1, null) as p1, 
		decode(state, 'WAITING', p2, null) as p2, 
		decode(state, 'WAITING', p3, null) as p3 
		from v$session_wait 
		where
			sid = &sid		
	) w 
where 
 sid = &sid
 and (event like '%%' or event = 'ON CPU')
group by sid, event, p1
order by count(*) desc 
;

       SID EVENT                           P1  WAIT_HITS
---------- ------------------------------ --- ----------
       141 db file sequential read          1      51160
       141 ON CPU                                  45571
       141 db file scattered read           1       3269

4. 티팩에서는 위에서 사용한 쿼리를 좀 더 세련되게 구사해서 대기 이벤트 정보를 수집합니다. 아래와 같이 수행하면 특정 세션의 모든 대기 이벤트(null)에 대해 Parameter1 기준(p1)으로 10초간(10) 대기이벤트 정보를 V$SESSION_WAIT로부터 수집해서 요약해줍니다.

-- wait profiling
col event_name format a25
col p1 format 99
col p2 format 99
col p3 format 99
col wait_pct format 99.9
col avg_wait_time heading AVG_WAIT

select * from table(tpack.wait_profile_report(&sid, null, 'p1', 10));

 SID EVENT_NAME                 P1  P2  P3 WAIT_PCT  WAIT_TIME AVG_WAIT
---- ------------------------- --- --- --- -------- ---------- --------
 143 ON CPU                                    63.3     6334.3   6334.3
 143 db file sequential read     1             23.4     2347.6     14.3
 143 db file scattered read      1             13.1       1318     15.5
마치 10046 이벤트(또는 SQL*Trace)를 수행한 후 TKPROF를 통해 대기 이벤트 정보를 추출한 것과 거의 비슷한 효과가 있습니다. 10046을 수행하지 않고도 간편하게 특정 세션의 대기 현황을 알 수 있습니다. 10046과 비교해서 가장 큰 장점은 이벤트의 Parameter별로 집계할 수 있다는 것입니다.

가령 buffer busy waits 이벤트의 경우 P3 값이 Block Class 정보를 나타냅니다. 이 값을 정확하게 아는 것이 중요합니다. 하지만 이 정보가 TKPROF 리포트에는 나타나지 않습니다(물론 10046 트레이스 원본에는 있습니다). 하지만 위에서 사용한 프로파일링 기법을 이용하면 어떤 P3 값이 가장 많이 나타나는지를 바로 알 수 있습니다.

5. 10046 Trace의 원본 파일(레벨 8 이상)은 가장 상세한 대기 이벤트 정보를 제공합니다.

exec dbms_monitor.session_trace_enable(waits=>true);

select count(*) from all_objects;

exec dbms_monitor.session_trace_disable;
트레이스 파일에는 다음과 같은 대기 이벤트가 기록됩니다.
WAIT #3: nam='db file sequential read' ela= 16023 file#=1 block#=7754 blocks=1 obj#=380 tim=709352877372
WAIT #3: nam='db file sequential read' ela= 369 file#=1 block#=7753 blocks=1 obj#=380 tim=709352877875
Regular Expression(10g부터 제공)을 이용하면 위의 텍스트로부터 Event, P1, P2, P3, Wait Time 정보를 추출할 수 있습니다.
select
regexp_replace(
'WAIT #3: nam=''db file sequential read'' ela= 16023 file#=1 block#=7754 blocks=1 obj#=380 tim=709352877372',
'[[:print:]]+nam=''([[:print:]]+)''[[:space:]]+ela=[[:space:]]*([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]]obj#=[[:print:]]+',
'\1.\2.\3.\4.\5')
from dual;

REGEXP_REPLACE('WAIT#3:NAM=''DBFILESEQ
--------------------------------------
db file sequential read.16023.1.7754.1
티팩에서도 위와 비슷한 방법으로 트레이스 파일로부터 직접 읽어서 대기 이벤트 정보를 집계할 수 있습니다.
select * from table(tpack.wait_file_report(tpack.get_tracefile_name(&sid)));

   SID EVENT_NAME                 P1  P2  P3 WAIT_PCT  WAIT_TIME AVG_WAIT
------ ------------------------- --- --- --- -------- ---------- --------
     0 db file sequential read                   76.7   2473.378      2.7
     0 db file scattered read                    23.1    744.395      3.3
     0 SQL*Net message from clie                   .1      3.808      1.3
       nt
     0 SQL*Net message to client                   .0       .018       .0
상세한 대기 정보를 얻는데 생각보다 다양한 방법이 있다는 것을 알 수 있습니다. 어떤 상황에서도 대기 이벤트 정보를 추출할 수 있도록 자신만의 기법 또는 툴 사용 체계를 수립할 필요가 있습니다. 대기 이벤트 정보는 그만큼 중요하기 때문입니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
  2. [티팩] oradebug
  3. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 1
  4. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 2 (핫 블록?)
저작자 표시
신고
tags :
Trackback 0 : Comment 0

Write a comment

티스토리 툴바