꿈꾸는 개발자, DBA 커뮤니티 구루비

프로파일링 데이터

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

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

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

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



-- 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%';