태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'wait event'에 해당되는 글 2건

  1. 2009.03.20 trace 파일을 사용하는 또 한가지 방법 (2)
  2. 2009.03.04 Oracle에서 Event란 무엇을 의미하는가? (1)

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
;

Trackbacks 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


Oracle에서 Event란 무엇을 의미하는가?

오라클 2009.03.04 10:49
얼마전 사내의 한 신입 사원과 "이벤트"라는 용어의 의미에 대해 논의할 시간이 있었다. 그 신입 사원(뿐이겠는가!)은 "이벤트"라는 용어를 제대로 이해하지 못하고 있었다.

이 모든 것은 우리가 영어를 제대로 해석하지 못하는데서 발생하는 것이다.

만일 "이벤트"라는 용어 대신 "사건"이라는 용어를 사용했다면 모든 것이 명확했을 것이다. 앞으로 이벤트라는 말을 만나면 이것을 "사건"으로 바꾸면 의미가 매우 분명해지는 것을 경험할 것이다.

Oracle에서 이벤트라는 말은 보통 2가지 경우에 사용된다.
  • 대기(용) 이벤트: 어떤 사건이 종료되기를 대기한다는 의미이다.
  • 진단(용) 이벤트: 어떤 사건이 발생했을 때 진단을 수행하겠다는 의미이다.

db file sequential read 이벤트의 의미는 무엇인가? 다음과 같은 Code를 상상해 보자.

function read_single_block(file#, block#) {
    ...
    start_wait('db file sequential read');
    v = pread(...);
    end_wait('db file sequential read');
}

즉, db file sequential read 이벤트는 OS Call인 pread함수를 호출한 후 리턴되는 사건(이벤트)을 의미한다. 따라서 이벤트를 대기한다는 말은 "어떤 사건(Function Call이 리턴되는 사건)이 발생할 때까지 기다린다"는 의미로 해석해야 한다.


이런 의미에서 Carry MilsapWAIT라는 용어 대신 SYSCALL 이라는 용어를 사용해야 한다고 주장한다. 매우 통찰력있는 주장이라고 할 수 있다. 대기의 대상이 되는 모든 이벤트는 SYSCALL과 연관되기 때문이다. 이 의미를 잘 파악하면 Wait = Sleep이 아닌 이유가 명확해진다.

다음과 같이 진단 이벤트를 사용한다.
  
alter session set events '10046 trace name context forever, level 12';


이것을 어떻게 해석해야 하는가?
  • 10046 = Query가 수행되는 사건. 즉 Query를 수행하는 "사건"을 의미한다.
  • trace name = Trace를 수행하라. 사건이 발생했을 때의 행위(Action)을 의미한다. 
  • context forever, level 12 = 사건이 발생할 때마다 행위를 수행하되, 행위의 레벨을 12로 하라
즉 다음과 같은 호출은
   
alter session set events '10046 trace name context forever, level 12';

다음과 같이 해석하면 된다.
   
10046 사건(Query가 수행되는 사건)이 발생하면 Trace를 수행하되, 사건이 발생할 때마다 하고, 레벨은 12로 하라

Tanel Poder가 진단 이벤트에 대해 아주 상세하고 친절한 해석을 제공하고 있다.


Oracle 이벤트라는 말을 사용할 때 무슨 고유명사나 심오한 의미가 있는 것으로 해석해서는 안된다. 말 그대로 "사건"으로 해석해야 정확한 의미가 파악된다.

항상 이 빌어먹을 영어가 문제다.

Trackbacks 0 : Comments 1
  1. 이명진 2009.03.04 13:50 신고 Modify/Delete Reply

    글을 읽고 나니 어느 정도 이벤트에 대한 정의가 뚜렷해지는 것 같습니다.
    10046, 10053 event 같은 경우에 위의 예처럼 생각하면 더욱 이해가 쉽게 되겠네요.
    오라클 Ace로 추천받으신 점 다시한번 감축드립니다^^*.

Write a comment