1. HOME
  2. [종료]구루비 DB 스터디
  3. 2012년 하반기 - 오라클 성능 트러블슈팅의 기초 스터디
  4. TKPROF를 이용한 SQL 추적 파일 분석

TKPROF를 이용한 SQL 추적 파일 분석 (by darkturtle) [2013.01.08]

TKPROF 를 이용한 SQL 추적 파일 분석

가. 주요 내용

  • SQL 추적 파일 분석 도구로 ORACLE 에서 제공되는 유틸리티 - TKPROF
  • SQL 수행 정보를 정리된 형태의 보고서로 생성 가능
  • TKProf is an Oracle database utility used to format SQL Trace output into human readable format.
    The TKProf executable is located in the ORACLE HOME/bin directory.
  • tracefile과 outputfile 만 설정하고 나머지는 생략 가능
  • SQL 파스, 수행, 패치 정보는 각 작업이 수행 될 때 SQL 추적 파일에 기록?
  • SQL 실행 계획 정보(STAT)는 해당 SQL의 커서가 닫힐 때 기록?
  • SQL 커서가 닫히기 전, SQL 추적 파일 생성이 종료된다면, explain 옵션으로 예상 실행계획 생성
  • sort 옵션 생략 경우, SQL 추적 파일에 기록된 SQL 수행 순서로 TKPROF 보고서 생성
  • print 옵션 생략 경우, 전체 SQL 기록
  • 정렬 기준 : 패치 소요 시간, 실행 소요 시간, 파스 소요 시간 기준으로 상위 5개만 출력
 
   tkprof orcl_ora_5155.trc ktprof_output.txt sort='(FCHELA,EXELA,PRSLEA)' print= 5
  • sys=yes : SYS 유저가 수행한 사용자 SQL 및 SQL 처리를 위해 내부적으로 수행한 재귀 쿼리(Recursive SQL)
  • aggreage = yes : 동일한 SQL의 수행 정보를 통합
  • aggreage = no : SQL 추적 파일에 기록된 오픈된 커서 단위로 따로따로 기록
    {note}
    재귀 SQL(Recursive SQL)
    사용자가 수행하는 SQL이 아닌 오라클 내부적으로 메타 데이터 확인 및 변경, 기타 내부 데이터를 사용할 때 수행되는 SQL
    {note}
  • insert 옵션 사용 시, 대기 이벤트와 실행 계획 정보는 제외?

나. TKPROF 명령어 사용법


Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  waits=yes|no     Record summary for any wait events found in the trace file.
  sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
    userid  userid of user that parsed the cursor

다. TKPROF 보고서 옵션 설명

컬럼의미
tracefileTKPROF 보고서 생성에 사용될 SQL 추적 파일 이름
outputfile생성할 TKPROF 보고서 이름
explain=user/passwordEXPLAIN PLAN 명령으로 실행 계획 생성
* USER - EXPLAIN PLAN 명령을 수행할 오라클 유저
* PASSWD - 오라클 유저 패스워드
table=schema.tablename실행 계획 생성 시 사용할 테이블
* SCHEMA - 실행 계획 테이블 소유자
* TABLE - 실행 계획 테이블
sort=optionTKPROF 보고서 정렬 순서
print=integerTKPROF 보고서에 기록된 SQL 수 지정
sys=noSYS 유 저로 수행된 SQL 포함 여부, 기본 값 YES
waits=yes/no대기 이벤트 포함 여부. 기본 값 YES
aggregate=yes/no동일한 SQL을 통합해서 보여줄지 여부 지정. 기본 값 YES
insert=filenameTKPROF 보고서 생성 데이터를 저장할 수 있는 스크립트 파일 생성
record=filenameSQL 추적 파일에 기록된 SYS 유저가 수행한 SQL 을 제외한 SQL을 지정된 파일에 기록
witdth=NUMBERTKPROF 한 줄의 넓이 지정. SQL 실행 계획 정보를 기록할 때 적용됨

라. TKPROF SQL 정렬 순서

