이 문서는 구루비에서 작성하였습니다.
이 문서를 다른 블로그나 홈페이지에 게재하실 경우에는 출처를 꼭 밝혀 주시면 고맙겠습니다.~^^
출처 : http://wiki.gurubee.net/pages/viewpage.action?pageId=20021332&
구루비 지식창고의 모든 문서는 크리에이티브 커먼즈의 저작자표시-비영리-동일조건변경허락(BY-NC-SA) 라이선스에 따라 자유롭게 사용할 수 있습니다.

오라클 성능 문제를 트러블슈팅하는 원리는 매우 간단하며, 그 원리를 현실세계에 적용하는 것도 어렵지 않음
그럼에도 불구하고 여전히 오라클 성능 문제를 트러블슈팅하는 것이 어렵게 느껴지는 것은 두 가지에서 기인함

가장 큰 원인은 성능 트러블슈팅의 기본개념 및 필수적인 툴에 대한 사용법이 체계적으로 정립되어 있지 않음
이런 기본기 위에 실제 현실 세계에서의 경험이 어느 정도 필요하다는 것임

책의 목적

오라클 성능 문제를 트러블슈팅하기 위해 어떤 개념을 이해해야 하는지
그 개념을 활용하기 위해 어떤 툴을 사용할 수 있어야 하는지
그것이 현실 세계의 성능문제와 어떻게 연결되는가를 다양한 사례를 통해 소개

오라클 성능 트러블슈팅에 필요한 기본개념 과 툴 소개

스냅샷과 프로파일링
SQL*Plus 스크립팅
딕셔녀리 뷰
진단 이벤트
덤프
PL/SQL 패키지
자바 저장 프로시져
정규식
oradebug

스냅샵과 프로파일링

질문

오라클 성능 트러블슈팅의 기본 중의 기본, 핵심 중의 핵심은 무엇일까?
필자가 생각하는 정답은 바로 데이터임

오라클 성능 문제를 트러블슈팅하는 과정은 필요한데이터를 체계적으로 수집하고, 수집한 데이터를 기반해서 문제를 해석하고 해결책을 찾는 일련의 과정임

질문

어떤 데이터를 어떻게 수집할 것인가 ?
데이터를 수집하는 체계적인 방법을 가장 먼저 정의 해야함 (필자: 스냅샷/ 프로파일링 데이터 로 분류)

오라클 성능 문제를 해석하는데 필요한 데이터를 분류하는 방법

분류	의미	예제
스냅샷 데이터	특정시점의 상태 데이터를 의미함	오늘 아침 10시에 V$SESSTAT뷰를 저장했다면, V$SESSTAT뷰에 대한 스냅샷 데이터를 가지고 있음
프로파일링(트레이스) 데이터	특정 구간에서 수행된 작업에 대한 데이터를 의미함	오늘 아침 10시부터 10시 10분까지 SQL*Trace를 수행했다면, 10분간의 프로파일링 데이터를 가지고있음

스냅샷 데이터는 공간적인 개념이며, 반면에 프로파일링 데이터는 시간적인 개념으로 이 두 가지 종류의 데이터를 합쳐야 완벽한 그림을 그릴수 있음

오라클이 제공하는 스냅샷/프로파일링 데이터를 정리

분류	종류	설명
스냅샷 데이터	대부분의 딕셔너리 뷰들	V$SESSTAT 뷰나 V$SESSION_WAIT뷰 와 같은 뷰들은 인스턴스의 현재상태에 대한 정보를 제공함
	AWR 뷰들	AWR이 제공하는 대부분의 뷰들은 특정 시점의 스냅샷 데이터들임 오라클은 한시간에 한번씩 데이터베이스의 전반적인 상태에 대한 스냅샷을 생성함 AWR 스냅샷은 많은 수의 뷰들에 대한 스냅샷 데이터로 구성되어 있음
	덤프 파일들	오라클이 제공하는 덤프 파일들은 대부분 스냅샷 데이터임 예를 들어 PGA 힙 덤프(PGA Heap Dump)는 PGA의 현재 상태를 나타내는 스냅샷 데이터임
프로파일링 데이터	진단 이벤트들	SQL문장의 수행시간 정보를 기록하는 10046진단 이벤트, 옵티마이저가 SQL문장을 최적화하는 과정을 기록하는 10053 진단 이벤트등 은 모두 프로파일링 데이터를 생성함 이들 데이터들은 프로세스가 하는 일을 시간 순으로 기록한 것들임
	매뉴얼 프로파일링	V$SESSION_WAIT 뷰 자체는 스냅샷 데이터에 해당함 하지만 이뷰를 반복적으로 액세스하면 마치 프로파일링을 수행한 것과 비슷한 효과를 얻을 수 있음

스냅샷/프로파일링 데이터에서 의미가 있는 정보를 얻는 방법

