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

일단 추적 기능이 활성화되면 오라클은 모든 SQL과 애플리케이션이 만든 최상위 수준의 PL/SQL호출을 서버의 추적파일에 기록한다.
이 추적파일 자체를 읽기란 매우 어렵다. 우리가 원하는것은 이 추적 파일로부터 사용자에게 친숙한 포멧의 보고서를 생성하는 것이다.
추적 파일을 이용하기 쉬운 무언가로 바꾸는 것이 바로 TKPROF의 유일한 목적이다.

TKPROF 활성화

TKPROF활성화 방법(SQL_TRACE를 켜는 방법)


alter session set timed_statistics=true;
alter session set events '10046 trace name context forever, level 12';

절차

1.최소한 세션수준에서 ALTER SESSION SET TIMED_STATISTICS=TRUE 를 활성화 되어야한다.(CPU시간이 보이지 않는다면 경과된 시간이 보이지 않으므로 어디가 병목인지를 알수 없음)
2.ALTER SESSION SET SQL_TRACE=TRUE 또는 ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL <N>';

  
<N>은 다음 수들 중의 하나임
1 - 표준 SQL_TRACE 기능을 활성화한다(SQL_TRACE=TRUE와 동일)
4 - SQL_TRACE을 활성화하고 바인드 변수의 값을 추적 파일에 기록한다.
8 - SQL_TRACE을 활성화하고 대기이벤트를 추적 파일에 기록한다.
12 - 표준 SQL_TRACE을 활성화하고 바인드변수와 대기이벤트를 기록한다.

TKPROF는 바인드 변수 값을 보고 하지 않기 때문에 추적파일 자체가 필요함
추적파일에 대기 이벤트가 포함되면 추적파일이 상당히 커질수 있으므로 max_dump_file_size init.ora매개변수가 이들 정보를 수용할 수 있을 만큼 충분히 큰지를 확인


PROD9i > show parameter  max_dump

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_dump_file_size                   string      UNLIMITED

TKPROF 실행

TKPROF가 무엇을 제공하고 서버의 추적 파일을 어떻게 액세스하는지를 보여주기 위하여 간단한 테스트, 즉 추적을 활성화하는 스크립트를 실행

주석파일의 생성

이 예에서는 ALL_OBJECTS로 부터 생성되어 많은 수의 행을 포함하도록 여러 차례 복사된 BIG_TABLE을 사용할 예정


tkyte@PROD9I> alter session set timed_statistics=true;

세션이 변경되었습니다.

tkyte@PROD9I> alter session set events '10046 trace name context forever, level 12';

세션이 변경되었습니다.

tkyte@PROD9I> select count(*) from big_table
  2  /

  COUNT(*)
----------
     25131

tkyte@PROD9I> select *
  2  from big_table
  3  where owner = 'SYS'
  4    and object_type = 'PACKAGE'
  5    and object_name like 'F%'
  6  /

선택된 레코드가 없습니다.

주석파일 이름의 획득


- Windows용으로서 Oracle8i와 그이전 버전에서 사용된 표준 8.3파일 이름 규칙을 이용하는 곳에서 사용
select c.value || '\ora' || to_char(a.spid,'fm00000') || '.trc'
from v$process a, v$session b, v$parameter c
where a.addr = b.PADDR
and b.audsid = sys_context('userenv','sessionid')
and c.name = 'user_dump_dest'
/

- 유닉스와 Windows용으로서 Oralce 9i 이상(플랫폼에 종속된 파일 이름 문제를 해결하였다)에서 사용
select rtrim(c.value,'/') || '/'|| d.instance_name ||
'_ora_' || ltrim(to_char(a.spid)) || '.trc'
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.PADDR
and b.audsid = sys_context('userenv','sessionid')
and c.name = 'user_dump_dest'
/


tkyte@PROD9I> select rtrim(c.value,'/') || '/'|| d.instance_name ||
  2  '_ora_' || ltrim(to_char(a.spid)) || '.trc'
  3  from v$process a, v$session b, v$parameter c, v$instance d
  4  where a.addr = b.PADDR
  5  and b.audsid = sys_context('userenv','sessionid')
  6  and c.name = 'user_dump_dest'
  7  /

RTRIM(C.VALUE,'/')||'/'||D.INSTANCE_NAME||'_ORA_'||LTRIM(TO_CHAR(A.SPID))||'.TRC'
--------------------------------------------------------------------------------------------

C:\oracle\admin\PROD9i\udump/prod9i_ora_2196.trc

tkyte@PROD9I>

tkyte@PROD9I> exit
Oracle9i Enterprise Edition Release 9.2.0.8.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.8.0 - Production에서 분리되었습니다.

C:\Documents and Settings\root\My Documents\Workspace>

이를 쿼리를 실행한 후에 SQL*Plus(사용중인 툴)를 빠져나오면서 추적파일을 완전히 닫아서 추적파일의 정보를 이용할 수 있도록함

TKPROF 보고서 생성


C:\oracle\admin\PROD9i\udump>tkprof prod9i_ora_2196.trc tk.prf

TKPROF: Release 9.2.0.8.0 - Production on 금 Aug 22 23:42:07 2008

Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.

