태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

trace 파일을 사용하는 또 한가지 방법

오라클 2009.03.20 14:02
자신만의 방식으로 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
;

신고
Trackback 1 : Comments 2
  1. 바다모습 2009.03.21 10:05 신고 Modify/Delete Reply

    오~ 오랫동안 가지고 있던 고민을 한번에 풀어 주는 것 같은데요~
    감사합니다.~!^^

  2. moncler online 2013.01.04 16:38 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment

티스토리 툴바