정렬 종류의미
prscntnumber of times parse was called
prscpucpu time parsing
prselaelapsed time parsing
prsdsknumber of disk reads during parse
prsqrynumber of buffers for consistent read during parse
prscunumber of buffers for current read during parse
prsmisnumber of misses in library cache during parse
execntnumber of execute was called
execpucpu time spent executing
exeelaelapsed time executing
exedsknumber of disk reads during execute
exeqrynumber of buffers for consistent read during execute
execunumber of buffers for current read during execute
exerownumber of rows processed during execute
exemisnumber of library cache misses during execute
fchcntnumber of times fetch was called
fchcpucpu time spent fetching
fchelaelapsed time fetching
fchdsknumber of disk reads during fetch
fchqrynumber of buffers for consistent read during fetch
fchcunumber of buffers for current read during fetch
fchrownumber of rows fetched
useriduserid of user that parsed the cursor

마. TKPROF 수행 예제

마.1. # SQL 추적 파일 생성 


SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER='10046_TRACE' ;

Session altered.

SQL> ALTER SESSION SET TIMED_STATISTICS = TRUE ;

Session altered.

SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED ;

Session altered.

SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

Session altered.

SQL> SELECT * FROM SCOTT.EMP WHERE ENAME ='TG';

no rows selected

SQL> SELECT * FROM SCOTT.EMP WHERE ENAME ='TG';

no rows selected

SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

Session altered.

SQL>

마.2. SQL 추적 파일 내용 


=====================
PARSING IN CURSOR #4 len=41 dep=0 uid=59 oct=3 lid=59 tim=1391261760726 hv=2585646416 ad='af880ce8'
SELECT * FROM SCOTT.EMP WHERE ENAME ='TG'
END OF STMT
PARSE #4:c=20000,e=37333,p=4,cr=27,cu=0,mis=1,r=0,dep=0,og=1,tim=1391261760723
BINDS #4:
EXEC #4:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1391261760805
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391261760836
WAIT #4: nam='db file sequential read' ela= 11566 file#=12 block#=248371 blocks=1 obj#=611995 tim=1391261772478
WAIT #4: nam='db file scattered read' ela= 10763 file#=12 block#=248372 blocks=5 obj#=611995 tim=1391261783359
FETCH #4:c=0,e=22543,p=6,cr=7,cu=0,mis=0,r=0,dep=0,og=1,tim=1391261783411
*** 2013-01-08 21:20:26.470
WAIT #4: nam='SQL*Net message from client' ela= 12641592 driver id=1650815232 #bytes=1 p3=0 obj#=611995 tim=1391274425048
STAT #4 id=1 cnt=0 pid=0 pos=1 obj=611995 op='TABLE ACCESS FULL EMP (cr=7 pr=6 pw=0 time=22540 us)'
=====================
PARSING IN CURSOR #3 len=41 dep=0 uid=59 oct=3 lid=59 tim=1391274425459 hv=2585646416 ad='af880ce8'
SELECT * FROM SCOTT.EMP WHERE ENAME ='TG'
END OF STMT
PARSE #3:c=0,e=123,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1391274425453
BINDS #3:
EXEC #3:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1391274425587
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=611995 tim=1391274425625
FETCH #3:c=0,e=97,p=0,cr=7,cu=0,mis=0,r=0,dep=0,og=1,tim=1391274425759
WAIT #3: nam='SQL*Net message from client' ela= 9141005 driver id=1650815232 #bytes=1 p3=0 obj#=611995 tim=1391283566811
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=611995 op='TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=94 us)'
=====================

마.3. aggregate=NO TKPROF 보고서

: 특정 구간 및 시점의 SQL 문제 파악 혹은 SQL 추적 파일 직접 분석 


--------------------------------------------------------------------------------

SELECT * 
FROM
 SCOTT.EMP WHERE ENAME ='TG'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.03          4         27          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.02          6          7          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.02       0.05         10         34          0           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 59  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL EMP (cr=7 pr=6 pw=0 time=22540 us)


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
  db file sequential read                         1        0.01          0.01
  db file scattered read                          1        0.01          0.01
  SQL*Net message from client                     1       12.64         12.64
********************************************************************************

SELECT * 
FROM
 SCOTT.EMP WHERE ENAME ='TG'


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        1      0.00       0.00          0          7          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          7          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 59  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=94 us)


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        9.14          9.14
********************************************************************************

마.4. aggregate=YES TKPROF 보고서 DEFAULT

: 각 SQL의 평균 값으로 문제 SQL을 판단한다면 문제 SQL 선정에 시간 단축 


********************************************************************************

SELECT * 
FROM
 SCOTT.EMP WHERE ENAME ='TG'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.02       0.03          4         27          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.02          6         14          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.02       0.06         10         41          0           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 59  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL EMP (cr=7 pr=6 pw=0 time=22540 us)


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
  db file sequential read                         1        0.01          0.01
  db file scattered read                          1        0.01          0.01
  SQL*Net message from client                     2       12.64         21.78
