by-nc-sa     개발자, DBA가 함께 만들어가는 구루비 지식창고!

03. 재현 가능한 문제의 분석




  • 효율적인 접근 방법 : Trace, Profiling 기능 활용
  • 문제 분류
    • SQL 처리 시간 많음
    • PL/SQL 처리 시간 많음
    • DBMS 가 Idle 상태 (외부병목)

3.1 데이터베이스 호출 트레이스

  • DB 계층이 병목 이라면 DB 와 AP 간 상호작용을 분석
    • SQL 트레이스 : SQL 구문 목록, SQL 실행 관련 성능 수치 제공
  • DB Trace 필수 단계
    1. SQL 트레이스 활성화
    2. 트레이스 파일 찾기
    3. 트레이스 파일에서 관련 정보 추출
    4. 프로파일러 수행
    5. 프로파일러 결과 해석

3.1.1 SQL 트레이스

  • SQL 엔진은 Parse, Execute, Fetch 를 실행
    • CPU를 사용하여 특정 처리 수행
    • 다른 자원을 사용 (예: 디스크)
    • 동기화 지점 거침 (예: 래치)
  • SQL 트레이스 목적
    • 응답시간의 서비스/대기 시간 분리
    • 사용된 자원, 동기화 작업의 상세 정보 제공
  • TKPROF 로 추출할 수 있는 정보
    • SQL 텍스트, 일부 실행 통계, 처리시 발생한 대기 이벤트, 파싱 단계 정보, 실행 계획
    • 실행 SQL 및 재귀 SQL 모두 정보 제공
  • SQL 트레이스는 10046 디버깅 이벤트 기반
    레벨 설명
    0 비활성화
    1 디버깅 활성화, DB 호출, SQL 구문, 응답/서비스 시간, 처리 Row수, 논리/물리 읽기/쓰기, 실행계획
    4 레벨1 + 바인드 변수 정보
    8 레벨1 + 대기시간 정보
    16 레벨1 + 실행 계획의 STAT 정보
    32 레벨1 - 실행 계획 정보
    64 레벨1 + 특정 커서가 1분 이상 DB 시간 소요 시 실행 계획의 STAT 정보
  • 레벨?
    • 레벨 4 부터 확장 SQL 트레이스
    • 레벨 조합 가능 : 레벨12 = 레벨4 + 레벨8
디버깅 이벤트
  • 실행 중 DB 엔진 프로세스에 플래그 설정 수단 (프로세스 동작 방식 변경 수단)
  • 오라클 지원 혹은 완전한 이해 하에서 사용
SQL 트레이스 활성화: ALTER SESSION 구문
-- LEVEL 1
ALTER SESSION SET sql_trace = TRUE

-- LEVEL 12
ALTER SESSION SET events '10046 trace name context forever, level 12'

-- 비활성화
ALTER SESSION SET events '10046 trace name context off'

-- ALTER SYSTEM 도 가능 : 큰 오버헤드, 명령 이후 생성된 세션만 동작
SQL 트레이스 활성화: DBMS_MONITOR 패키지
  • 세션 속성(식별자, 서비스명, 모듈명, 액션명)에 따라 SQL 트레이스 적용 가능
    • 커넥션 풀 환경에서 유용
      파라미터 트레이스 레벨 기본값
      BINDS 4 FALSE
      WAITS 8 TRUE
      PLAN_STAT(ALL_EXECUTIONS) 16 NULL(FIRST_EXECUTION)
      PLAN_STAT(NEVER) 32 NULL(FIRST_EXECUTION)
      - 64  
세션 레벨
-- session_id, serial_num 미 지정시 현재 세션 적용
dbms_monitor.session_trace_enable(session_id => 127, serial_num => 29, waits => TRUE, binds => FALSE, plan_stat => 'first_execution');
dbms_monitor.session_trace_disable(session_id => 127, serial_num => 29);
  • SQL 트레이스 활성화 확인 : v$session.(sql_trace, sql_trace_waits, sql_trace_binds, sql_trace_plan_stats)
    • 적어도 하나의 SQL 구문 실행 후 값 제공
  • RAC 에서는 타겟 세션이 위치한 인스턴스에서 시행
클라이언트 레벨
-- v$session.client_identifier 가 "helicon.antognini.ch' 설정 된 모든 세션 적용 (RAC 에서 모든 인스턴스 대상, DB 재시작 시 설정 지속)
-- 대상 세션 조회 : dba_enabled_traces
dbms_monitor.client_id_trace_enable(client_id => 'helicon.antognini.ch', waits => TRUE, binds => TRUE, plan_stat => 'first_execution');
dbms_monitor.client_id_trace_disable(client_id => 'helicon.antognini.ch');
컴포넌트 레벨
-- 기본값 없음 : service_name
-- 기본값 있음 : module_name (any), action_name (any), instance_name (any)
dbms_monitor.serv_mod_act_trace_enable(service_name => 'DBM11203.antognini.ch', module_name => 'mymodule', action_name => 'myaction', waits => TRUE, binds => TRUE, plan_stat => 'all_execution');
dbms_monitor.serv_mod_act_trace_disable(service_name => 'DBM11203.antognini.ch', module_name => 'mymodule', action_name => 'myaction');

-- dba_enabled_traces.trace_type  : SERVICE, SERVICE_MODULE, SERVICE_MODULE_ACTION
데이터베이스 레벨
-- 모든 파라미터 기본 값 있음, 다른 레벨에서 enable 한 세션은 영향 못줌
dbms_monitor.database_trace_enable(waits => TRUE, binds => TRUE, instance_name => 'DBM11203', plan_stat => 'first_execution');
dbms_monitor.database_trace_disable(instance_name => 'DBM11203');
SQL 트레이스 활성화: DBMS_SESSION 패키지
-- 현재 세션 전용
dbms_session.session_trace_enable(waits => TRUE, binds => TRUE, plan_stat => 'all_executions');
dbms_session.session_trace_disable;
트리거에서 SQL 트레이스 활성화 하기
CREATE ROLE sql_trace;

