태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'10046 trace'에 해당되는 글 3건

  1. 2010.09.28 대기이벤트가 포함된 10046 진단이벤트 실행하기 - Oracle 11g (4)
  2. 2009.03.20 trace 파일을 사용하는 또 한가지 방법 (2)
  3. 2008.10.20 11g is better - 10046 Trace가 좋아졌다!!!

대기이벤트가 포함된 10046 진단이벤트 실행하기 - Oracle 11g

오라클/대기이벤트 2010.09.28 15:22
Oracle 11g에서 대기 이벤트가 포함된 10046 진단 이벤트를 실행하는 방법을 정리해봤습니다.

1. 전통적인 10046 진단 이벤트 사용법은 다음과 같습니다. 레벨 8 이상이면 대기 이벤트가 기록됩니다.

alter session set events '10046 trace name context forever, level 8';

select /* 10046 */ count(*) from user_objects;

alter session set events '10046 trace name context off';
2. 11g에서는 다음과 같이 sql_trace라는 "인식 가능한" 이름의 진단 이벤트를 사용할 수 있습니다.
-- sql_trace + level 8
alter session set events 'sql_trace level 8';

select /* sql_trace_1 */ count(*) from user_objects;

alter session set events 'sql_trace off';

-- sql_trace + wait=true
alter session set events 'sql_trace wait=true';

select /* sql_trace_2 */ count(*) from user_objects;

alter session set events 'sql_trace off';

-- sql_trace + wait=true, bind=true
alter session set events 'sql_trace wait=true, bind=true';

select /* sql_trace_3 */ count(*) from user_objects;

alter session set events 'sql_trace off';
11g에서 추가된 새로운 진단 이베트 기능은 매우 강력해서 아래와 같이 SQL을 지정할 수도 있습니다. 너무나 유용한 기능이죠.
-- SQL_ID 얻어오고...
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;

col sql_id new_value sql_id1
select sql_id 
from v$sqlarea 
where sql_text = 'select /* sql_trace_4 */ count(*) from user_objects';

col sql_id new_value sql_id2
select sql_id 
from v$sqlarea 
where sql_text = 'select /* sql_trace_5 */ count(*) from user_objects';

-- 하나의 sql에 대해서
alter session set events 'sql_trace [sql: &sql_id1] wait=true';
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;
alter session set events 'sql_trace off';

-- 여러 개의 sql에 대해서
alter session set events 'sql_trace [sql: &sql_id1 | &sql_id2] wait=true';
select /* sql_trace_4 */ count(*) from user_objects;
select /* sql_trace_5 */ count(*) from user_objects;
alter session set events 'sql_trace off';
3. DBMS_MONITOR 패키지가 오라클이 공식적으로 추천하는 방법입니다. DBMS_MONITOR 패키지에서도 SQL을 특정할 수 있는 기능이 제공된다면 좋겠지만 개발자들이 아직 거기까지는 고려하지 못한 것 같습니다.
exec dbms_monitor.session_trace_enable(waits=>true);

select /* dbms_monitor */ count(*) from user_objects;

exec dbms_monitor.session_trace_disable;
4. DBMS_SYSTEM 패키지나 DBMS_SUPPORT 패키지같은 히든 패키지에서도 비슷한 기능을 제공합니다만, DBMS_MONITOR 패키지가 등장한 이상 필요가 없어졌죠.
col sid new_value sid
col serial# new_value se
select sid, serial# 
from v$session 
where sid = userenv('sid');

exec sys.dbms_system.set_ev(&sid, &se, 10046, 8, null);

select /* dbms_system */ count(*) from user_objects;

exec sys.dbms_system.set_ev(&sid, &se, 10046, 0, null);
SQL_ID 값을 이용해서 특정 SQL에 대해서만 진단 이벤트를 수행할 수 있는 기능이 특히 유용해보입니다. 오라클 11g의 확장된 진단 이벤트 기능은 아래 문서에 자세히 소개되어 있습니다.
저작자 표시
신고
Trackback 0 : Comments 4
  1. park1q 2010.09.30 12:33 신고 Modify/Delete Reply

    10G 이상에서는 v$session 보면 어떤 세션이 trace 중인가 하는 칼럼이 sql_trace sql_trace_binds, sql_trace_waits 등이 있어 알기 쉬운에..혹시 9i 에도 이걸 알수 있는 뭔가가 있을까요?

    • 욱짜 2010.09.30 13:42 신고 Modify/Delete

      저도 이 문제를 고민한 적이 있는데 뚜렷한 방법을 찾지 못해서 포기했었더랬습니다. 이후로도 아직 도움이 될만한 정보를 얻지 못하고 있어요.

  2. 물곰 2010.10.06 17:08 신고 Modify/Delete Reply

    해당 명령어로 Trace를 잡을 시 Trace파일의 Prefix를 지정할수 있는 방법은 없을까요?

    • 욱짜 2010.10.06 18:27 신고 Modify/Delete

      아마 질문의 의도가 SQL 트레이스가 동작하는 시점에 트레이스 파일의 Identifier(tracefile_identifier)를 바꾸는 것을 의미하시는 것 같습니다.

      제가 알기로는 아직 그런 기능은 없는 것 같습니다.

Write a comment


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


11g is better - 10046 Trace가 좋아졌다!!!

오라클 2008.10.20 16:56
Query를 튜닝하다면 보면
Oracle의 예측과 실제 수행  결과를 한눈에 비교해보고 싶을 때가 있다.

하지만 10046 Trace의 결과로는 그것을 알 수가 없다.
다음과 같이 실제 수행 결과만 출력되기 때문이다.


select count(*)
from t1
where c1 between 1 and 100

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          7          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=7 pr=0 pw=0 time=737 us)
    100   TABLE ACCESS FULL T1 (cr=7 pr=0 pw=0 time=429 us)


Oracle 10g부터는 GATHER_PLAN_STATISTICS라는 아름다운 Hint를 사용하면 예측과 실제를 한 눈에 비교할 수 있다.

select /*+ gather_plan_statistics */
  count(*)
from t1
where c1 between 1 and 100
;

--------------------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE    |      |      1 |      1 |            |      1 |00:00:00.01 |       7 |
|*  2 |   TABLE ACCESS FULL| T1   |      1 |    100 |     4   (0)|    100 |00:00:00.01 |       7 |
--------------------------------------------------------------------------------------------------

Oracle 11g부터는 10046 Trace에 예측 정보가 추가로 출력된다.
아래 결과를 보자.

select count(*)
from t1
where c1 between 1 and 100

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00       0.00          0         10         18           0
Fetch        2      0.00       0.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.01          0         18         18           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 88 

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=7 pr=0 pw=0 time=0 us)
    100   TABLE ACCESS FULL T1 (cr=7 pr=0 pw=0 time=2 us cost=3 size=300 card=100)

Row Source Operation에 Cost, Cardinality 등의 정보가 추가적으로 출력되는 것을 알 수 있다.

기쁘지 아니한가?


신고
Trackback 0 : Comment 0

Write a comment

티스토리 툴바