제 4 장 시스템 진단과 튜닝

2.SQL_TRACE(Trace 파일 생성)

SQL_TRACE 는 실행되는 SQL문의 실행통계를 세션(Session)별로 모아서 트레이스(Trace) 파일을 만는다.

{section}{column:width=33%}



SQL_TRACE 에는 다음과 같은 사항들이 포함되어 있다.

■ SQL 파싱(Parsing), 실행(Execute), 페치(Fetch)를 수행한 횟수
■ 수행한 CPU 시간과 경과한(Elapsed) 시간들
■ 물리적(Disk), 논리적(Memory)인 읽기를 수행한 횟수
■ 추출된 로우의 수

{column}{section}

SQL_TRACE에 의해 생성되는 트레이스 파일의 이름은 시스템에 따라서 다르지만 보통 filename.TRC 의 형태를 가진다. 이 파일은 직접 읽을 수가 없으므로 읽을수 있는 상태로 만들기 위해 TKPROF 유틸리티를 실행시켜야 한다.

파라메터	지정	설 명
TIMED_STATISTICS	TRUE	RDBMS가 추가적인 시간통계(사용 CPU TIME)를 모을수 있게한다. 이 시간통계는 SQL_TRACE 나 SQL*DBA MONITOR 에서 사용되며 해당 SQL의 악성 여부를 판단하는 가장중요한 요소가 된다.
SQL_TRACE	TRUE	오라클에 세션을 맺는 모든 사용자들의 트레이스를 수행한다. FALSE로 지정하면 트레이스는 생성되지 않으면 필요한 사용자만 'ALTER SESSION SET SQL_TRACE=TRUE' 명령으로 트레이스를 생성시킬 수 있다. FALSE가 디폴트이다.
USER_DUMP_DEST	directory	SQL_TRACE가 트레이스 파일을 저장하는 디렉토리. default는 시스템에 따라 다르지만 보통 시스템 덤프(Dump)를 갖는 디렉토리이다(예; $ORACLE_HOME/rdbms/log)
MAX_DUMP_FILE_SIZE	number	트레이스 파일의 물리적인 크기를 O/S block 단위로 지정할 수 있게 한다. 이 SQL_TRACE파라메타를 전체 데이터베이스에 대해 설정하면, 디스크 사용량을 조절할 수 있게 도돠준다. 어떤크기를 지정할지 알려면 시스템에 있는 사용 가능한 O/S 블럭의 크기를 알아 본다. SQL_TRACE는 공간이 부족하면, 완전한 출력되지 않으므로 더 많은 공간을 부여해주고 다시 시작해야 한다.

SQL_TRACE를 수행하는 방법은 각각의 오라클 툴과 사용자 세션들에 따라 다르며 오라클 툴이 아닌 경우에는 조금씩 다를 수 있다.

실 행 툴	지 정 방 법
SQL*Forms	RUNFORM formname username/password -S(버전 3.0 이상에서)
SQL*Plus	ALTER SESSION SET SQL_TRACE = TRUE
SQL*Reportwriter	SQL_TRACE 라는 필드와 CHAR(40)의 속성을 가진 GROUP REPORT를 생성시키고 다음과 같이 지정한다.    &SQL ALTER SESSION SET SQL_TRACE = TRUE
Pro*SQL	EXEC SQL ALTER SESSION SET SQL_TRACE = TRUE

3.TKPROF(trace 파일 출력)

TKPROF 유틸리티는 SQL_TRACE를 통해 생성된 트레이스 파일을 분석이 가능한 형식으로 전환하여 출력한다.
SQL 문에 대한 실행(Explan Plan) 뿐만 아니라 다양한 옵션(Options)을 이용하여 분석하기 쉬운 형태로 추출시킬 수도 있다.

TKPROF 는 다음의 실행문으로 실행한다.

{section}{column:width=33%}

 
[syntax]

TKPROF tracefile listfile [SORT = parameters]  [PRINT = number]
       [EXPLAN = username/password]

tracefile     : SQL_TRACE 기능에 의해 생성된 통계정보를 가진 트레이스 파일이름
listfile      : TKPROF 가 출력시킬 파일의 이름
                    모든 SQL_TRACE로 모아진 통계값에 대해 파라메터를 지정할 수 있다. 
                 TKPROF는 지정한 파라메터의 통계값에 대한 역순으로 통계를 출력한다. 예)SORT=EXECPU
                 TKPROF는 가장 나쁜 EXECPU 값을 가진 통계값을 먼저 (여기서는 실행 CPU 시간이 많은 SQL 부터)출려해준다.
                 하나 이상의 파라메터를 지정하려면 다음과같이 부여한다.
                 SORT=(FCHDSK, PRSCPU)