CREATE OR REPLACE TRIGGER enable_sql_trace AFTER LOGON DATABASE
BEGIN
  IF (dbms_session.is_role_enabled('SQL_TRACE'))
  THEN
    EXECUTE IMMEDIATE 'ALTER SESSION SET timed_statistics = TRUE';
	EXECUTE IMMEDIATE 'ALTER SESSION SET max_dump_file_size = unlimited';
	dbms_monitor.session_trace_enable;
  END IF;
END;

-- ALTER SESSION, sql_trace 권한 부여
-- 대안 : AP 에서 파라미터에 따라 SQL 트레이스 직접 수행
트레이스 파일에 시간 정보 포함시키기
  • timed_statistics = TRUE
    • 경과시간(elapsed_time) 및 CPU시간(cpu_time) 관찰 가능
  • 설정 방법
    -- statistics_level = basic 이면 FALSE typical/all 이면 TRUE
    ALTER SESSION SET timed_statistics = TRUE;
    
동적 초기화 파라미터
  • 정적(static), 동적(dynamic) 파라미터 존재
  • 동적 : 인스턴스 재시작 불필요 (시스템, 세션 레벨) - v$parameter 뷰 확인 가능
트레이스 파일의 크기 제한하기
-- K, M 설정 가능, 초과 시 ORA-48913 발생
ALTER SESSION SET max_dump_file_size = 'unlimited';
트레이스 파일 찾기
  • 10.2 버전
    • user_dump_dest : dedicated 서버 프로세스
    • background_dump_dest : background 서버 프로세스 (v$bgprocess 에 모두 나타나지 않음)
  • 11.1 버전 - ADR(Automatic Diagnostic Repository) 도입
    • diagnostic_dest + v$diag_info
    • v$process.tracefile
  • 트레이스 파일 이름
    • (instance_name)(process name)(process id)_(tracefile identifier).trc
      • (process name) : 프로세스 소문자 이름(v$shared_server.name, v$bgprocess.name), dedicated 서버 프로세스는 ora 적용
      • (process id) : 시스템 레벨 PID (v$process.spid, 윈도우는 스레드 ID)
      • (tracefile identifier) : 옵션, 최대 255자 식별자, 세션 레벨 파라미터 (v$process.traceid)
트레이스 파일 내 기밀 정보
  • 기본적으로 DB내 모든 데이터가 트레이스 파일에 기록될 수 있음
  • _trace_files_public = FALSE (TRUE 설정 시 0640 → 0644)

3.1.2 트레이스 파일의 구조(p.91)

  • 특정 프로세스에서 실행한 데이터베이스 호출 정보 저장
  • OS PID 재할당 시 기존 파일 사용 - 한개 파일에 여러 프로세스 정보 저장
  • 여러 세션이 하나의 프로세스 사용 가능 (공유 서버, 병렬 슬레이브 프로세스)
  • 세션 속성(모듈명, 액션명)에 따라 트레이서 파일 내 논리적 섹션 구분 됨(***)