분류	방법	설명
스냅샷 데이터	차이(Delta) 값을 구함	특정 시점에서의 값 그 자체보다는 시점 A 와 시점 B 사이에 어떤 차이가 있는가가 핵심적인 데이터임 가령 Logical Reads가 얼마나 증가하는지, 리두크기는 얼마나 증가하는지 등의 데이터를 얻는 것이 중요함 AWR 리포트는 두 개의 스냅샷 간의 차이(Delta)값을 효과적으로 보여주는 것을 목적으로 함
프로파일링 데이터	집계(Summary)를 수행	프로파일링 데이터는 시간 순으로 모든 작업, 혹은 아주 많은 수의 작업을 기록함 이 많은 데이터를 일일이 확인하는 것은 어려우며 대신 효과적으로 집계를 함으로써 의미있는 정보를 얻게 됨 TKPROF 리포트를 사용해 보신 분이라면 그 의미를 직관적으로 이해하실수 있음

내용 요약

오라클 성능 트러블슈팅에 필요한 데이터는 스냅샷 데이터와 프로파일링 데이터로 나눌수 있음
스냅샷 데이터는 특정시점의 상태에 대한 데이터를 의미하며, 차이(Delta) 값을 통해서 의미있는 정보를 얻음
프로파일링 데이터는 특정 시간 구간 내의 작업에 대한 데이터를 의미하며, 집계(Summary)값을 통해 의미있는 데이터를 얻음

스냅샷 데이터

:간단한 형태의 스냅샷과 리포트

스냅샷 데이터와 리포트를 만드는 기본적인 방법

시점A 에서 스냅샷 A를 만듬
작업을 수행함
시점B에서 스냅샷B를 만듬
스냅샷B 와 스냅샷A의 차이(스냅샷B - 스냅샷A)를 얻음

스냅샷 데이터와 리포트를 만드는 간단한 예제

/**
 -- STEP1. 우선 다음과 같이 V$SYSSTAT뷰에 대한 스냅샷을 만듬
 --        1) V$SYSSTAT뷰의 내용을 테이블 SYSSTAT1에 저장함으로써 스냅샷을 만들수 있음
**/

SQL> create table sysstat1 as select * from v$sysstat;

테이블이 생성되었습니다.



-- STEP2. 그리고 ALL_OBJECTS뷰를 읽는 작업을 수행함

SQL> select count(*) from all_objects;

  COUNT(*)
----------
     60078



-- STEP3. 다음으로 두번째 스냅샷을 테이블 SYSSTAT2에 만듬

SQL> create table sysstat2 as select * from v$sysstat;

테이블이 생성되었습니다.



/**
 -- STEP4. 스냅샷 간의 차이 값이야말로 두 개의 스냅샷에 해당하는 구간(시간 스냅샷~ 끝 스냅샷)에서 어떤 일이 발생했는지를 말해주기 때문임
 --        1) 아래와 같이 두개의 스냅샷, 테이블 SYSSTAT2 와 SYSSTAT1간의 차이(Delta)값을 구함으로써 어떤 변화가 있었는지 알수 있음
 --        2) 아래의 스냅샷 리포트로부터 얻을수 있는 결론 중 하나는 ALL_OBJECTS 뷰를 읽는 작업에 의해 Physical Reads가 2M 바이트 이상 발생한다는 것임
 **/

SQL> -- get delta
SQL> col name format a40
SQL> col delta format 999,999,999,999
SQL> select s1.name , (s2.value - s1.value) as delta
  2  from sysstat1 s1, sysstat2 s2
  3  where s1.statistic# = s2.statistic#
  4  and (s2.value - s1.value) > 0
  5  order by 2 desc;


NAME                                                DELTA
---------------------------------------- ----------------
session pga memory max                         18,219,008
cell physical IO interconnect bytes             3,028,480
session uga memory max                          2,741,368
physical read total bytes                       2,383,872
physical read bytes                             1,564,672
file io wait time                                 665,853
physical write total bytes                        644,608
session pga memory                                196,608
session uga memory                                 80,680
index scans kdiixs1                                69,669
table scan rows gotten                             68,216
.... (중략)

성능트러블 슈팅을 위해서는 보다 많은 수의 뷰들에 대한 스냅샷 데이터가 필요하며, 어떤 뷰라도 성능 문제에 대한 데이터만 제공한다면 스냅샷의 대상이 될수 있음

V$SYSSTAT 뷰는 일량(Workload)에 대한 정보만을 제공함
V$SYSTEM_EVENT 뷰는 대기 이벤트에 대한 정보를 제공함
V$LATCH뷰는 래치활동에 대한 정보를 제공함

:AWR 스냅샷과 리포트

스냅샷 데이터에 대한 리포트 중 가장 광범위한 데이터를 제공하는 것이 AWR리포트임

AWR 스냅샷은 1시간마다 한번씩 자동으로 생성됨
하지만 DBMS_WORKLOAD_REPOSITORY패키지를 이용해서 수동으로 생성할수도 있음

