[펌]SQL*TRACE와 TKPROF

튜닝의 도구 – SQL*TRACE와 TKPROF

Oracle의 SQL*TRACE는 사용자가 실행 한 SQL문에 대해 구문분석(Parsing), 실행(execute), 추출(fetch) 부분으로 나누어 각 단계에서 걸리는 Overhead와 시간 등의 통계 정보를 일정한 형태로 저장 합니다. EXPALIN PLAN에서 제공하는 정보와 더블어 CPU/IO의 필요량, 실행계획의 각 단계에서의 레코드 개수등의 정보도 확인 가능 합니다.  EXPLAIN PLAN 명령어와 함께 자주 사용되는 튜닝의 도구 입니다.

SQL*TRACE나 TKPROF를 실행 했을 때의 결과는 이해하기가 쉽지 않지만 강력한 튜닝의 도구 입니다. SQL*TRACE에 의해 분석되는 결과는 바이너리 형태로 운영체제의 파일 시스템에 생성 됩니다. 물론 바이너리 이므로 결과를 직접 눈으로 보면 이해가 되지 않지만 TKPROF 유틸리티를 이용하여 텍스트 파일 형태로 변환 시켜 확인이 가능 합니다.

SQL*TRACE의 결과는 데이터베이스 전체 또는 특정 세션에 대해 적용 할 수 있는데 데이터베이스 전체에 트레이스를 적용하면 실제 Application 수행에 추가적인 부하를 가져오므로 특별한 경우를 제외하고 전체 데이터베이스 시스템에 TRACE를 거는 것은 삼가 해야 합니다. 대부분은 특정 세션에 대해서만 부분적으로 활성화 하여 사용 합니다.


SQL*TRACE의 사용

SQL TRACE를 사용하기 전에 몇 가지 설정이 필요한데 먼저 초기파일에서 USER_DUMP_DEST 파라미터를 확인해야 합니다. 이 매개변수는 TRACE를 실행 할 때 생성되는 파일의 위치를 설정 하는 것입니다. 또한 시간 정보를 TRACE 항목에 추가할려면 TIMED_STATISTICS 항목을 TRUE로 해야 하거나 SQL*Plus등에서는 alter session set timed_statistics=true 라고 해주어야 합니다. 아래에 자세히 확인 하도록 합니다.

TIMED_STATISTICS

시간 통계 정보에 대해 수집여부를 결정, 기본값은 false
세션레벨에서는 alter session set timed_statistics=true라고 하면 됩니다.

MAX_DUMP_FILE_SIZE

TRACE의 결과로 생기는 바이너리 파일의 최대 사이즈를 단위는 블록 입니다. 기본값은 500 블록 입니다. 또한 세션 레벨에서 다음과 같이 지정 가능 합니다. Alter session set max_dump_file_size = 800(800개의 시스템 블록)

USER_DUMP_DEST

TRACE의 결과로 생기는 바이너리 파일의 위치를 지정 합니다. 세션레벨에서는 alter session set user_dump_dest = “C:\oracle\admin\wink\udump” 등으로 지정 합니다.

위의 세개의 파라미터를 init.ora 파일에 지정하였다면 SQL*TRACE의 시작을 전체 데이터베이스에서 할건지 세션 레벨에서 할건지를 정할 수가 있습니다. 인스턴스 레벨에서 할려면 init.ora 파일에서 SQL_TRACE 항목을 TRUE로 설정하면 되구요 세션 레벨에서 할려면 alter session set sql_trace = true 라고 하면 됩니다.

자 이제 실습을 위해 위의 3개의 매개변수를 init.ora 에 설정토록 합니다.

MAX_DUMP_SIZE = 800
TIMED_STATISTICS = TRUE
USER_DUMP_DEST = C:\oracle\admin\wink\udump

다음을 따라 하도록 합니다.

SQL> conn / as sysdba
연결되었습니다.
SQL> shutdown immediate
데이터베이스가 닫혔습니다.
데이터베이스가 마운트 해제되었습니다.
ORACLE 인스턴스가 종료되었습니다.
SQL> startup open
ORACLE 인스턴스가 시작되었습니다.

Total System Global Area  135338868 bytes
Fixed Size                   453492 bytes
Variable Size             109051904 bytes
Database Buffers           25165824 bytes
Redo Buffers                 667648 bytes
데이터베이스가 마운트되었습니다.
데이터베이스가 열렸습니다.

SQL>conn scott/tiger

SQL> alter session set sql_trace=true;

세션이 변경되었습니다.

SQL> select job,avg(sal) from emp
  2  group by job
  3  having avg(sal) > (select avg(sal) from emp
  4  where job = 'SALESMAN');

JOB         AVG(SAL)
--------- ----------
ANALYST         3000
MANAGER   2758.33333
PRESIDENT       5000

session에서 trace를 중지

SQL> alter session set sql_trace=false;

SQL*Plus를 종료하고 c:\oracle\admin\wink\udump에 가보면 trc 파일이 생겼을 것
입니다. 저의 경우 DB SID가 wink이므로 wink_ora_3316.trc 와 같은 파일이 생겼습니다.

TKPROF를 이용하여 TRACE파일을 텍스트 파일로 변경 하기

TKPROF Utility를 이용하면 매우 유용한 분석 정보를 얻을 수 있습니다. 즉 TKPROF의 결과 파일은 트레이스가 실행되는 동안 프로세스에 의해 데이터베이스에서 실행된 작업에 대한 요약 정보 입니다.