3.1.3 TRCSESS

  • 트레이스 파일 일부 추출(통합) 도구
    trcsess [output=<output file name>] [session=<session ID>] [clientid=<clientid>] [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>
    

3.1.4 프로파일러

  • TKPROF (Trace Kernel PROFiler) - 오라클 제공, 언제든 사용 가능
  • 저자 제작 : TVD$XTAT
  • 고려 대상 : OraSRP, Method R Profiler, Method R Tools suite, Trace Analyzer(오라클 제공)

3.1.5 TKPROF

tkprof DBM11106_ora_6334.trc DBM11106_ora_6334.txt sys=no sort=prsela,exeela,fchela
TKPROF 인수 (p.96)
인수 의미 비고
explain 트레이스 내 SQL 에 대한 예상 실행 계획 생성  
table plan_table 지정 미 지정시 prof$plan_table 생성/제거
print 출력 파일에 포함되는 SQL 수 제한 미 지정시 무제한
aggregate 동일 텍스트 SQL 처리(YES:집계, NO:개별) 11.2 부터 실행계획 까지 동일하면 집계
insert 분석 결과를 DB에 저장하는 SQL 스크립트 출력 파일명  
sys SYS 유저에 의해 실행되는 재귀 SQL 포함 여부(기본값:YES) 제어 불가 영역이므로 NO 권장
record 트레이스 파일내 비재귀 SQL 출력 파일명 바인드 변수 처리 불가
waits 대기 이벤트 정보 추가 여부(기본값:YES)  
sort 출력 파일 SQL 기록 순서(기본값:트레이스 파일 내 순서 유지), 여러 옵션 지정시 합산 처리 권장: sort=prsela,exeela,fchela
TKPROF 출력 해석하기
  • 예제
    tkprof DBM11203_ora_28030.trc DBM11203_ora_28030.txt sort=prsela,exeela,fchela print=4 explain=chris//ian aggregate=no
    
  • 헤더
    TKPROF: Release 11.2.0.3.0 - Development on Fri Nov 30 23:45:57 2012
    
    Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.
    
    Trace file: DBM11203_ora_28030.trc
    Sort options: prsela  exeela  fchela  
    ********************************************************************************
    count    = number of times OCI procedure was executed
    cpu      = cpu time in seconds executing 
    elapsed  = elapsed time in seconds executing
    disk     = number of physical reads of buffers from disk
    query    = number of buffers gotten for consistent read
    current  = number of buffers gotten in current mode (usually for update)
    rows     = number of rows processed by the fetch or execute call
    --------------------------------------------------------------------------------
    
    *** SESSION ID:(156.29) 2012-11-30 23:21:45.691
    
    ********************************************************************************
    
  • 헤더 뒤 모든 SQL 에 대한 텍스트, 실행 통계, 파싱 정보, 실행 계획, 대기 이벤트 정보 출력
  • 실행 통계
    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    10001      6.49      11.92      71499      38474          8     1000000
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total    10003      6.49      11.92      71499      38474          8     1000000
    
  • 항목 설명
    항목 설명 비고
    count DB 호출 횟수  
    cpu 호출 처리에 소요된 총 CPU 시간(초)  
    elapsed 호출 처리에 소요된 총 경과 시간(초)  
    disk 물리 읽기 블록 수 disk > query + current : Temp Tablespace 읽음
    query 논리(consistent) 읽기 블록 수  
    current 논리(current) 읽기 블록 수  
    rows 처리(페치)된 로우의 수 예제는 한번에 100 개 로우 페치
  • 파싱 정보
    • LINE 1~2 : 파싱(parse) 과 실행(execute) 단계 발생 하드 파싱 횟수
    • LINE 3~4 : 옵티마이저 모드와 파싱한 유저 (유저명은 explain 인수 지정시 표시)
    • LINE 5 : 재귀 호출 정보 (예제는 PL/SQL로 호출)
      Misses in library cache during parse: 1
      Misses in library cache during execute: 1
      Optimizer mode: ALL_ROWS
      Parsing user id: 34  (CHRIS)   (recursive depth: 1)
      
  • 실행 계획
    • 처음 : Row Source Operation - 서버 프로세스에 의해 기록된 실행 계획
      • 반환 로우 수[처음, 평균, 최대] 제공 - 대상 실행 계획 건수 포함
        • 런타임 통계 제공 (자식 오퍼레이션 값이 포함 됨, 첫 실행 값 표시 / 11.2.0.2 부터 평균 값 표시)
          항목 설명 비고
          cr 논리(consistent) 읽기 블록 수  
          pr 물리 읽기 블록 수 Temp Tablespace 읽기 33,036 블록 = 71,499 - 38,463
          pw 물리 쓰기 블록 수  
          time 오퍼레이션 처리 총 경과시간(단위: 마이크로초 - 1/1,000,000 초) 샘플링으로 부정확할 수 있음
          cost 오퍼레이션 비용 추정 값 11.1 부터 제공, 누적값 아님
          size 오퍼레이션 반환 예상 데이터 양 11.1 부터 제공
          card 오퍼레이션 반환 예상 로우 수 11.1 부터 제공
    • 나중 : Execution Plan - explain 인수에 의해 TKPROF 가 생성
      Number of plan statistics captured: 1
      
      Rows (1st) Rows (avg) Rows (max)  Row Source Operation
      ---------- ---------- ----------  ---------------------------------------------------
         1000000    1000000    1000000  SORT ORDER BY (cr=38474 pr=71499 pw=33035 time=11123996 us cost=216750 size=264000000 card=1000000)
         1000000    1000000    1000000   TABLE ACCESS FULL T (cr=38474 pr=38463 pw=0 time=5674541 us cost=21 size=264000000 card=1000000)
      
      
      Rows     Execution Plan
      -------  ---------------------------------------------------
            0  SELECT STATEMENT   MODE: ALL_ROWS
      1000000   SORT (ORDER BY)
      1000000    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'T' (TABLE)
      
  • 대기 이벤트
    항목 설명 비고
    Times Waited 대기 이벤트 발생 횟수  
    Max, Wait 최대 대기시간(초)  
    Total Waited 총 대기시간(초)  
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                         2        0.00          0.00
      db file scattered read                        530        0.06          2.79
      direct path write temp                      11002        0.00          0.51
      direct path read temp                       24015        0.00          2.41
    --------------------------------------------------------------------------------
    
  • 집계된 대기 이벤트 정보
  • 총 경과시간 - CPU 시간 = SUM(Total Waited) + <계측되지 않은 시간>
계측되지 않은 시간
  • 실제 경과시간과 트레이스 파일 내 계측 시간 차이
  • 원인
    • 트레이스 파일 내 시간 정보(timed_statistics = TRUE), 대기 이벤트(Level 8) 누락
    • CPU 할당 관련 실행/요청대기/할당대기(run queue) 중 CPU 고갈로 인한 할당대기 시간 계측 불가
    • 계측시 컴퓨터 시스템 타이머 한계로 작은 오차 발생 가능
    • 계측은 전체 코드 대상 아님 (예외: 트레이스 파일 쓰기 코드)
  • PL/SQL 구문
    DECLARE
      l_count INTEGER;
    BEGIN
      FOR c IN (SELECT extract(YEAR FROM d), id, pad
                FROM t
                ORDER BY extract(YEAR FROM d), id)
      LOOP
        NULL;
      END LOOP;
      FOR i IN 1..10
      LOOP
        SELECT count(n) INTO l_count
        FROM t
        WHERE id < i*123;
      END LOOP;
    END;
    
  • PL/SQL Trace
    -- 실행 통계 - PL/SQL 은 물리/논리 읽기 정보 없음
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute      1      0.44       0.40          0          0          0           1
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        2      0.45       0.41          0          0          0           1
    
    -- 재귀 실행 표시 없음
    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 34  (CHRIS)
    
    -- 네트워크 계층에서 클라이언트로 데이터를 보냄 : SQL*Net message to client
    -- 네트워크 계층에서 클라이언트로 부터 데이터를 기다림 : SQL*Net message from client
    -- 네트워크 전송 시간 미포함, SQL*Net 라운드 트립마다 대기 한쌍 발생, 하위 계층 라운드 트립과 다를 수 있음
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       1        0.00          0.00
      SQL*Net message from client                     1        0.00          0.00
    ******************************************************************************** 
    
  • PL/SQL 내 두번째 SQL 구문
    SQL ID: 7fjjjf0yvd05m Plan Hash: 4270555908
    
    SELECT COUNT(N) 
    FROM
     T WHERE ID < :B1 *123
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        1      0.00       0.00          0          0          0           0
    Execute     10      0.00       0.00          0          0          0           0
    Fetch       10      0.00       0.02         53        303          0          10
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       21      0.01       0.02         53        303          0          10
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 34  (CHRIS)   (recursive depth: 1)
    -- 10번 실행 됨 (1st/avg/max 값이 다름, Row Source Operation 은 평균 값)
    Number of plan statistics captured: 10
    
    Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    ---------- ---------- ----------  ---------------------------------------------------
             1          1          1  SORT AGGREGATE (cr=30 pr=5 pw=0 time=2607 us)
           122        676       1229   TABLE ACCESS BY INDEX ROWID T (cr=30 pr=5 pw=0 time=2045 us cost=8 size=1098 card=122)
           122        676       1229    INDEX RANGE SCAN T_PK (cr=4 pr=0 pw=0 time=872 us cost=3 size=0 card=122)(object id 20991)
    
    
    Rows     Execution Plan
    -------  ---------------------------------------------------
          0  SELECT STATEMENT   MODE: ALL_ROWS
          1   SORT (AGGREGATE)
        122    TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'T' (TABLE)
        122     INDEX   MODE: ANALYZED (RANGE SCAN) OF 'T_PK' (INDEX (UNIQUE)
                    )
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                        53        0.00          0.02
    --------------------------------------------------------------------------------
    
  • 마지막 SQL 구문
    -- 오브젝트 정보를 얻기 위해 엔진에 의해 재귀적으로 실행 됨
    SQL ID: 96g93hntrzjtr Plan Hash: 2239883476
    
    select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, 
      sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, 
      spare1, spare2, avgcln 
    from
     hist_head$ where obj#=:1 and intcol#=:2
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        0      0.00       0.00          0          0          0           0
    Execute      4      0.00       0.00          0          0          0           0
    Fetch        4      0.00       0.01          5         12          0           4
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        8      0.00       0.01          5         12          0           4
    
    Misses in library cache during parse: 0
    Optimizer mode: RULE
    -- SYS 계정, 재귀 2단계
    Parsing user id: SYS   (recursive depth: 2)
    
    -- Row Source Operation 정보가 없음
    -- CHRIS 유저는 HIST_HEAD$ 권한이 없으므로 실행 계획 미제공
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                         5        0.00          0.01
    
  • 전체 실행 통계
    -- 비재귀/재귀 SQL 구분 분리 표시
    ********************************************************************************
    
    OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute      3      0.45       0.42         20        226          0           3
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total        5      0.45       0.42         20        226          0           3
    
    Misses in library cache during parse: 2
    Misses in library cache during execute: 1
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      SQL*Net message to client                       2        0.00          0.00
      SQL*Net message from client                     2        0.00          0.00
    
    
    OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse        2      0.00       0.00          0          0          0           0
    Execute     29      0.00       0.00          0          0          0           0
    Fetch    10037      6.50      11.97      71569      38832          8     1000028
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total    10068      6.50      11.97      71569      38832          8     1000028
    
    Misses in library cache during parse: 2
    Misses in library cache during execute: 2
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      db file sequential read                        72        0.00          0.04
      db file scattered read                        530        0.06          2.79
      direct path write temp                      11002        0.00          0.51
      direct path read temp                       24015        0.00          2.41
    
    -- 세션 내 SQL 통계 표시
        5  user  SQL statements in session.
       13  internal SQL statements in session.
       18  SQL statements in session.
        2  statements EXPLAINed in this session.
    
    -- 트레이스 파일 전체 정보
    -- 18 개 SQL S중 4개 표시
    ********************************************************************************
    Trace file: DBM11203_ora_28030.trc
    Trace file compatibility: 11.1.0.7
    Sort options: prsela  exeela  fchela  
           1  session in tracefile.
           5  user  SQL statements in trace file.
          13  internal SQL statements in trace file.
          18  SQL statements in trace file.
          18  unique SQL statements in trace file.
           2  SQL statements EXPLAINed using schema:
               CHRIS.prof$plan_table
                 Default table was used.
                 Table was created.
                 Table was dropped.
       46125  lines in trace file.
          12  elapsed seconds in trace file.
    

3.1.6 TVD$XTAT

  • Trivadis 확장 트레이스 파일 분석 도구
    tvdxtat -i DBM11106_ora_6334.trc -o DBM11106_ora_6334.html
    
TKPROF로 충분하지 않은 이유
  • TVD$XTAT 에서 해결된 TKPROF 의 다섯 가지 문제
    • sort 인수 지정 시 SQL 간 관계 손실
    • 집계 데이터 제공 (유용한 정보 손실)
    • 바인드 변수 정보 미제공
    • 경과 시간에 Idle 대기 이벤트가 제외 됨 (예: SQL*Net message from client)
    • 트레이스 파일에 SQL 구문 텍스트가 없으면 상세 정보 미제공, 요약 정보 합산 제공 됨
      • SQL 실행 시작 이후 트레이스 활성화 시
설치
  1. http://top.antognini.ch 에서 다운로드
  2. 디렉터리 생성 후 압축 풀기
  3. tvdxtat.sh 내 JAVA_HOME, TVDXTAT_HOME 설정
  4. 인수 설정 변경 (config/tvdxtat.properties)
  5. 로깅 설정 변경 (config/logging.properties)
TVD$XTAT 인수 (p.113)
인수 설명 비고
input 입력 파일 - .trc 혹은 압축 파일(.gz, .zip) .zip 에서는 하나만 추출 됨
output 출력 파일 임시 파일(xml) 생성/삭제 됨
cleanup 임시 파일(xml) 제거 여부  
feedback 진행 상황 표시 여부  
help 도움말 표시  
limit 출력 파일내 목록에서 제공되는 항목의 최대 개수 0:무제한
release 트레이스 파일 생성 DB 메이저 버전 지정 7,8,9,10,11,12
sys sys 유저 재귀 SQL 출력 여부  
template 출력 파일 생성에 사용될 XSL 템플릿 지정 html.xsl, text.xsl
version TVD$XTAT 버전 표시  
wait 대기 이벤트 상세 정보 출력 여부 부하가 크므로 필요시 적용
logging 로깅 레벨 제어(severe, warning, info, fine, finer) TVD$XTAT 디버깅용
TVD$XTAT 출력 해석
tvdxtat -i DBM11203_ora_28030.trc -o DBM11203_ora_28030.txt -s no -w yes -t text
  • 주요 정보 : Interval, Transactions
    Database Version
    ****************
    Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
    With the Partitioning, Automatic Storage Management, Oracle Label Security, OLAP,
    Data Mining and Real Application Testing options
    
    Analyzed Trace File
    *******************
    /u00/app/oracle/diag/rdbms/dbm11203/DBM11203/trace/DBM11203_ora_28030.trc
    
    Interval
    ********
    Beginning 30 Nov 2012 23:21:45.691
    End       30 Nov 2012 23:21:58.097
    Duration  12.407 [s]
    
    Transactions
    ************
    Committed  0
    Rollbacked 0
    
  • 리소스 사용률 프로파일 - 개괄 적인 정보
    • 처리시간 : 12.407초 (CPU: 56%, 임시파일 24%, 파일읽기 23%, 계측되지 않은 시간...)
      • TVD$XTAT 는 항상 응답시간 기준으로 리스트
        Resource Usage Profile
        **********************
                                                                  Total             Number of      Duration per
        Component                                          Duration [s]       %        Events        Events [s]
        --------------------------------------------- ----------------- ------- ------------- -----------------
        CPU                                                       6.969  56.171           n/a               n/a
        db file scattered read                                    2.792  22.502           530             0.005
        direct path read temp                                     2.417  19.479        24,015             0.000
        direct path write temp                                    0.513   4.136        11,002             0.000
        db file sequential read                                   0.041   0.326            72             0.001
        SQL*Net message from client                               0.001   0.008             2             0.001
        SQL*Net message to client                                 0.000   0.000             2             0.000
        unaccounted-for                                          -0.325  -2.623           n/a               n/a
        --------------------------------------------- ----------------- -------
        Total                                                    12.407 100.000
        
  • 비재귀 SQL 구문 목록 - SQL 별 정보
    Statement ID  Type                                  Duration [s]       %    Executions     Execution [s]
    ------------- -------------------------------- ----------------- ------- ------------- -----------------
    #1            PL/SQL                                      12.724 102.561             1            12.724
    #5            PL/SQL                                       0.006   0.045             1             0.006
    #9            PL/SQL                                       0.002   0.016             1             0.002
    ------------- -------------------------------- ----------------- -------
    Total                                                     12.732 102.623
    
  • 처리 시간을 가장 많이 차지한 SQL 세부 정보 확인(Statement ID #1)
    ****************************************** STATEMENT #1 ******************************************
    
    Session ID           156.29
    Service Name         SYS$USERS
    Module Name          SQL*Plus
    Parsing User         34
    Hash Value           166910891
    -- 11.1 버전 이상 SQL ID 지원
    SQL ID               15p0p084z5qxb
    
    DECLARE
      l_count INTEGER;
    BEGIN
      FOR c IN (SELECT extract(YEAR FROM d), id, pad
                FROM t
                ORDER BY extract(YEAR FROM d), id)
      LOOP
        NULL;
      END LOOP;
      FOR i IN 1..10
      LOOP
        SELECT count(n) INTO l_count
        FROM t
        WHERE id < i*123;
      END LOOP;
    END;
    
    -- Misses : 하드 파싱 횟수
    -- LIO    : Consisitent + Current
    
    Database Call Statistics with Recursive Statements
    **************************************************
    
    Call                            Count        Misses           CPU [s]       Elapsed [s]       PIO [b]       LIO [b]    Consistent [b]   Current [b]          Rows
    ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
    Parse                               1             1             0.005             0.006             7            20                20             0             0
    Execute                             1             0             6.957            12.387        71,562        38,820            38,812             8             1
    Fetch                               0             0             0.000             0.000             0             0                 0             0             0
    ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
    Total                               2             1             6.962            12.393        71,569        38,840            38,832             8             1
    
    Database Call Statistics without Recursive Statements
    *****************************************************
    
    Call                            Count        Misses           CPU [s]       Elapsed [s]       PIO [b]       LIO [b]    Consistent [b]   Current [b]          Rows
    ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
    Parse                               1             1             0.005             0.004             0             0                 0             0             0
    Execute                             1             0             0.448             0.410             0             0                 0             0             1
    Fetch                               0             0             0.000             0.000             0             0                 0             0             0
    ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
    Total                               2             1             0.453             0.414             0             0                 0             0             1
    
    Resource Usage Profile
    **********************
                                                              Total             Number of      Duration per
    Component                                          Duration [s]       %        Events        Events [s]
    --------------------------------------------- ----------------- ------- ------------- -----------------
    recursive statements                                     12.271  96.437           n/a               n/a
    CPU                                                       0.453   3.560           n/a               n/a
    SQL*Net message from client                               0.000   0.003             1             0.000
    SQL*Net message to client                                 0.000   0.000             1             0.000
    --------------------------------------------- ----------------- -------
    Total                                                    12.724 100.000
    
    -- 재귀 SQL 목록 중 Statement ID #2 드릴 다운 필요
    7 recursive statements were executed.
    
                                                               Total        
    Statement ID  Type                                  Duration [s]       %
    ------------- -------------------------------- ----------------- -------
    #2            SELECT                                      12.234  96.150
    #3            SELECT                                       0.033   0.263
    #7            SELECT (SYS recursive)                       0.003   0.022
    #11           SELECT (SYS recursive)                       0.000   0.001
    #12           SELECT (SYS recursive)                       0.000   0.001
    #14           SELECT (SYS recursive)                       0.000   0.001
    #16           SELECT (SYS recursive)                       0.000   0.000
    ------------- -------------------------------- ----------------- -------
    Total                                                     12.252  96.286
    
  • Statement ID #2
    • 재귀 레벨, 부모 SQL Statement ID 정보 추가 (SQL 구문 사이의 관계)
      ****************************************** STATEMENT #2 ******************************************
      
      Session ID           156.29
      Service Name         SYS$USERS
      Module Name          SQL*Plus
      Parsing User         34
      Recursive Level      1 <<<
      Parent Statement ID  1 <<<
      Hash Value           955957303
      SQL ID               7wd0gdwwgph1r
      
      SELECT EXTRACT(YEAR FROM D), ID, PAD FROM T ORDER BY EXTRACT(YEAR FROM D), ID
      
      Execution Plan
      **************
      
      Optimizer Mode       ALL_ROWS
      Hash Value           961378228
      
               Rows Operation
      ------------- --------------------------------------------------------------------------------------
          1,000,000 SORT ORDER BY (cr=38474 pr=71499 pw=33035 time=11123996 us cost=216750 size=264000000 card=1000000)
          1,000,000   TABLE ACCESS FULL T (cr=38474 pr=38463 pw=0 time=5674541 us cost=21 size=264000000 card=1000000)
      
      Database Call Statistics with Recursive Statements
      **************************************************
      
      Call                            Count        Misses           CPU [s]       Elapsed [s]       PIO [b]       LIO [b]    Consistent [b]   Current [b]          Rows
      ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
      Parse                               1             1             0.004             0.010             7            32                32             0             0
      Execute                             1             1             0.000             0.000             0             0                 0             0             0
      Fetch                          10,001             0             6.492            11.926        71,499        38,482            38,474             8     1,000,000
      ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
      Total                          10,003             2             6.496            11.936        71,506        38,514            38,506             8     1,000,000
      Average (per row)                   0             0             0.000             0.000             0             0                 0             0             1
      
      Database Call Statistics without Recursive Statements
      *****************************************************
      
      Call                            Count        Misses           CPU [s]       Elapsed [s]       PIO [b]       LIO [b]    Consistent [b]   Current [b]          Rows
      ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
      Parse                               1             1             0.001             0.001             0             9                 9             0             0
      Execute                             1             1             0.000             0.000             0             0                 0             0             0
      Fetch                          10,001             0             6.492            11.926        71,499        38,482            38,474             8     1,000,000
      ----------------------- ------------- ------------- ----------------- ----------------- ------------- ------------- ----------------- ------------- -------------
      Total                          10,003             2             6.493            11.927        71,499        38,491            38,483             8     1,000,000
      Average (per row)                   0             0             0.000             0.000             0             0                 0             0             1
      
      Resource Usage Profile
      **********************
                                                                Total             Number of      Duration per
      Component                                          Duration [s]       %        Events        Events [s]
      --------------------------------------------- ----------------- ------- ------------- -----------------
      CPU                                                       6.493  53.071           n/a               n/a
      db file scattered read                                    2.792  22.818           530             0.005
      direct path read temp                                     2.417  19.753        24,015             0.000
      direct path write temp                                    0.513   4.194        11,002             0.000
      recursive statements                                      0.020   0.161           n/a               n/a
      db file sequential read                                   0.000   0.002             2             0.000
      --------------------------------------------- ----------------- -------
      Total                                                    12.234 100.000
      
      6 recursive statements were executed.
      
                                                                 Total        
      Statement ID  Type                                  Duration [s]       %
      ------------- -------------------------------- ----------------- -------
      #4            SELECT (SYS recursive)                       0.015   0.121
      #6            SELECT (SYS recursive)                       0.004   0.032
      #10           SELECT (SYS recursive)                       0.001   0.008
      #13           SELECT (SYS recursive)                       0.000   0.001
      #17           SELECT (SYS recursive)                       0.000   0.000
      #18           SELECT (SYS recursive)                       0.000   0.000
      ------------- -------------------------------- ----------------- -------
      Total                                                      0.006   0.050
      
      -- 대기 이벤트 히스토그램 (db file scattered read : 멀티블록 읽기 → Blocks per Event[b])
      db file scattered read
      **********************
                                                     Total             Number of          Duration per                  Blocks per
      Range [us]                              Duration [s]       %        Events       %    Event [us]    Blocks [b]     Event [b]
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      256 ≥ duration < 512                           0.003   0.111             7       1           443            56             8
      512 ≥ duration < 1024                          0.008   0.288             9       2           892            72             8
      1024 ≥ duration < 2048                         0.033   1.191            18       3         1,847           826            46
      2048 ≥ duration < 4096                         0.517  18.525           166      31         3,115        11,627            70
      4096 ≥ duration < 8192                         1.465  52.459           264      50         5,547        20,742            79
      8192 ≥ duration < 16384                        0.579  20.736            60      11         9,648         4,722            79
      16384 ≥ duration < 32768                       0.126   4.496             5       1        25,101           336            67
      32768 ≥ duration < 65536                       0.061   2.195             1       0        61,274            81            81
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      Total                                          2.792 100.000           530 100.000         5,267        38,462            73
      
      -- 디스크 I/O 관련 대기 이벤트 추가 정보
      File                      Total             Number of                                Duration per 
      Number             Duration [s]       %        Events       %    Blocks [b]       %    Event [us] 
      ------------- ----------------- ------- ------------- ------- ------------- ------- ------------- 
      4                         2.792 100.000           530 100.000        38,462 100.000         5,267 
      
      direct path read temp
      *********************
                                                     Total             Number of          Duration per                  Blocks per
      Range [us]                              Duration [s]       %        Events       %    Event [us]    Blocks [b]     Event [b]
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      4 ≥ duration < 8                               0.002   0.078           264       1             7           264             1
      8 ≥ duration < 16                              0.086   3.559         6,576      27            13         6,576             1
      16 ≥ duration < 32                             0.073   3.003         3,065      13            24         3,065             1
      32 ≥ duration < 64                             0.080   3.301         1,585       7            50         1,585             1
      64 ≥ duration < 128                            0.799  33.046         7,724      32           103         7,724             1
      128 ≥ duration < 256                           0.688  28.485         4,276      18           161         4,276             1
      256 ≥ duration < 512                           0.115   4.770           356       1           324           356             1
      512 ≥ duration < 1024                          0.004   0.167             5       0           809             5             1
      1024 ≥ duration < 2048                         0.035   1.438            23       0         1,511            23             1
      2048 ≥ duration < 4096                         0.430  17.797           119       0         3,614           119             1
      4096 ≥ duration < 8192                         0.097   3.997            21       0         4,599            21             1
      8192 ≥ duration < 16384                        0.009   0.359             1       0         8,673             1             1
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      Total                                          2.417 100.000        24,015 100.000           101        24,015             1
      
      File                      Total             Number of                                Duration per 
      Number             Duration [s]       %        Events       %    Blocks [b]       %    Event [us] 
      ------------- ----------------- ------- ------------- ------- ------------- ------- ------------- 
      201                       2.417 100.000        24,015 100.000        24,015 100.000           101 
      
      direct path write temp
      **********************
                                                     Total             Number of          Duration per                  Blocks per
      Range [us]                              Duration [s]       %        Events       %    Event [us]    Blocks [b]     Event [b]
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      4 ≥ duration < 8                               0.001   0.141            91       1             8            91             1
      8 ≥ duration < 16                              0.007   1.283           520       5            13           520             1
      16 ≥ duration < 32                             0.004   0.844           169       2            26           169             1
      32 ≥ duration < 64                             0.423  82.467         9,340      85            45         9,340             1
      64 ≥ duration < 128                            0.068  13.263           865       8            79           865             1
      128 ≥ duration < 256                           0.001   0.189             6       0           162             6             1
      256 ≥ duration < 512                           0.001   0.193             3       0           330             3             1
      512 ≥ duration < 1024                          0.003   0.633             4       0           812             4             1
      1024 ≥ duration < 2048                         0.005   0.987             4       0         1,266             4             1
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      Total                                          0.513 100.000        11,002 100.000            47        11,002             1
      
      File                      Total             Number of                                Duration per 
      Number             Duration [s]       %        Events       %    Blocks [b]       %    Event [us] 
      ------------- ----------------- ------- ------------- ------- ------------- ------- ------------- 
      201                       0.513 100.000        11,002 100.000        11,002 100.000            47 
      
      db file sequential read
      ***********************
                                                     Total             Number of          Duration per                  Blocks per
      Range [us]                              Duration [s]       %        Events       %    Event [us]    Blocks [b]     Event [b]
      ---------------------------------- ----------------- ------- ------------- ------- ------------- ------------- -------------
      64 ≥ duration < 128                            0.000 100.000             2     100           106             2             1
      
      File                      Total             Number of                                Duration per 
      Number             Duration [s]       %        Events       %    Blocks [b]       %    Event [us] 
      ------------- ----------------- ------- ------------- ------- ------------- ------- ------------- 
      4                         0.000  54.460             1  50.000             1  50.000           116 
      201                       0.000  45.540             1  50.000             1  50.000            97 
      ------------- ----------------- ------- ------------- ------- ------------- ------- -------------
      Total                     0.000 100.000             2 100.000             2 100.000           106
      
      
  • SQL Statement ID #3 - 바인드 변수 있을 때
    ****************************************** STATEMENT #3 ******************************************
    
    Session ID           156.29
    Service Name         SYS$USERS
    Module Name          SQL*Plus
    Parsing User         34
    Recursive Level      1
    Parent Statement ID  1
    Hash Value           1035370675
    SQL ID               7fjjjf0yvd05m
    
    SELECT COUNT(N) FROM T WHERE ID < :B1 *123
    
    Bind Variables
    **************
    
    10 bind variable sets were used to execute this statement.
    
    Number of
    Execution     Bind          Datatype                          Value
    ------------- ------------- --------------------------------- ----------------------------------------
    1             1             NUMBER                            "1"
    2             1             NUMBER                            "2"
    3             1             NUMBER                            "3"
    4             1             NUMBER                            "4"
    5             1             NUMBER                            "5"
    6             1             NUMBER                            "6"
    7             1             NUMBER                            "7"
    8             1             NUMBER                            "8"
    9             1             NUMBER                            "9"
    10            1             NUMBER                            "10"
    

3.2. PL/SQL 코드 프로파일링

DBMS_HPROF DBMS_PROFILER
계층형 프로파일러(권장) 라인 레벨 프로파일러
활성화 시 매우 작은 오버헤드
호출 레벨의 정보 제공
Self time 과 Total time 개념 모두 지원
추가 권한 불필요
네이티브 컴파일 된 PL/SQL 지원
라인 레벨 정보 제공
11.1 이전 버전에서 사용 가능
모든 주요 개발도구에서 지원

3.2.1 DBMS_HPROF

  • 세션 레벨에서 계층형 프로파일러 제공
    • 호출이 실행된 총 횟수
    • 호출을 처리하는 데 소모한 시간
    • 서브 호출을 처리하는 데 소모한 시간
    • 호출 계층에 대한 정보
  • 대상 : 사용자 실행 가능 모든 PL/SQL 코드 (wrapped PL/SQL 은 최상위 레벨 정보만 수집됨)
  • 출력 : 트레이스 파일 → 테이블 적재 or PLSHPROF 유틸리티 적용
    테이블 내용
    DBMSHP_RUNS 프로파일링 세션 정보
    DBMSHP_FUNCTION_INFO 수행된 서브프로그램 목록
    DBMSHP_PARENT_CHILD_INFO 호출 하는/당하는 프로그램 간 관계
출력 테이블 설치하기
  • DBMS_HPROF 는 사용자 권한 수행
    • dbmshptab.sql 수행 후 SYNONYM & GRANT 처리
    • 사용자 계정에 테이블 생성
프로파일링 데이터 수집
  • dbms_hprof.start_profiling : 프로파일러 활성화
    파라미터 정보
    location 트레이스 파일이 저장 될 오라클 디렉터리 오브젝트 이름
    filename 트레이스 파일 이름 (존재 시 덮어씀)
    max_depth 데이터 수집 호출 깊이 (NULL: 무제한)
  • dbms_hprof.stop_profiling : 프로파일링 비활성화
  • dbms_hprof.analyze : 출력테이블 저장
    BEGIN
      dbms_hprof.start_profiling(location => 'PLSHPROF_DIR',
                                 filename => 'dbms_hprof.trc');
    END;
    /
    
    SET TIMING ON
    DECLARE
      l_count INTEGER;
    BEGIN
      perfect_triangles(1000);
      SELECT count(*) INTO l_count
      FROM all_objects;
    END;
    /
    
    BEGIN
      dbms_hprof.stop_profiling;
    END;
    /
    
    SELECT dbms_hprof.analyze(location => 'PLSHPROF_DIR',
                              filename => 'dbms_hprof.trc') AS runid
    FROM dual;
    
프로파일링 데이터를 수동으로 리포팅하기
  • 네임스페이스 별로 나눔
    SELECT sum(function_elapsed_time)/1000 AS total_ms,
           100*ratio_to_report(sum(function_elapsed_time)) over () AS total_percent,
           sum(calls) AS calls,
           100*ratio_to_report(sum(calls)) over () AS calls_percent,
           namespace AS namespace_name
    FROM dbmshp_function_info
    WHERE runid = &runid
    GROUP BY namespace
    ORDER BY total_ms DESC;
    
    TOTAL [ms]   TOT%  CALLS   CAL% NAMESPACE_NAME
    ---------- ------ ------- ----- --------------
          565	54.9%	  89    5.6 SQL
          464	45.1%   1494   94.4 PLSQL
    
  • 모듈 별로 나눔 (p.128)
    SELECT sum(function_elapsed_time)/1000 AS total_ms,
           100*ratio_to_report(sum(function_elapsed_time)) over () AS total_percent,
           sum(calls) AS calls,
           100*ratio_to_report(sum(calls)) over () AS calls_percent,
           namespace,
           nvl(nullif(owner || '.' || module, '.'), function) AS module_name,
           type
    FROM dbmshp_function_info
    WHERE runid = &runid
    GROUP BY namespace, nvl(nullif(owner || '.' || module, '.'), function), type
    ORDER BY total_ms DESC;
    
  • 계층 구조에 따라 표시 (p.129)
    SELECT lpad(' ', (level-1) * 2) || nullif(c.owner || '.', '.') ||
           CASE WHEN c.module = c.function THEN c.function ELSE nullif(c.module || '.', '.') || c.function END AS function_name,
           pc.subtree_elapsed_time/1000 AS total_ms, 
           pc.function_elapsed_time/1000 AS function_ms,
           pc.calls AS calls
    FROM dbmshp_parent_child_info pc, 
         dbmshp_function_info p, 
         dbmshp_function_info c
    START WITH pc.runid = &runid
    AND p.runid = pc.runid
    AND c.runid = pc.runid
    AND pc.childsymid = c.symbolid
    AND pc.parentsymid = p.symbolid
    AND p.symbolid = 1
    CONNECT BY pc.runid = prior pc.runid
    AND p.runid = pc.runid 
    AND c.runid = pc.runid
    AND pc.childsymid = c.symbolid 
    AND pc.parentsymid = p.symbolid
    AND prior pc.childsymid = pc.parentsymid
    ORDER SIBLINGS BY total_ms DESC;
    
PLSHPROF 사용하기
$ plshprof -output dbms_hprof dbms_hprof.trc
-- 두개 트레이스 파일 지정 시 둘 사이 값의 차이(Delta) 표시
  • 결과물(dbms_hprof.html)
    • 8개의 서로 다른 기준에 따라 정렬된 함수별 경과시간 데이터
    • 3개의 서로 다룬 기준에 따라 정렬된 모듈별 경과시간 데이터
    • 3개의 서로 다른 기준에 따라 정렬된 네임스페이스별 경과시간 데이터
    • 부모와 자식의 경과시간 데이터
GUI 사용하기
  • SQL Developer
  • Dell Toad

3.2.2 DBMS_PROFILER

  • 세션 레벨에서 라인 레벨 프로파일러 제공
    • 라인 별 수집 정보
      • 실행된 총 횟수
      • 실행하는 데 소모한 총 시간
      • 실행하는 데 소모한 최대/최소 시간
    • 조건
      • 랩핑 X
      • 네이티브 모드 컴파일 X
      • 사용자 CREATE 권한 (소유자 혹은 CREATE ANY 권한 보유)
    • 저장
      • PLSQL_PROFILER_RUNS : 프로파일링 세션 정보
      • PLSQL_PROFILER_UNITS : 실행별로 수행된 유닛 목록
      • PLSQL_PROFILER_DATA : 코드 라인 프로파일링 데이터
출력 테이블 설치하기
  • @?/rdbms/admin/proftab.sql 으로 테이블 생성 후 SYNONYM & GRANT 처리
프로파일링 데이터 수집하기
dbms_profiler 패키지 내 프로시저(함수) 내용
start_profiler 프로파일러 활성화
flush_data 프로파일링 데이터를 출력 테이블에 저장
stop_profiler 플러시 & 프로파일러 비활성화
pause_profiler 프로파일링 일시 중지
resume_profiler 프로파일링 재개
SELECT dbms_profiler.start_profiler AS status
FROM dual;

  STATUS
--------
       0

execute perfect_triangles(1000)

SELECT dbms_profiler.stop_profiler AS status,
       plsql_profiler_runnumber.currval AS runid
FROM dual;

  STATUS    RUNID
-------- --------
       0        1
프로파일링 데이터 보고서 수동 생성하기
  • 3개 테이블을 쿼리로 조회 가능 (p.135)
  • 쿼리에서 응답시간은 백분율만 제공
    • 가장 느린 부분을 파악하는 것이 목표
    • 시간 정보는 신뢰하기 어려움 (CPU 의존 코드의 경우 프로파일러 오버헤드 발생 : 1초미만 → 약7초소요 → 약4초측정)
      SELECT s.line, 
             round(ratio_to_report(p.total_time) OVER ()*100,1) AS time, 
             total_occur, 
             s.text
      FROM all_source s,
           (SELECT u.unit_owner, u.unit_name, u.unit_type,
                   d.line#, d.total_time, d.total_occur
            FROM plsql_profiler_units u, plsql_profiler_data d
            WHERE u.runid = &runid
            AND d.runid = u.runid
            AND d.unit_number = u.unit_number) p
      WHERE s.owner = p.unit_owner (+)
      AND s.name = p.unit_name (+)
      AND s.type = p.unit_type (+)
      AND s.line = p.line# (+)
      AND s.owner = user
      AND s.name = 'PERFECT_TRIANGLES'
      AND s.type IN ('PROCEDURE', 'PACKAGE BODY', 'TYPE BODY')
      ORDER BY s.line;
      
GUI 사용하기
  • PL/SQL Developer
  • SQLDetective
  • Dell Toad
  • SQL Navigator
  • Rapid SQL

3.2.3 트리거를 활용한 프로파일링

  • DBMS_HPROF, DBMS_PROFILER 모두 PL/SQL 코드 실행 세션에서 만 활성화 가능
  • 로그온 트리거 활용 (필요한 세션만 트레이스 할 수 있도록 롤/USERENV 컨텍스트 활용)
    CREATE TRIGGER start_hprof_profiler AFTER LOGON ON DATABASE
    BEGIN
      IF (dbms_session.is_role_enabled('HPROF_PROFILE')) 
      THEN
        dbms_hprof.start_profiling(
          location => 'PLSHPROF_DIR',
          filename => 'dbms_hprof_'||sys_context('userenv','sessionid')||'.trc'
        );
      END IF;
    END;
    /
    
    CREATE TRIGGER stop_hprof_profiler BEFORE LOGOFF ON DATABASE
    BEGIN
      IF (dbms_session.is_role_enabled('HPROF_PROFILE')) 
      THEN
        dbms_hprof.stop_profiling();
      END IF;
    END;
    /
    

문서정보

Enter labels to add to this page:
Please wait 
Looking for a label? Just start typing.