PRINT = number : 트레이스 파일별로 출력시킬 sql 문의수. 나쁜 수행속도를 가지는 sql문의 개수를 예상하여 제한하는 것이 좋다.
EXPLAIN = username/password
                해당 트레이스 파일이 수행된 세션의 사용자그룹 및 패스워드를 지정하여야 하며 트레이스 
                   파일내에 있는 각 sql 문에대한 실행계획이 수립되고 저장된다.
                저장된 실행계획에는 각 수행 단계별로 수행된 로우수가 같이 표시되므로 비효율이 발생한 
                   이유 및 그 개선방법을 찾기가 아주 쉬워진다ㅣ.

예:  TKPROF ora_12343.trc trc1.txt  SORT=(EXECPU)  [EXPLAIN = scott/tiger]

{column}{section}

로우/컬럼	설 명
Parse	sql문이 파싱되는 단계에 대한 통계. 새로 파싱을 했거나 Shared SQL Pool에서 찾아 온 것도 같이 포함된다. 단, PL/SQL 내에서 반복수행 된 SQL이나 PRO*SQL에서 보존커서를 지정한 경우에는 한번만 파싱된다.
Execute	sql문의 실행 단계에 대한 통계. UPDATE, DELETE, INSERT 문은 여기에 수행한 결과가 나타난다. 전체범위방식으로 처리된 결과가 여러 건인 경우는 주로 여기에 많은 값이 나타나며 Fetch 에는 아주 적은 값이 나타난다.
Fetch	sql 문이 실행되면서 페치된 통계. 부분범위방식으로 처리된 select 문들이나 전체범위처리를 한 후 한 건을 추출하는 경우 (전체 집계, Count 등)는 주로 여기에 많은 값들이 나타나고 Execute에는 아주 적은 값이 나타난다.
Count	sql문이 파싱된 횟수, 실행된 횟수, 페치가 수행된 횟수
cpu	parse,execute,fetch가 실제로 사용한 CPU 시간 (1/100초 단위)
elapsed	작업의 시작에서 종료시까지 실제 소요된 시간
disk	디스크에서 읽혀진 데이터 블러의 수
query	메모리내에서 변경되지 않은 블럭을 읽거나 다른 세션에 의해 변경되었으나 아직 commit되지 않아 복사해 둔 스냅샷 블럭을 읽은 블럭수. select 문에서는 거의가 여기에 해당하며 Update, Delete, Insert 시에는 소량만 발생한다.
current	현 세션에서 작업한 내용을 commit하지 않아 오로지 자신에게만 유효한 블럭을 액세스한 블럭 수, 주로 Update, Delete, Insert 작업시 많이 발생한다. select 문에서는 거의 없거나 아주 적은 양인 경우가 대부분이다.
rows	sql문을 수행한 결과에 의해 최종적으로 액세스된 로우의수 (만약 쿼리인 경우라면 서브쿼리에 의해서 추출된 로우는 제외됨)

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

tkprof유틸을 이용하여 trace 보려고할때 정렬방법

parameter	설 명
PRSCNT	parse 한 횟수
PRSCPU	parse하는데 걸린 CPU 시간
PRSELA	parse하는대 걸린 Elapsed시간
EXECNT	실행한 횟수
EXECPU	실행할때 걸린 CPU 시간
EXEELA	실행하는데 걸린 Elapsed시간
FCHCNT	petch한 횟수
FCHCPU	petch하는데 걸린 CPU 시간
FCHELA	petch하는데 걸린 Elapsed시간

{section}{column:width=33%}

 

튜닝을 하기 위해서는 먼저 통계정보를 확인한다.

{column}{section}

{section}{column:width=33%}

 

통계정보를 보니 table, index 부분에 distinct 가 100만건이 있는걸 확인할수 있다.

index 를 만드는 목적은 빨리 실행되야하는 이유도 있지만 전체 table에 분포도가 얼마나 차지 하고있는지를 확인하여야한다.

실행계획을 한번 보고 sql_trace를 하는것이 좋다
여기서는 바로 tkprof를 이용하여 sql_trace를 하겠다.

먼저 튜닝해야할 부분 쿼리를 날려본다.

{column}{section}

{section}{column:width=33%}

 
*********************************************************************************************************
11.스크립트 기록.txt

SQL*Plus: Release 10.2.0.1.0 - Production on Thu Nov 8 19:51:30 2007

Copyright (c) 1982, 2005, Oracle.  All rights reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP and Data Mining options

SQL> CREATE TABLE XSOFT_TEMP(ORDER_DATE   VARCHAR2(8),
  2                          ORDER_NUMBER NUMBER);

Table created.