********************************************************************************

TKPROF 보고서 분석

가. TKPROF 주요 칼럼

컬럼의미
callSQL 수행 단계, 소프트 파스와 하드 파스 모두 기록
countSQL 수행 단계별 발생 횟수
cpuSQL 수행 단계별 CPU 사용 시간,
* CPU 오래 소요 원인
1. 과도한 행에 대한 복작한 데이터 가공 하는 SQL
2. 과도한 I/O
elpasedSQL 수행 단계별 응답 시간
diskSQL 수행 단계별 발생한 디스크 I/O
querySQL 수행 단계별 발생한 읽기 일관성 버퍼 캐시 I/O, 주로 SELECT
currntSQL 수행 단계별 발생한 현재 버퍼 캐시 I/O, 주로 DML 발생
rowsSQL 수행 단계별 추출 행 수
ParseSQL 파스 단계 통계
ExecuteSQL 실행 단계 통계, SQL 수행 시 증가, DML 수행 시 증가
FetchSQL 패치 단계 통계
totalSQL 커서 전체 통계
Misses in library cache during parse하드 파스 횟수
Optimizer modeSQL 수행 시 사용한 옵티마이저 모드
Parsing user idSQL 수행 유저ID. DBA_USERS.USER_ID
RowsSQL 실행 계획의 단계별 추출 행 수
Row Source OperationSQL 추적 파일의 STAT 항목에 기록된 SQL 수행 당시 실행 계획
* cr - 읽기 일관성 버퍼 캐시 I/O 횟수
* pr - 디스크에서 읽은 I/O 횟수
* pw - 디스크로 내려쓴 I/O 횟수
* time - 수행 시간(단위:1/1,000,000 초)		Execution Planexplain 옵션에 의해 tpprof 보고서 생성 당시 explain plan 명령으로 생성된 SQL 실행 계획
Event waited onSQL 수행 시 발생한 대기 이벤트, elapsed - cpu
Times Waited대기 이벤트 발생 횟수
Max. Wait가장 오래 대기한 시간(단위:초)
Total Waited총 대기 시간(단위:초)
Error encounteredSQL 수행 시 발생한 에러

나. 옵티마이저 모드

옵티마이저 모드설명
FIRST_ROWS_nn으로 지정된 수의 행을 가장 빨리 추출할 수 있는 SQL 실행 계획을 선택한다.
n 값으로는 1,10,100,1,000 이 지정 가능하다.
RULE규칙 기반 옵티마이저를 사용한다.
CHOOSE세그먼트에 통계 데이터가 있으면 비용 기반 옵티마이저로 수행되고
없으면 규칙 기반 옵티마이저가 사용된다.

다. SQL 악성 여부 판단 기준이 되는 TKPROF 항목

1. 응답 시간(elpased 칼럼 값)
2. CPU 사용 시간(cpu 칼럼 값)
3. 버퍼 캐시 I/O(query+current 칼럼 값)
4. 디스크 I/O (disk 칼럼 값 )
5. 추출 행 수(rows 칼럼 값 )

라. 악성 SQL 기준

1. SQL 응답 시간이 목표 성능에 미달
2. 과도한 자원 사용 ( 동시성 저하 )

  • 동적 샘플링이란
    1. 파스 단계에서 SQL이 사용하는 테이블에 통계 데이터가 없거나 신뢰할 수 없는 경우
    일부 샘플 블록을 추출해서 즉석에서 통계 정보를 수집하는 방식
    2. 즉석 통계 정보는 테이블 및 관련 인덱스에서 수집 된다.
    3. 관련 파라미터
    3.1. _OPTIMIZER_DYN_SMP_BLKS
    = 동적 샘플링에 사용할 기본 샘플 블록 수 지정, 기본 값 32
    3.2 _OPTIMIZER_DYNAMIC_SAMPLING
    = 동적 샘플링 수행 수준 설정,
    = 기본 값 2, SQL이 사용하는 테이블 중 통계정보가 없는 테이블이 존재

  1. HOME
  2. [종료]구루비 DB 스터디
  3. 2012년 하반기 - 오라클 성능 트러블슈팅의 기초 스터디
  4. TKPROF를 이용한 SQL 추적 파일 분석