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 보고서 옵션 설명

라. TKPROF SQL 정렬 순서

마. 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
********************************************************************************