이 명령은 현재 작업 디렉토리에 tk.prf라는 텍스트 파일을 만듬

TKPROF 보고서 읽기


select count(*) 
from
 big_table


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.10       0.08          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        4      0.07       0.38       1100       2544          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.18       0.47       1100       2544          0           2

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 39  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE 
  25131   TABLE ACCESS FULL BIG_TABLE 


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     3      114.51        114.51
  db file scattered read                         70        0.05          0.32
********************************************************************************

쿼리와 실행 통계

보고서는 데이터베이스에 의해 처리된 쿼리의 텍스트로 시작된다.


 select count(*) from big_table

다음에는 쿼리 자체의 주요 단계별 실행 통계가 테이블 형태로 나타난다.

분석(Parse)	오라클이 공유 풀에서 쿼리를 찾거나(소프트 파스) 새로운 쿼리 계획을 작성하는 단계(하드 파스)이다.
실행(Execute)	쿼리에 나타난 OPEN또는 EXECUTE문을 보고 오라클이 작업을 수행하는 단계이다.
	SELECT문의 경우 대부분 공백으로 나타나며 UPDATE문의 경우에는 모든 작업이 수행되는 곳이다.
인출(Fetch)	SELECT 문의 경우에는 대부분의 작업이 수행되어 나타나는 단계이다.
	UPDATE 문의 경우에는 아무것도 나타나지 않는다(갱신 작업 시에는 인출하지 않아도 된다).

처리된 모든 문은 이들 세 단계를 거치며 보고서의 맨 위에는 다음과 같은 제목이 나타난다.

횟수(Count)	이 단계가 몇번 수행되었는가를 나타낸다. 적절하게 애플리케이션에서는 모든 SQL에 대해 분석 회수와 실행 횟수가 1또는 2 이상으로 나타난다.
CPU	이 단계에서 소비된 총 CPU 시간으로 1/1000초 단위로 기술된다.
경과(Elapsed)	이 단계에서 소된 총 벽시계 시간, 경과 시간이 CPU 시간보다 훨씬 큰 경우에는 대기 시간이 존재하였음을 의미한다.
디스크(Disk)	이 단계에서 수행된 물리적인 I/O의 수를 나타낸다.
쿼리(Query)	일관된 모드 블록을 인출하기 위하여 수행된 논리적인 I/O의 수를 나타낸다.
	이들 블록을 롤백 세그먼트로부터 재구성되었을지도 모르기 때문에 쿼리가 시작될 당시에 이미 존재했을 수도 있다.
	일반적으로 모든 물리적인 I/O는 논리적인 I/O를 동반하여 논리적인 I/O의 수가 물리적인 I/O의 수를 능가한다.
	그러나 앞쪽의 AUTOTRACE절에서 보았듯이 임시공간에 대한 직접읽기 및 쓰기에는 이 규칙이 적용되지 않는다.
	다시 말하면 논리적인 I/O로 변역되지 않는 물리적인 I/O가 존재할 수도 있다.
현재(Cureent)	지금 현재 블록을 인출하기 위하여 수행된 논리적인 I/O의 수를 나타낸다. 갱신과 삭제같은 수정DML 작업중에는 이들을 흔히 볼수 있다.
	테이블에 쿼리를 던질때는 오라클이 쿼리가 시작된 시점을 기준으로 블록을 인출해 오는 것과 달리 수정을 처리하기 위해서는 현재 모드로 블록을 인출하여야 한다.
행(Rows)	이 과정에서 처리되거나 영향을 받은 행의 수를 나타낸다. 수정중일 때는 실행 과정에 행 값이 나타나며 SELECT 쿼리중에는 인출 과정에 이 값이 나타난다

쿼리 환경

TKPROF 보고서의 다음 절은 쿼리가 실행된 환경을 말해준다.


Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 39

Misses in library cache during parse: 0은 소프트 파스 수행
Optimizer goal: CHOOSE는 최적화기 목표가 RBO또는 CBO로 사용될수 있음을 의미
Parsing user id : 이 쿼리가 파싱될 때 적용된 스키마


tkyte@PROD9I> select * from all_users where user_id = 39;

USERNAME                          USER_ID CREATED
------------------------------ ---------- --------
TKYTE                                  39 08/01/14

쿼리 계획

TKPROF 보고서의 다음절은 이 쿼리가 실행될 때 실제로 이용되었던 쿼리 계획이다.


Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2300 r=2209 w=0 time=2077 us)
   1000   TABLE ACCESS FULL OBJ#(30635) (cr=2300 r=2209 w=0 time=1054 us)

cr	일관된 모드 읽기로서 일관된 입수(논리적인 I/O)를 보여준다.
r	물리적인 읽기를 나타낸다
w	물리적인 쓰기를 나타낸다
time	경과된 시간을 1/1,000,000초 단위로 나타낸다. us는 마이크로초를 나타낸다

대기 이벤트

TKPROF 보고서의 마지막 부분에는 대기 이번트가 온다 (Oracle 9iR1 이상에서 SET EVENT 구문 사용시)


  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     3      114.51        114.51
  db file scattered read                         70        0.05          0.32