1. 대기 이벤트 프로파일링
    1. V$ACTIVE_SESSION_HISTORY
    2. V$SESSION_WAIT 뷰 샘플링
    3. 트레이스 파일 이용

대기 이벤트 프로파일링

  • V$SESSION_EVENT 뷰, TKPROF 리포트가 제공하는 집계 리포트의 문제점 : 자신만의 입맛에 맞게 대기 정보를 분석할 수 없다.
    예) I/O 와 관련된 대기 이벤트들에 대해서 P1(파일 번호) 별로 대기 회수와 대기 시간을 집계하고자 할 경우
  1. V$ACTIVE_SESSION_HISTORY 뷰 사용
  2. V$SESSION_WAIT 뷰 직접 샘플링
  3. 대기 이벤트가 포함된 SQL 트레이스 이용
  • 1, 2 방법은 세션#1 에서 작업을 수행하면서 해당 뷰를 조회함.
    3 방법은 트레이스 설정 후 작업을 수행한 후 tkprof 로 가공되지 않은 트레이스 파일을 조회함.

V$ACTIVE_SESSION_HISTORY

  • 액티브 세션의 목록을 1초에 한번씩 샘플링한 데이터
  • V$SESSION_WAIT(V$SESSION) 뷰를 1초에 한번씩 샘플링한 것과 동일한 효과를 얻을 수 있음.

세션#1 : ALL_OBJECTS 뷰를 조회하는 간단한 작업 수행


SQL> exec dbms_application_info.set_client_info('SESSION1');

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

SQL> alter system flush buffer_cache;

시스템이 변경되었습니다.

SQL> select count(*) from all_objects;

  COUNT(*)
----------
     68227

세션#2


-- 세션#1 분석을 위한 세션 아이디를 얻어둠
SQL> col sid new_value sid
SQL> select sid from v$session where client_info = 'SESSION1';

       SID
----------
       122

SQL> col event format a30
SQL> col sql_id format a13
SQL> select * from (
  2      select to_char(sample_time, 'hh24:mi:ss'),
  3             session_id,
  4             session_state,
  5             sql_id,
  6             event,
  7             p1
  8      from   v$active_session_history
  9      where  session_id = &sid
 10      order by sample_time desc
 11  ) where rownum <= 10;
구   9:     where  session_id = &sid
신   9:     where  session_id =        122