AWR리포트를 생성하는 방법

시점A 에서 AWR스냅샷 A를 생성함
특정 작업을 수행함
시점B 에서 AWR스냅샷 B를 생성함
스냅샷B 와 스냅샷A 의 차이(스냅샷B - 스냅샷A)를 얻음

AWR스냅샷을 생성 후 스냅샷간의 차이값을 리포팅하는 예제


-- STEP1. DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT함수를 이용해 스냅샷A 를 만듬

SQL> -- 1st snapshot
SQL> col begin_snap new_value begin_snap;
SQL> col db_id new_value db_id;
SQL> col inst_num new_value inst_num;
SQL> select dbid as db_id from v$database;

     DB_ID
----------
  84928337



SQL> select instance_number as inst_num from v$instance;

  INST_NUM
----------
         1

SQL> select dbms_workload_repository.create_snapshot as begin_snap from dual;

BEGIN_SNAP
----------
         5

-- STEP2. ALL_OBJECTS뷰를 읽는 작업을 수행함

SQL> select count(*) from all_objects;

  COUNT(*)
----------
     60080



-- STEP3. 스냅샷 B를 만듬

SQL> -- 2nd snapshot
SQL> col end_snap new_value end_snap;
SQL> select dbms_workload_repository.create_snapshot as end_snap from dual;

END_SNAP
----------
         6



-- STEP4. DBMS_WORKLOAD_REPOSITORY.AWR_REPORT_TEXT[_HTML]함수를 이용해서 스냅샷 B와 스냅샷 A간의 차이점을 리포팅함

SQL> -- AWR report
SQL> select * from table(dbms_workload_repository.awr_report_text(&db_id, &inst_num, &begin_snap, &end_snap));

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

OUTPUT
--------------------------------------------------------------------------------

                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                                1          49.3
db file sequential read                  80           0      5   29.8 User I/O
control file sequential read             89           0      2   10.7 System I/O
db file scattered read                    4           0      3     .8 User I/O
Disk file operations I/O                  1           0      1     .1 User I/O
Host CPU (CPUs:    2 Cores:    2 Sockets:    1)

... (중략)

왜? 스냅샷은 다양한 방식으로 사용할수 있는 차이점이 존재하는가

어떤 뷰들을 스냅샷의 대상으로 할것인가?
스냅샷간의 차이 값을 어떻게 보여줄 것인가?

:덤프와 스냅샷

오라클 성능 트러블슈팅을 위해 필요한 스냅샷 데이터의 99%는 오라클이 제공하는 동적성능뷰(Dynamic Performanc View)에서 얻을수 있음
하지만 1% 정도의 문제에 대해서는 동적 성능 뷰만으로 부족한 경우가 있음 (빈도는 1%이지만 중요도로 10%이상이라고 생각됨)

PGA의 크기가 계속증가하면서 세션의 성능이 저하되는 현상

이 경우 V$SESSTAT뷰와 동적 성능 뷰를 통해서 얻을 수 있는 것은 PGA의 크기가 매 스냅샷마다 얼마나 증가하느냐임
동적성능뷰를 통하여 가령 1분 가격으로 5개의 스냅샷을 생성했는데, 각 스냅샷마다 PGA의 크기가 100M 바이트씩 증가(즉 각 스냅샷간의 차이값이 100M 바이트) 한다는 사실을 알수 있음
하지만 왜 크기가 증가하는지의 이유를 알수 없음
크기가 커졌다는 사실만 알 수 있고, 왜 크기가 증가했는지를 알 수없다면 트러블슈팅의 궁극적인 목적인 해결책을 만드는것이 불가능함

이런 경우에 사용할수 잇는 것이 PGA 힙 덤프임

PGA힙 덤프를 수행하는 예제


-- STEP1. PGA힙 덤프 수행
SQL> -- every dump is snapshot data!!!
SQL> alter session set events 'immediate trace name heapdump level 1';

세션이 변경되었습니다.

-- STEP2. 현재 프로세스의 PGA힙 정보가 트레이스 파일에 기록됨

HEAP DUMP heap name="pga heap"  desc=0BBC9830
 extent sz=0x206c alt=108 het=32767 rec=0 flg=3 opc=2
 parent=00000000 owner=00000000 nex=00000000 xsz=0xfff8 heap=00000000
 fl2=0x60, nex=00000000
EXTENT 0 addr=0D230008
  Chunk  d230010 sz=    65520    free      "               "
EXTENT 1 addr=0D220008
  Chunk  d220010 sz=     1628    freeable  "diag pga       "  ds=0CEE04C0
  Chunk  d22066c sz=     4164    freeable  "diag pga       "  ds=0CEE04C0
  Chunk  d2216b0 sz=     4164    freeable  "diag pga       "  ds=0CEE04C0
  Chunk  d2226f4 sz=     8224    freeable  "PLS PGA hp     "  ds=08AE8EA8
  Chunk  d224714 sz=     2096    freeable  "PLS PGA hp     "  ds=08AE8EA8
  Chunk  d224f44 sz=     8284    recreate  "PLS PGA hp     "  latch=00000000

