- 3.1 데이터베이스 호출 트레이스
- 3.2. PL/SQL 코드 프로파일링
- 효율적인 접근 방법 : Trace, Profiling 기능 활용
- 문제 분류
- SQL 처리 시간 많음
- PL/SQL 처리 시간 많음
- DBMS 가 Idle 상태 (외부병목)
3.1 데이터베이스 호출 트레이스
- DB 계층이 병목 이라면 DB 와 AP 간 상호작용을 분석
- SQL 트레이스 : SQL 구문 목록, SQL 실행 관련 성능 수치 제공
- DB Trace 필수 단계
- SQL 트레이스 활성화
- 트레이스 파일 찾기
- 트레이스 파일에서 관련 정보 추출
- 프로파일러 수행
- 프로파일러 결과 해석
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)
- 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 고갈로 인한 할당대기 시간 계측 불가
- 계측시 컴퓨터 시스템 타이머 한계로 작은 오차 발생 가능
- 계측은 전체 코드 대상 아님 (예외: 트레이스 파일 쓰기 코드)
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 은 물리/논리 읽기 정보 없음
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
********************************************************************************
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 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 구문 텍스트가 없으면 상세 정보 미제공, 요약 정보 합산 제공 됨
설치
- http://top.antognini.ch 에서 다운로드
- 디렉터리 생성 후 압축 풀기
- tvdxtat.sh 내 JAVA_HOME, TVDXTAT_HOME 설정
- 인수 설정 변경 (config/tvdxtat.properties)
- 로깅 설정 변경 (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
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
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;
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 사용하기
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;
/