자신만의 방식으로 trace 분석을 해야만 하는 경우가 종종 있다.
예를 들어, 아래와 같이 10046 trace 파일의 대기 레코드들이 있다고 하자.
...
WAIT #11: nam='buffer busy waits' ela= 4 file#=17 block#=2313 class#=8 obj#=81140 tim=520863116874
WAIT #11: nam='buffer busy waits' ela= 5456 file#=17 block#=2624 class#=1 obj#=81140 tim=520864249735
WAIT #11: nam='buffer busy waits' ela= 6 file#=17 block#=2569 class#=8 obj#=81140 tim=520864249933
...
다음과 같이 buffer busy waits 를 class# 항목으로 정렬해서 보고 싶다. :
CLASS# CNT ELAPSED
---------- ---------- -------
8 1456 3.01
1 420 1.54
4 5 .00
35 2 .00
77 1 .00
일반적인 tkprof로는 방법이 없다. 그럼 어떻게 해야할까, 개발자를 새로 고용? 뭔가 멋진 방법이 있을까?
No. 나라면 100% SQL로 구현할 것이다. SQL이라면, 쉽고 유연하며 무엇보다 공짜다.
자, 그럼 내가 제안하는 방법을 한번 보자.
1. 디렉토리와 array 를 생성한다.
-- create directory and varchar2 array
col value new_value user_dump_directory;
select value from v$parameter where name = 'user_dump_dest';
create or replace directory user_dump_dir as '&user_dump_directory';
create or replace type varchar2_array as table of varchar2(4000);
/
2. utl_file 패키지와 함께 pipelined table function를 생성한다. 만약 pipelined table function에 대해 잘 모른다면 여기를 참조한다.
-- create get_trace_file1 function
create or replace function get_trace_file1(s_id number default userenv('sid'))
return varchar2_array
pipelined
as
v_handle utl_file.file_type;
v_filename varchar2(2000);
v_line varchar2(4000);
begin
-- get exact file_name
select i.value||'_ora_'||p.spid||'.trc' into v_filename
from v$process p, v$session s,
(select value from v$parameter where name = 'instance_name') i
where p.addr = s.paddr
and s.sid = s_id
;
v_handle := utl_file.fopen('USER_DUMP_DIR', v_filename, 'R', 32767);
loop
begin
utl_file.get_line(v_handle, v_line);
exception when no_data_found then
exit;
end;
pipe row(v_line);
end loop;
return;
end;
/
-- create get_trace_file2 function
create or replace function get_trace_file2(file_name in varchar2)
return varchar2_array
pipelined
as
v_handle utl_file.file_type;
v_line varchar2(20000);
begin
v_handle := utl_file.fopen('USER_DUMP_DIR', file_name, 'R', 32767);
loop
begin
utl_file.get_line(v_handle, v_line);
exception when no_data_found then
exit;
end;
pipe row(v_line);
end loop;
return;
end;
/
3. 자... 그럼 간단한 데모를 보자.
alter session set events '10046 trace name context forever, level 8';
select count(*) from t1;
alter session set events '10046 trace name context off';
select * from table(get_trace_file1);
Dump file c:\oracle\admin\ukja10\udump\ukja10_ora_2820.trc
Thu Mar 19 15:10:10 2009
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU : 2 - type 586
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:1481M/3070M, Ph+PgF:3140M/4960M, VA:1359M/2047M
Instance name: ukja10
Redo thread mounted by this instance: 1
Oracle process number: 16
Windows thread id: 2820, image: ORACLE.EXE (SHAD)
*** ACTION NAME:() 2009-03-19 15:10:10.109
*** MODULE NAME:(SQL*Plus) 2009-03-19 15:10:10.109
*** SERVICE NAME:(UKJA10) 2009-03-19 15:10:10.109
*** SESSION ID:(157.1205) 2009-03-19 15:10:10.109
=====================
PARSING IN CURSOR #1 len=68 dep=0 uid=61 oct=42 lid=61 tim=172367882897 hv=740818757 ad='27e12b14'
alter session set events '10046 trace name context forever, level 8'
END OF STMT
...
4. 이제 buffer busy waits 이벤트를 class#로 정렬해서 분석할 수 있다.
col class# format a10
col elapsed format 99.99
with t as (
select /*+ materialize */
column_value as line,
instr(column_value, 'ela=') ei,
instr(column_value, 'file#=') fi,
instr(column_value, 'block#=') bi,
instr(column_value, 'class#=') ci,
instr(column_value, 'obj#=') oi,
instr(column_value, 'tim=') ti
from table(get_trace_file2('trc_1.trc'))
--from table(get_trace_file2('trc_2.trc'))
where
instr(column_value, 'WAIT #2: nam=''buffer busy waits''') > 0
--instr(column_value, 'WAIT #11: nam=''buffer busy waits''') > 0
)
select
class#
, count(1) as cnt
, sum(elapsed)/1000000 as elapsed
from
(
select
substr(line, ei+4, fi-ei-4) as elapsed,
substr(line, fi+6, bi-fi-6) as file#,
substr(line, bi+7, ci-bi-7) as block#,
substr(line, ci+7, oi-ci-7) as class#,
substr(line, oi+5, ti-oi-5) as obj#,
substr(line, ti+4) as tim
from
t
) x
group by
class#
order by
2 desc, 3 desc
;
내가 실제로 수행하고자 한 것은 다음과 같다.
1. trc_1.trc 파일은 ASSM 으로 된 40K extent size의 10046 trace result를 갖고있다.
2. trc_2.trc 파일은 ASSM 으로 된 10M extent size 의 10046 trace result를 갖고있다.
3. 10개의 동시 세션이 10046 trace가 enable된 상태에서 테이블에 insert를 수행한다.
4. extent size가 buffer 경합 패턴에 어떻게 영향을 주는지 분석하고자 한다.
결과는 아래와 같다.
-- when extent size is 40K
CLASS# CNT ELAPSED
---------- ---------- -------
8 285 1.40
1 215 4.64
4 42 .01
9 2 .00
19 1 .00
33 1 .00
-- when extent size is 10M
CLASS# CNT ELAPSED
---------- ---------- -------
8 1456 3.01
1 420 1.54
4 5 .00
35 2 .00
77 1 .00
차이점을 보면 extent size 가 큰 경우에는 1st level 비트맵 블럭(8)에서 주로 버퍼 경합이 발생했고, extent size 가 작은 경우, data block(1)에서 경합이 주로 발생했다.
이 결과가 무엇을 의미 하는가? 여기서 이야기하고자 하는 주제는 아니므로 생략...
여기서 내가 말하고자 하는것은, 오라클은 우리가 상상하는 것 이상의 기능을 갖고 있다는 것이다. pipelined table function 과 utl_file 패키지라는 간단한 트릭을 사용해서 wait 이벤트의 새로운 패턴을 분석할 수 있었다.
PS1) pipelined table function 대신 external table도 이용할수 있으나 아무래도 pipelined table function 이 훨씬 멋진 방법인것 같다.
PS2) 10g부터는 다음과 같이 Regular Expression을 이용해서 훨씬 간단하게 분석할 수 있다.
select
cursor_number cur_id,
event,
class,
round(sum(elapsed/1000000), 2) elapsed_time,
count(event) cnt
from (
select
substr(regexp_substr(txt, ‘wait #[^:]*’), 7) cursor_number,
substr(regexp_substr(txt, ”’[^'']*’), 2) event,
nvl(substr(regexp_substr(txt, ‘class#=[^ ]*’), 8), ‘n/a’) class,
substr(regexp_substr(txt, ‘ela= [^ ]*’), 6) elapsed
from table(get_trace_file1)
where regexp_substr(txt, ‘wait #[^:]*’) is not null
)
group by
cursor_number,
event,
class
order by cursor_number
;
의 
블로그