PGA 힙 덤프와 같은 덤프 데이터는 가장 자세한 형태의 스냅샷 데이터라고 볼수 있음
이런 종류의 스냅샷 데이터는 지나치게 정밀하기 때문에 다른 종류의 스냅샷 데이터 처럼 차이(Delta)값을 구하는 것이 어려우며 큰 의미도없고 사용시 적절한 형태로 집계할 필요가 있음

프로파일링 데이터

:간단한 형태의 매뉴얼 프로파일링

프로파일링 데이터를 얻고 리포팅하는 기본적인 방법

프로파일링 대상이 되는 데이터(주로 딕셔너리 뷰)를 필요한 만큼 반복적으로 엑세스해서 읽음
위와 같이 읽은 데이터를 원본데이터로 이용할수 있음
원본데이터를 적절히 집계해서 리포팅함으로써 보다 의미있는 데이터를 얻을 수 있음

프로파일링 데이터와 리포트를 만드는 간단한 예제


-- STEP1. 세션#1 에서 ALL_OBJECTS뷰를 읽는 작업을 수행

SQL> -- session #1
SQL> exec dbms_application_info.set_client_info('session1');

PL/SQL 처리가 정상적으로 완료되었습니다.

SQL> select count(*) from all_objects;

  COUNT(*)
----------
     60080

-- STEP2. 세션#1 이 작업을 수행하는 동안 세션 #2로 부터 세션1이 어떤 대기 이벤트(WaitEvent)을 대기하는지 프로파일링하는게 예제의핵심
--        1) 우선 세션#2에서 세션#1의 세션아이디(SID)값을 얻음

SQL> -- session #2
SQL> col sid new_value sid
SQL> select sid from v$session where client_info = 'session1';

       SID
----------
        12

        
-- STEP3. 총 1,000회 걸쳐 V$SESSION_WAIT뷰를 반복적으로 읽으면서 대기 이벤트를 얻음
--        즉 대기 이벤트 정보를 프로파일링 함

SQL> set serveroutput on
SQL> declare
  2   v_sw   v$session_wait%rowtype;
  3  begin
  4   for idx in 1 ... 1000 loop
  5      begin
  6            select * into v_sw
  7            from v$session_wait
  8            where sid = &sid
  9            and state = 'WAITING';
 10
 11            dbms_output.put_line(
 12              'event = ' || v_sw.event ||
 13              ', seq# = '|| v_sw.seq#  ||
 14              ', p1 = ' || v_sw.p1 ||
 15              ', elapsed = ' ||
 16              trunc(v_sw.wait_time_micro/1000,2) || '(ms)');
 17
 18            exception when others then null;
 19
 20        end;
 21    end loop;
 22  end;
 23  /