TO_CHAR( SESSION_ID SESSION SQL_ID        EVENT                                  P1
-------- ---------- ------- ------------- ------------------------------ ----------
00:10:39        122 ON CPU  9tz4qu4rj9rdp                                         1
00:10:38        122 ON CPU  4c1xvq9ufwcjc                                         1
00:10:37        122 ON CPU  fjdh242qfjfr6                                         1
00:10:36        122 ON CPU  4c1xvq9ufwcjc                                         1
00:10:35        122 ON CPU  fjdh242qfjfr6                                         1
00:10:34        122 ON CPU  fjdh242qfjfr6                                         1
00:10:33        122 ON CPU  fjdh242qfjfr6                                         1
00:10:32        122 WAITING 4c1xvq9ufwcjc db file sequential read                 2
00:10:31        122 ON CPU  9tz4qu4rj9rdp                                         1
00:10:30        122 ON CPU  9tz4qu4rj9rdp                                         1

10 개의 행이 선택되었습니다.

  • 단점 : 샘플링의 구간이 너무 길다는 것(1초)

V$SESSION_WAIT 뷰 샘플링


SQL> select /*+ ordered use_nl(w) */
  2         sid,
  3         event,
  4         p1,
  5         count(*) as wait_hits
  6  from  (select /*+ no_merge */ level as lvl from dual connect by level <= 10000),
  7        (select /*+ no_merge */
  8                sid,
  9                decode(state, 'WAITING', event, 'ON CPU') as event,
 10                decode(state, 'WAITING', seq#, 0) as seq#,
 11                decode(state, 'WAITING', p1, null) as p1,
 12                decode(state, 'WAITING', p2, null) as p2,
 13                decode(state, 'WAITING', p3, null) as p3
 14         from v$session_wait
 15         where sid = &sid
 16         ) w
 17  where sid = &sid
 18  and  (event like '%%' or event = 'ON CPU')
 19  group by sid, event, p1
 20  order by count(*) desc
 21  ;
구  15:        where sid = &sid
신  15:        where sid =        122
구  17: where sid = &sid
신  17: where sid =        122

       SID EVENT                                  P1  WAIT_HITS
---------- ------------------------------ ---------- ----------
       122 ON CPU                                          7289
       122 db file sequential read                 1       2711

more advanced version


col cur_time new_value cur_time
select dbms_utility.get_time as cur_time from dual;

-- 1초
SQL> define how_long = 1
SQL> select /*+ NO_QUERY_TRANSFORMATION */
  2         sid,
  3         event,
  4         p1,
  5         trunc(100*(wait_hits/(max(total_hits) over())),1) as wait_pct,
  6         trunc(1000*&how_long*(wait_hits/(max(total_hits) over())),1) as wait_time,
  7         trunc(1000*&how_long*((wait_hits/dist_waits)/(max(total_hits) over())),1) as avg_wait_time
  8  from  (select /*+ orderd use_nl(w) */
  9                sid,
 10                event,
 11                p1,
 12                count(*) as wait_hits,
 13                max(lvl) as total_hits,
 14                count(distinct seq#) as dist_waits
 15         from  (select /*+ no_merge */
 16                       level as lvl
 17                from   dual connect by level <= 100000000000
 18                and   (dbms_utility.get_time - &cur_time) <= 100*&how_long) t1,
 19               (select /*+ no_merge */
 20                       sid,
 21                       decode(state, 'WAITING', event, 'ON CPU') as event,
 22                       decode(state, 'WAITING', seq#, 0) as seq#,
 23                       decode(state, 'WAITING', p1, null) as p1,
 24                       decode(state, 'WAITING', p2, null) as p2,
 25                       decode(state, 'WAITING', p3, null) as p3
 26                from v$session_wait
 27                where sid = &sid
 28                ) w
 29         where (event like '%%' or event = 'ON CPU')
 30         group by sid, event, p1
 31         order by count(*) desc
 32         )
 33  ;
구   6:        trunc(1000*&how_long*(wait_hits/(max(total_hits) over())),1) as wait_time,
신   6:        trunc(1000*1*(wait_hits/(max(total_hits) over())),1) as wait_time,
구   7:        trunc(1000*&how_long*((wait_hits/dist_waits)/(max(total_hits) over())),1) as avg_wait_time
신   7:        trunc(1000*1*((wait_hits/dist_waits)/(max(total_hits) over())),1) as avg_wait_time
구  18:               and   (dbms_utility.get_time - &cur_time) <= 100*&how_long) t1,
신  18:               and   (dbms_utility.get_time -    1497348) <= 100*1) t1,
구  27:               where sid = &sid
신  27:               where sid =        122

       SID EVENT                                  P1   WAIT_PCT  WAIT_TIME AVG_WAIT_TIME
---------- ------------------------------ ---------- ---------- ---------- -------------
       122 ON CPU                                          75.2      752.1         752.1
       122 db file sequential read                 1       17.8        178           2.5
       122 db file scattered read                  1        6.9       69.8          17.4
       

  • 대기 이벤트가 포함된 SQL 트레이스에 비해 그 정확도는 떨어지지만, 분석 대상이 되는 세션의 성능에 영향을 주지 않고 데이터를 얻을 수 있다는 장점이 있음.

트레이스 파일 이용

  • 해당 세션의 성능을 저하시킬 수 있지만 가장 완벽한 정보를 제공함.
  • 작업 순서 : 트레이스 활성화 -> 작업 수행 -> 트레이스 비활성화 -> 트레이스 파일을 읽고 정규식을 사용하여 원하는 패턴의 데이터를 찾아서 집계

-- 트레이스 활성화
SQL> exec dbms_monitor.session_trace_enable(waits=>true);

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

-- 작업 수행
SQL> select count(*) from all_objects;

  COUNT(*)
----------
     68227

SQL> exec dbms_monitor.session_trace_disable;

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

-- 정규식을 이용하여 각 라인에서 {대기이벤트, 대기 시간, Pl, P2, P3, 오브젝트 번호} 정보를 얻을 수 있음.
SQL> select regexp_replace(
  2  'WAIT #11: nam=''asynch descriptor resize'' ela= 5 outstanding #aio=0 current aio limit=-1 new aio limit=357 obj#=118 tim=278440630732',
  3  '[[:print:]]+nam=''([[:print:]]+)''[[:space:]]+ela=[[:space:]]*([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=-*([[:
digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]]obj#=[[:space:]]*([[:digit:]]+)[[:space:]]tim=[[:digit:]]+',
  4  '\1.\2.\3.\4.\5.\6')
  5  from dual;