SQL> INSERT INTO XSOFT_TEMP
  2  SELECT TO_CHAR(TO_DATE('10000101', 'YYYYMMDD') + LEVEL - 1, 'YYYYMMDD') ORDER_DATE
  3       , TRUNC(LEVEL / 10) + 100                                          ORDER_NUMBER
  4  FROM   DUAL
  5  CONNECT BY LEVEL <= 1000000;

1000000 rows created.

SQL> CREATE INDEX APPS.XSOFT_TEMP_N1 ON APPS.XSOFT_TEMP (ORDER_DATE, ORDER_NUMBER)
  2  TABLESPACE APPS_TS_TX_DATA COMPUTE STATISTICS PARALLEL 6;

Index created.

SQL> ALTER INDEX APPS.XSOFT_TEMP_N1 NOPARALLEL;

Index altered.

SQL> CREATE INDEX APPS.XSOFT_TEMP_N2 ON APPS.XSOFT_TEMP (ORDER_NUMBER, ORDER_DATE)
  2  TABLESPACE APPS_TS_TX_DATA COMPUTE STATISTICS PARALLEL 6;

Index created.

SQL> ALTER INDEX APPS.XSOFT_TEMP_N2 NOPARALLEL;

Index altered.

SQL> BEGIN
  2      DBMS_STATS.GATHER_TABLE_STATS('APPS',           -- OWNER
  3                                    'XSOFT_TEMP',     -- TABLE_NAME
  4                                    CASCADE => TRUE);
  5  END;
  6  /

PL/SQL procedure successfully completed.

SQL> SELECT P.SPID SERVER
  2  FROM   V$PROCESS P,
  3         V$SESSION S
  4  WHERE  P.ADDR = S.PADDR
  5  AND    S.AUDSID = USERENV('SESSIONID');

SERVER
------------------------
435616

SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED;

Session altered.

SQL> 
SQL> ALTER SESSION SET SQL_TRACE=TRUE;

Session altered.

SQL> 
SQL> SET TERMOUT OFF;
SQL> /

Session altered.

SQL> SELECT /*+ INDEX(XSOFT_TEMP XSOFT_TEMP_N1) */
  2         *
  3  FROM   XSOFT_TEMP
  4  WHERE  ORDER_DATE BETWEEN '20000101' AND '30000101'
  5  AND    ORDER_NUMBER = 50000;

ORDER_DATE       ORDER_NUMBER
---------------- ------------
23660325                50000
23660326                50000
23660327                50000
23660328                50000
23660329                50000
23660330                50000
23660331                50000
23660401                50000
23660402                50000
23660403                50000

10 rows selected.

SQL> ALTER SESSION SET SQL_TRACE=FALSE;

Session altered.

SQL > EXIT;
*********************************************************************************************************

{column}{section}

{section}{column:width=33%}

 


*$ORACLE_HOME\admin\kdohee\udump* 에 TRC파일이 있는걸 확인할수있다.
가장 처음에 기록된걸 TKPROF를 이용하여 실행한다.

!tkprof_trans.jpg!

이때 여기서 명령어를 칠때 맨 마지막에 sort=fchela 를 하였는데 이는 패치를 하는데 걸린 실제 소요시간을 말한다 
이렇게 옵션을 준다.


|TKPROF: Release 10.2.0.1.0 - Production on Thu Nov 8 20:11:01 2007

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: intg41_ora_435616.trc
Sort options: 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
********************************************************************************

SELECT /*+ INDEX(XSOFT_TEMP XSOFT_TEMP_N1) */
       *
FROM   XSOFT_TEMP
WHERE  ORDER_DATE BETWEEN '20000101' AND '30000101'
AND    ORDER_NUMBER = 50000

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.26       0.63       1276       1277          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.26       0.64       1276       1277          0          10

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

Rows     Row Source Operation
-------  ---------------------------------------------------
     10  INDEX RANGE SCAN XSOFT_TEMP_N1 (cr=1277 pr=1276 pw=0 time=242396 us)(object id 844722)

********************************************************************************|

Row Source Operation을 보니 INDEX RANGE SCAN을 탄것을 볼수있다.
10건을 추출하는데 걸리는 시간은 0.26초걸리고 실제로 쿼리문이 돌면서 걸린시간은 0.64초가 걸렸다.
한번 PARSE하고 Fetch는 2번 했다 이는 운반단위가 두번 움직였다는걸 볼수있다.

{column}{section}

참고자료

오라클클럽
대용량 데이터베이스 솔루션1 제4장 시스템 진단과 튜닝
4조 강정식 오빠 조장

문서에 대하여

최초작성자 : 김도희
최초작성일 : 2007년 11월 9일
이 문서는 오라클클럽 대용량 데이터베이스 솔루션1 제4장 시스템 진단과 튜닝 모임에서 작성하였습니다.