텍스트 파일의 내용을 보면 PARSE, EXECUTION, FETCH시 작업을 실행 한 횟수, CPU 사용 시간, 검색된 행이 무엇인지, SQL이 수행된 총 소요시간, DISK IO 블록 수, 조건을 만족하는 전체 행의 수, 수행된 SQL문이 사용한 SGA 영역의 크기, SQL문장의 실행 계획, 해당 세션에서 작업했던 전체 작업에 대한 CPU, 메모리, 블록의 크기 등의 정보를 확인 할 수 있습니다.

SQL문을 해석하기 위해서는 아래의 단계가 필요 합니다.

파싱(parse)

SQL문을 실행 계획으로 번역 하는 것을 말합니다. 해당 SQL을 실행 하는데 필요한 적절한 권한, 컬럼이 있는지, 참조된 객체에 관한 확인 등의 작업이 이루어지게 됩니다.

실행(execution)

오라클에 의해 SQL문을 실제 실행 한 것을 말합니다.

추출/인출(fetch)

쿼리에 의해 추출된 레코드를 이여기 합니다.  Select 문에서만 이용 됩니다.


다음은 TKPROF의 통계 정보 컬럼 입니다.

Count : 분석, 실행, 추출을 몇번 했는지를 나타 냅니다.
CPU : 분석, 실행, 추출에 대한 CPU 처리 시간(CURSOR를 공유하면 분석단계의 처리 시간은 0 입니다.)
Elapsed : 분석, 실행, 추출 처리 단계별로 처리된 소요 시간
Disk : 테이블의 데이터를 읽기 위해 데이터 파일로부터 읽어 들인 블록 수
Query : SELECT로 데이터를 읽어 올 때 이미 다른 사용자에 의해 같은 데이터가 사용 되었다면 그 블록에서 데이터를 가져옵니다.
Current : 메모리에 저장된 데이터를 가지고 오기 위해 읽은 버퍼의 블록 수(update, insert, delete 후 select 했을 때)

TKPROF를 실행하기 위한 문법

Explain = 사용자계정/패스워드(명시된 사용자에 대해 EXPLAIN PLAN 실행)
Print = n (트레이스 파일내의 분석된 SQL문의 수를 n 만큼만 제한할 때 이용)
Record = 파일명(트레이스 파일내에 분석된 SQL문을 지정한 파일에 저장)
Sort=option(트레이스 파일내에 분석된 SQL문을 지정한 옵션에 의해 정렬)
Sys=[NO](트레이스 파일내에 생성된 SQL 문장 중에 오라클 서버가 내부적인 작업을 위해 실행한 SQL문장을 출력 시 포함 할건지를 결정)
Table=스키마.테이블명(실행 계획을 지정한 테이블에 저장)

이전의 SQL*TRACE에 의해 생긴 바이너리 파일을 TKPROF를 이용하여 분석을 해보도록 하겠습니다.

명령프롬픝에서 다음과 같이 실행 합니다.(TRACE 파일이 만들어진 곳에서 실행)

C:\oracle\admin\wink\udump>tkprof wink_ora_3316.trc sql1.tkp sys=no explain=scot
t/tiger

TKPROF: Release 9.2.0.1.0 - Production on 목 Dec 16 01:33:23 2004

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

다음은 sql1.tkp 파일의 내용 입니다.



TKPROF: Release 9.2.0.1.0 - Production on 목 Dec 16 01:33:23 2004

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

Trace file: wink_ora_3316.trc
Sort options: default

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

alter session set sql_trace=true


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59  (SCOTT)
********************************************************************************


아래는 사용자가 실행한 SQL 문장 입니다.

select job,avg(sal) from emp
group by job
having avg(sal) > (select avg(sal) from emp
where job = 'SALESMAN')

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        2      0.00       0.00          0          6          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.01          0          6          0           3

Misses in library cache during parse: 1 이 값이 0이라는 의미는 실행한 SQL문이 이전에 실행 된적이 없었음을 나타 냅니다.
Optimizer goal: CHOOSE 옵티마이저 모드 입니다.
Parsing user id: 59  (SCOTT)

Rows     Row Source Operation
-------  ---------------------------------------------------
      3  FILTER  
      5   SORT GROUP BY
     14    TABLE ACCESS FULL EMP
      1   SORT AGGREGATE
      4    TABLE ACCESS FULL EMP


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      3   FILTER
      5    SORT (GROUP BY)
     14     TABLE ACCESS   GOAL: ANALYZED (FULL) OF 'EMP'
      1    SORT (AGGREGATE)
      4     TABLE ACCESS   GOAL: ANALYZED (FULL) OF 'EMP'

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

alter session set sql_trace=false


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 59  (SCOTT)



********************************************************************************
아래의 TOTAL은 전체 작업 결과에 대한 분석 결과 입니다.

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.01       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          6          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.01       0.01          0          6          0           3

Misses in library cache during parse: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

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

Misses in library cache during parse: 0

    3  user  SQL statements in session.
    1  internal SQL statements in session.
    4  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: wink_ora_3316.trc
Trace file compatibility: 9.00.01
Sort options: default

       1  session in tracefile.
       3  user  SQL statements in trace file.
       1  internal SQL statements in trace file.
       4  SQL statements in trace file.
       4  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           SCOTT.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
      54  lines in trace file.


출처 : http://insvelley.tistory.com/tag/trace