REGEXP_REPLACE('WAIT#11:NAM=''ASYNCHDE
--------------------------------------
asynch descriptor resize.5.0.1.357.118

-- UTL_FILE 패키지를 이용하여 트레이스 파일을 읽는 GET_TRACE_FILE1 함수 정의

SQL> col value new_value user_dump_directory;

-- 트레이스 파일이 저장되는 물리적 위치를 조회
SQL> select value from v$parameter where name = 'user_dump_dest';

VALUE
----------------------------------------------------------------------------------------------------
d:\app\administrator\diag\rdbms\orcl\orcl\trace

-- 물리적 위치에 접근하기 위한 디렉토리 객체 생성
SQL> create or replace directory user_dump_dir as '&user_dump_directory';
구   1: create or replace directory user_dump_dir as '&user_dump_directory'
신   1: create or replace directory user_dump_dir as 'd:\app\administrator\diag\rdbms\orcl\orcl\trace'

디렉토리가 생성되었습니다.

SQL> create or replace type varchar2_array as table of varchar2(4000);
  2  /

유형이 생성되었습니다.

-- 트레이스 파일을 읽어들일 함수 생성
SQL> create or replace function get_trace_file1(s_id number default userenv('sid'))
  2  return varchar2_array
  3  pipelined
  4  as
  5      v_handle utl_file.file_type;
  6      v_filename varchar2(2000);
  7      v_line     varchar2(4000);
  8  begin
  9      -- 트레이스 파일명 조회
 10      select i.value||'_ora_'||p.spid||decode(t.value, null, '', '_'||t.value)||'.trc' into v_filename
 11      from   v$process p
 12           , v$session s
 13           ,(select value from v$parameter where name = 'instance_name') i
 14           ,(select value from v$parameter where name = 'tracefile_identifier') t
 15      where  p.addr = s.paddr
 16      and    s.sid  = s_id
 17      ;
 18
 19      v_handle := utl_file.fopen('USER_DUMP_DIR', v_filename, 'R', 32767);  -- 트레이스 파일 오픈
 20
 21      loop
 22          begin
 23              utl_file.get_line(v_handle, v_line);  -- 한줄씩 읽어들임
 24          exception
 25              when no_data_found then
 26                  exit;
 27          end;
 28
 29          pipe row(v_line);
 30      end loop;
 31
 32      utl_file.fclose(v_handle);
 33
 34      return;
 35  end;
 36  /

함수가 생성되었습니다.

-- 함수를 사용하여 트레이스 파일을 읽어들인 후 정규식을 사용하여 원하는 패턴의 데이터를 찾고 가공함
SQL> select event
  2       , p1
  3       , trunc(sum(ela)/1000000, 1) as wait_time
  4  from  (select regexp_replace(line, '([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)', '\1') as event           -- asynch descriptor resize
  5              , to_number(regexp_replace(line, '([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)', '\2')) as ela  -- 5
  6              , to_number(regexp_replace(line, '([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)\.([[:print:]]+)', '\3')) as p1   -- 0
  7         from  (select regexp_replace(column_value, '[[:print:]]+nam=''([[:print:]]+)''[[:space:]]+ela=[[:space:]]*([[:digit:]]+)[[:space:]][[:prin
t:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=-*([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]]obj#=-*[[:space:]]*([[:digit:]]+)[[:space
:]]tim=[[:digit:]]+',
  8                                                    '\1.\2.\3.\4.\5.\6') as line  -- 정규식을 사용하여 변형함 => asynch descriptor resize.5.0.1.357.118
  9                from   table(get_trace_file1)  -- get_trace_file1 함수를 사용하여 트레이스 파일을 읽어들임
 10                where  column_value like 'WAIT #%'
 11                )
 12         )
 13  group by event, p1
 14  ;

EVENT                                  P1  WAIT_TIME
------------------------------ ---------- ----------
db file scattered read                  2          0
SQL*Net message from client    1111838976          0
db file sequential read                 2         .1
db file scattered read                  1         .2
SQL*Net message to client      1111838976          0
db file sequential read                 1         .7

6 개의 행이 선택되었습니다.