-- STEP4. 그결과 아래와 같이 대기 이벤트 목록을 얻을 수 있음
--
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.68(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.76(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.84(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.91(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.99(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72756.07(ms)

V$SESSION_WAIT 뷰 자체는 스냅샷 데이터에 해당하지만, 그 뷰를 시간의 흐름에 따라 반복적으로 엑세스하면 프로파일링 데이터가됨
즉, 프로파일링 데이터는 스냅샷 데이터의 시간 확장판 이라고 할수 있음

프로파일링 데이터에 대해 대기이벤트를 기준으로 히트(Hit) 회수를 집계하는 방법


-- STEP1.우선 프로파일링 데이터를 저장할 테이블 SESSION_WAIT를 만듬

SQL> create table session_wait as select * from v$session_wait where 1=0;

테이블이 생성되었습니다.



-- STEP2. 세션#1 에 대해 대기 이벤트를 프로파일링하면서 그 결과를 테이블 SESSION_WAIT에 저장함

SQL> begin
  2   for idx in 1 .. 1000 loop
  3
  4            insert into session_wait
  5            select *
  6            from v$session_wait
  7            where sid = &sid
  8            and state = 'WAITING';
  9
 10            dbms_lock.sleep(0.001);
 11    end loop;
 12  end;
 13  /
구   7:           where sid = &sid
신   7:           where sid =         12

PL/SQL 처리가 정상적으로 완료되었습니다.



-- STEP3. 프로파일링 결과가 테이블에 저장되어 있기 때문에 다음과 같이 손쉽게 집계리포트를 만들수 있음
--        1) 집계(Summary)를 수행함으로써 어떤 대기 이벤트가 주로 발생했는지를 알수 있음

SQL> select event, count(*) as hits
  2  from session_wait
  3  group by event
  4  order by 2 desc;

EVENT                                                                  HITS
---------------------------------------------------------------- ----------
SQL*Net message from client                                            1000



-- STEP4. 위의 방법을 응용하면 테이블을 만들고 테이블에 INSERT하는 등의 번거로운 작업 없이 
--        하나의 쿼리로 동일한 결과의 리포트를 만들수 있음

SQL> select /*+ no_query_transformation ordered use_nl(w) */
  2         w.event, count(*) as hits
  3  from (select level from dual connect by level <= 50000) x,
  4       (select decode(state, 'WAITING', event, 'ON CPU') as event
  5        from v$session_wait
  6        where sid = &sid) w
  7  group by w.event
  8  order by 2 desc;

EVENT                                                                  HITS
---------------------------------------------------------------- ----------
SQL*Net message from client                                           50000

쿼리를 해석하는 방법

DUAL테이블에서 50,000 건을 읽는 뷰 X가 선행 테이블이 됨
뷰 X를 선행 테이블로 해서 V$SESSION_WAIT 뷰를 50,000번 반복적으로 읽으면서 프로파일링하고(Nested Loop Join 에 의해)
위와 같이 읽은 결과를 대기 이벤트 (w.event)별로 집계(Group By에 의해)함

위와 같은 효과를 얻기 위해서 다음과 같은 힌트를를 사용하여 SQL제어함

NO_QUERY_TRANSFORMATION 힌트를 사용해서 뷰 머지(View Merge)가 발생하는 것을 막음
뷰 머지가 발생하면 테이블의 조인 순서가 예상치 못하게 바뀔 수 있기 때문
ORDERED 힌트를 이용해서 뷰 X가 선행 테이블(아우터 테이블)이 되게함
USE_NL 힌트를 이용해서 루프 돌면서 반복적으로 후행 테이블(이너 테이블) V$SESSION_WAIT뷰 를 읽도록함

대기 이벤트별 대기 회수와 대기 시간도 어느정도 측정할수 있는 예제


-- STEP1. 대기 이벤트별 대기 회수와 대기 시간 측정가능 SQL작성

SQL> -- session2
SQL> col event format a30
SQL> with w as (
  2    select /*+ no_query_transformation ordered use_nl(w) */
  3           w.event
  4         , count(*) as hits
  5         , count(distinct seq#) as dist_waits
  6         , 5000 as total_hits
  7    from (select level from dual connect by level <= 50000) x
  8       , (select decode(state, 'WAITING', event, 'ON CPU') as event
  9               , decode(state, 'WAITING', seq#, 0) as seq#
 10          from v$session_wait
 11          where sid = &sid) w
 12    group by w.event
 13    order by 2 desc
 14  )
 15  select /*+ ordered */
 16         w.event
 17       , trunc(100*w.hits/w.total_hits,1) as wait_pct
 18       , trunc((t2.gt - t1.gt)*w.hits/w.total_hits/100,2) as wait_time
 19       , trunc((t2.gt - t1.gt)*w.hits/w.total_hits/w.dist_waits/100,3) as avg_wait_time
 20  from   (select dbms_utility.get_time as gt from dual) t1
 21       , w
 22       , (select dbms_utility.get_time as gt from dual) t2
 23  order by 2 desc;



-- STEP2. 아래에 그 결과가 있음

EVENT                            WAIT_PCT  WAIT_TIME AVG_WAIT_TIME
------------------------------ ---------- ---------- -------------
SQL*Net message from client          1000        4.1           4.1

쿼리를 해석하는 방법

V$SESSION_WAIT 뷰를 후행으로 해서 Nested Loops Join을 수행함으로써 반복적으로 프로파일링하게 됨
그리고 그결과를 대기 이벤트에 대해 집계함으로써 대기 이벤트별, 히트회수, 대기회수 등의 정보를 얻음
위의 작업을 수행하기 전 후에 각각 현재 시간을 얻음으로써 시작 시간과 끝 시간을 얻음
이렇게 얻은 정보를 잘 조합하면 대기 이벤트별 대기 시간을 추측할수 있음

위에서 소개한 프로파일링 기법은

V$SESSION_WAIT 뷰나 V$SESSION 뷰와 같은 매 순간마다 정보가 바뀌는 뷰들(즉, 스냅샷 데이터)에 대해서 최소한의 오버헤드로 가능한 많은 회수의 프로파일링 데이터를 얻고 이를 집계할수 있다는 점이 유용함
하지만 자주 엑세스한다고 하더라도 샘플링(Sampling)의 한계를 벗어나기 어렵다는 점도 명확히 인식해야함

:진단 이벤트와 프로파일링

매뉴얼 프로파일링 기법의 한계는 100% 완벽한 데이터(= 샘플링 데이터)가 아니라는 점이만, 오라클 자체적으로 제공하는 프로파일링 데이터는 이런제약사항이 없음

10046 진단 이벤트

10046 진단 이벤트의 정확한 목적은 SQL 수행의 각 단계별로 시간 정보를 얻는 것임

다른 용어로는 Extended SQL*Trace 라고부름

10046 진단 이벤트 정의

prompt> oerr 10046
"enable SQL statement timing"
// *Cause:
// *Action:

프로파일링 데이터는 시계열데이터이며, 이러한 요구사항을 가장 완벽하게 구현한 것이 10046 진단 이벤트임
아래와 같은 방법으로 대기 이벤트의 대기 시간까지 포함된 프로파일링 데이터를 얻을수 있음

10046 진단 이벤트에 의해 생성되는 프로파일링 데이터를 확인


-- STEP1. 10046 진단 이벤트를 활성화한 상태에서 쿼리를 수행함

SQL> alter session set events '10046 trace name context forever, level 8';
세션이 변경되었습니다.

SQL> select count(*) from all_objects;

  COUNT(*)
----------
     60081

SQL>
SQL> alter session set events '10046 trace name context off';
세션이 변경되었습니다.

/**
 -- STEP2. 10046 진단 이벤트에 의해 생성된 프로파일링 데이터는 서버 프로세스의 트레이스 파일에 기록됨
 --        아래 데이터를 보면 앞서 매뉴얼 프로파일링을 통해서 얻은 데이터와 거의 유사항 포멧으로 기록되는 것을 알 수 있음
 **/

PARSING IN CURSOR #4 len=32 dep=0 uid=52 oct=3 lid=52 tim=2454862187 hv=789896629 ad='220f54a4' sqlid='9tz4qu4rj9rdp'
select count(*) from all_objects
END OF STMT
PARSE #4:c=171601,e=256547,p=2,cr=258,cu=2,mis=1,r=0,dep=0,og=1,plh=1743485846,tim=2454862184
EXEC #4:c=0,e=150,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1743485846,tim=2454862732
WAIT #4: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=2454862904



/**
 -- STEP3. 프로파일링 데이터는 집계(Summary)를 통해서 의미있는 정보를 얻을수 있음
 --        10046 진단 이벤트에 의해 생성된 프로파일링 데이터는 TKPROF툴을 이용해 집계 리포트를 얻을수 있음
 **/

D:\app_db\engine_oracle\diag\rdbms\ora11gr2\ora11gr2\trace>tkprof ora11gr2_ora_1312.trc ora11gr2_ora_1312.out
TKPROF: Release 11.2.0.1.0 - Development on 금 3월 2 09:07:49 2012
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

D:\app_db\engine_oracle\diag\rdbms\ora11gr2\ora11gr2\trace>noetpad ora11gr2_ora_1312.out
SQL ID: 9tz4qu4rj9rdp
Plan Hash: 1743485846
select count(*) 
from
 all_objects


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.12       0.12          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      1.71       1.74          0      38115          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.84       1.87          0      38115          0           1

...(중략)

TKPROF는 Transient Kernel Profiler의 약자이며, Profiler라는 용어에 주목해야함
TKPROF가 다루는 데이터가 프로파일링 데이터라는 것을 스스로 말하고 있음

10053 진단 이벤트

10053 진단 이벤트는 옵티마이저가 최적화(Optimizer)를 수행하는 과정을 시간 순으로 기록함

즉, 쿼리최적화라는 작업을 프로파일링함

10053 진단 이벤트 정의

prompt> oerr  10053
"CBO Enable optimzier trace"
// *Cause:
// *Action:

진단 이벤트의 정의로부터 프로파일링을 수행한다는 것을 명확히 알수 있음

10053 진단 이벤트에 의해 생성되는 프로파일링 데이터를 확인


-- STEP1. 10053 진단 이벤트를 활성화한 상태에서 쿼리를 수행함

SQL> alter session set events '10053 trace name context forever, level 1';
세션이 변경되었습니다.

SQL> select count(*) from all_objects where rownum = 1;

  COUNT(*)
----------
         1

SQL> alter session set events '10053 trace name context off';
세션이 변경되었습니다.

-- STEP2. 그리고 트레이스 파일의 내용을 확인해보면 옵티마이저가 수행하는 일련의 작업이 시간순으로 기록된 것을 알수 있음
--        이런 데이터는 "왜 이런 실행계획이 만들어지는가?" 라는 의문을 해결할수 있는 가장 완벽한 정보를 제공함

SQL> @trace_file



-- STEP3. 10053 진단 이벤트에 의해 생성된 프로파일링 데이터(트레이스 파일)는 원본 데이터를 직접이용하는 것이 가장 보편적인 사용방법임
--        하지만 필요하면 집계를 통해서 원하는 데이터를 얻을수있음 
--        예를 들어 아래와 같은 방법으로 트레이스 파일로 부터 조인 회수를 구할 수 있음

select count(*)
from table(tpack.get_tracefile_contents(tpack.get_tracefile_name))
where column_value like 'Now joining%';

예외적인 데이터를

동적 성능 뷰(Dynamic Performance View)와 덤프 파일은 대부분 스냅샷 데이터에 해당하며, 진단이벤트는 프로파일링 데이터에 해당함
하지만 예외적인 데이터들이 있음

:액티브 세션 히스토리

V$ACTIVE_SESSION_HISTORY 뷰는 1초 간격으로 저장된 액티브 세션의 과거 목록을 가지고 있음
따라서 V$ACTIVE_SESSION_HISTORY 뷰는 동적 성능 뷰임에도 불구하고 프로파일링 데이터로 분류할수 있음

V$ACTIVE_SESSION_HISTORY 뷰로 확인되는 데이터를 확인


-- Note: 

SQL> -- v$active_session_history
SQL> col sid format 999
SQL> col sql_text format a20
SQL> col event format a10
SQL> col sid new_value sid
SQL> select  to_char(h.sample_time,'mi:ss') as sample_time
  2        , h.sample_id
  3        , h.session_id as sid
  4        , h.session_state as st
  5        , h.sql_id
  6        , (select sql_text from v$sqlarea a where a.sql_id = h.sql_id) as sql_text
  7        , event
  8        , blocking_session as blocker
  9  from    v$active_session_history h
 10  where   session_id = &sid
 11  ;
구  10: where   session_id = &sid
신  10: where   session_id =         12

SAMPL  SAMPLE_ID  SID ST      SQL_ID        SQL_TEXT             EVENT         BLOCKER
----- ---------- ---- ------- ------------- -------------------- ---------- ----------
44:30       8747   12 ON CPU  9tz4qu4rj9rdp select count(*) from
                                             all_objects

37:40       8338   12 ON CPU  25vwt55t1093f select to_clob(
                                                 restart||queue_
                                            schema||'.'||queue_n
                                            ame || '(' || queue_

... (중략)

스냅샷 데이터를 아주 빈번하게 엑세스하면 프로파일링 데이터가 된다는 원리가 가장 이상적으로 구현된 뷰가 V$ACTIVE_SESSION_HISTORY뷰라고 할수 있음

:콜 스택덤프

콜 스택 덤프는 특정 프로세스의 현재 시점에서의 함수 히스토리를 시간의 역순으로 출력하는 기능을 제공함

콜 스택 덤프 생성으로 확인되는 데이터를 확인


-- STEP1. 콜 스택 덤프 명령을 수행하면 트레이스 파일에 다음과 같이 함수 호출 히스토리가 출력됨

SQL> -- callstack data is snapshot + profiling
SQL> alter session set events 'immediate trace name callstack level 1';
세션이 변경되었습니다.



-- STEP2. 아래의 결과가 의미하는 것은 서버 프로세스가 현재의 명령을 처리하기 위해 
--        1) { 00000000 -> 76EA3779 -> _OracleThreadStart -> _opimai -> ... -> _ksedst_tracecb -> _skdstdst } 의 순서로 함수를 호출 중이라는 것을 의미함
--        2) 현재 호출 중인 가장 함수는 가중 위에 있는 _skdstdst  함수임

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
EnumerateLoadedModules64 failed with error -1073741819
_skdstdst()+121      CALLrel  _kgdsdst()           E8E9768 0
_ksedst1()+93        CALLrel  _skdstdst()          E8E9768 0 0 436646 435BE2
                                                   436646
_ksedst_tracecb()+5  CALLrel  _ksedst1()           0 0
4                                                  
_dbkdaKsdActDriver(  CALLreg  00000000             1
)+3615                                             
06E05165             CALLreg  00000000             DB40454 E8EAEA0
06E05D11             CALLrel  06E04E06             DB40454 5C0D830 20C0003
                                                   E8EAEA0 1
06DFE9A5             CALLrel  06E059F2             DB40454 DB4ECF4
075B4D0A             CALLrel  06DFE972             DB40454 DB4ECD8
_dbkdParseCmd()+395  CALLrel  _dbgdParseCmd()      DB40454 BC20380 E13FFD0
                                                   DB413C8 1D843C84 26 3 0 0
                                                   E8EB4FC
__VInfreq__kkyase()  CALLrel  _dbkdParseCmd()      1D843C84 26 3 E8EB4FC
+5166                                              
_kksExecuteCommand(  CALLrel  _kkyase()            1D843C74
)+1024                                             
_opiexe()+17037      CALLrel  _kksExecuteCommand(  E4902A0 2 E8ECA98
                              )                    
_kpoal8()+2109       CALLrel  _opiexe()            49 3 E8ECA98
_opiodr()+1248       CALLreg  00000000             5E 1C E8EF070
61AB29CD             CALLreg  00000000             5E 1C E8EF070 0
_opitsk()+1404       CALL???  00000000             BC2AC00 5E E8EF070 0 E8EED00
                                                   E8EF19C 53E52E 0 E8EF1C8
_opiino()+980        CALLrel  _opitsk()            0 0
_opiodr()+1248       CALLreg  00000000             3C 4 E8EFBC4
_opidrv()+1201       CALLrel  _opiodr()            3C 4 E8EFBC4 0
_sou2o()+55          CALLrel  _opidrv()            3C 4 E8EFBC4
_opimai_real()+124   CALLrel  _sou2o()             E8EFBD4 3C 4 E8EFBC4
_opimai()+125        CALLrel  _opimai_real()       2 E8EFBFC
_OracleThreadStart@  CALLrel  _opimai()            2 E8EFF3C 0 70 FFFFFFFF
4()+830                                            FFFFFFFF
752EED67             CALLptr  00000000             E7EFF6C E8EFFD4 76EA377B
                                                   E7EFF6C 787D2C88 0
76EA3779             CALLreg  00000000             E7EFF6C 787D2C88 0 0 E7EFF6C
                                                   0
76EA3749             CALLrel  76EA3754             401326 E7EFF6C 0 0 0 0
00000000             CALL???  00000000             
----- End of Call Stack Trace -----

이처럼 콜 스택 덤프의 결과는 스냅샷이면서 동시에 프로파일링 이기도 한 독특한 데이터임

만일 콜 스택 덤프를 여러 번 수행하면 여러 개의 콜 스택이 기록될 것이며, 콜 스택에 대한 프로파일링 데이터를 얻을수 있음
이 데이터를 분석하면 시간에 따라 콜 스택이 어떻게 변하는지, 어떤 콜 스택이 주로 사용되는지 알 수 있음

콜 스택를 여러번 수행하여 여러 개의 기록을 기반으로 프로파일링 데이터를 확인

SQL> select * from table(tpack.callstack_prof_report(&sid));

:10032 진단 이벤트

10046 진단 이벤트나 10053 진단 이벤트와 같이 진단 이벤트들은 주로 프로파일링 데이터를 얻는데 사용되지만 또 다른 많은 수의 진단 이벤트들은 현재 상태에 대한 정보를 얻는 목적으로 사용되기도함

예를들어 10032 진단 이벤트는 정렬작업에 대한 스냅샷 데이터를 얻는 목적으로 사용됨

10032 진단 이벤트 정의

prompt> oerr 10032
"sort statistics (SOR*)"
// *Cause:
// *Action:

10032 진단 이벤트에 의해 생성되는 스냅샷 데이터를 확인



-- STEP1. 10032 진단 이벤트를 활성화한 상태에서 쿼리를 수행함

SQL> -- 10032 trace 
SQL> ALTER SESSION SET EVENTS '10032 trace name context forever, level 10';
세션이 변경되었습니다.


SQL> select OWNER, count(*) from ALL_OBJECTS group by OWNER order by OWNER;

OWNER                            COUNT(*)
------------------------------ ----------
APPQOSSYS                               3
DBSNMP                                 57
EXFSYS                                187
MAZAL                                   3
OLAPSYS                               717
ORACLE_OCM                              8
OUTLN                                   8
PUBLIC                              24438
SYS                                 30447
SYSMAN                               3404
SYSTEM                                503
WMSYS                                 306


-- STEP3. 10032 진단 이벤트 결과를 확인
--        마치 V$SESSTAT뷰 처럼 현재 상태에 대한 스냅샷 데이터를 제공하고 있음

---- Sort Parameters ------------------------------
sort_area_size                    65536
sort_area_retained_size           65536
sort_multiblock_read_count        1
max intermediate merge width      3
---- Sort Statistics ------------------------------
Input records                             60081
Output records                            12
Total number of comparisons performed     150601
  Comparisons performed by in-memory sort 150601
Total amount of memory used               2048
Uses version 1 sort
---- End of Sort Statistics -----------------------

진단 이벤트가 제공하는 데이터의 다양성을 소개하기 위해서 10032 진단 이벤트를 예제로 다룸

Oracle Event Reference

원문URL : https://netfiles.uiuc.edu/jstrode/www/oraparm/EventReference.html#10013

문서에 대하여

최초작성일 : 2012년 03월 01일
이 문서는 오라클클럽 오라클 성능 트러블슈팅의 기초 스터디 모임에서 작성하였습니다.
이 문서의 내용은 엑셈(EXEM) 에서 출간한 '오라클 성능 트러블슈팅의 기초'를 참고하였습니다.

문서정보

이 문서는 구루비에서 작성하였습니다.
이 문서를 다른 블로그나 홈페이지에 게재하실 경우에는 출처를 꼭 밝혀 주시면 고맙겠습니다.~^^
출처 : http://wiki.gurubee.net/pages/viewpage.action?pageId=20021332&
구루비 지식창고의 모든 문서는 크리에이티브 커먼즈의 저작자표시-비영리-동일조건변경허락(BY-NC-SA) 라이선스에 따라 자유롭게 사용할 수 있습니다.

스냅샷과 프로파일링