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

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.