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

10046 Trace 사용 순서

아래와 같은 순서로 사용을 하면 된다.

① 자신이 접속한 Session의 SPID(Server Process ID)를 확인한다.

 
-- SYSDBA 권한으로 접속한다. 
SQL> SELECT P.SPID SERVER
     FROM V$PROCESS P, V$SESSION S
     WHERE P.ADDR = S.PADDR
       AND S.AUDSID = USERENV('SESSIONID');

    SERVER
    ------
    218038

② 10046 Trace 활성화

아래 명령어로 SQL Trace를 활성화 할 수 있다.

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

항 목	설 명
LEVEL - 1	기본 정보
LEVEL - 4	기본 정보 + Binding 정보
LEVEL - 8	기본 정보 + Waiting 정보
LEVEL - 12	기본 정보 + Binding 정보 + Waiting 정보

③ SQL 수행

Trace를 분석 할 SQL 문장을 실행 시킨다.

 
SQL> SELECT *
     FROM EMP E
     WHERE E.EMPNO = 9999999
     AND E.DEPTNO = 10;

④ 10046 Trace 비 활성화

SQL_TRACE 옵션을 FALSE로 Trace 모드를 비 활성화 한다.

 
SQL> ALTER SESSION SET SQL_TRACE=FALSE;

⑤ Trace 파일 확인

①번 단계에서 조회한 SPID와 동일한 trc 파일이 생성되었는지 확인해 본다.

- USER_DUMP_DEST(UDUMP)에서 SPID.trc 파일 확인
- 일반적인 UDUMP 파일 경로
- $ORACLE_HOME/admin/Instance Name/udump/spid.trc

⑥ 218038.trc 파일 확인

아래 예제와 같이 trc 파일은 직관적으로 보기가 어렵다.

 
=====================
PARSING IN CURSOR #2 len=69 dep=0 uid=44 oct=3 lid=44 tim=65620558312435 hv=1079158054 ad='a3a0eaf0'
SELECT *
FROM   EMP E
WHERE  E.EMPNO  = 9999999
AND    E.DEPTNO = 10
END OF STMT
PARSE #2:c=0,e=4143,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=65620558312421
EXEC #2:c=0,e=159,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=65620558312792
FETCH #2:c=10000,e=3280,p=3,cr=4,cu=0,mis=0,r=0,dep=0,og=1,tim=65620558316229

⑦ TKPROF Util 사용하여 파일 변환

tkprof 유틸을 사용하면 분석하기 쉬운 포맷으로 변환한다.

 
tkprof 218038.trc 218038.txt

TKPROF 구문

Options	설명
SORT = option	명령문 정렬 순서(ex. fchela : fetch 하는데 수행시간이 가장 오래 걸린 SQL로 Descending Sort)
EXPLAIN = username/password	지정된 schema에서 EXPLAIN PLAN을 실행 함
SYS = NO	user에 의해 실행된 Recursive SQL문의 나열 비 활성화
AGGREGATE = NO	다른 user의 동일한 SQL문을 하나의 레코드로 집계하지 않음
WAITS = YES	Trace파일에서 발견된 모든 Wait이벤트에 대한 요약 기록 여부

⑧ 변환한 218038.txt 파일 확인

아래는 tkprof 유틸로 변환한 218038.txt 파일의 내용이다. 자세한 설명은 아래 표를 참고하기 바란다.

 
SELECT *
FROM   EMP E
WHERE  E.EMPNO  = 9999999
AND    E.DEPTNO = 10

-- #보기 1
Call     Count CPU Time Elapsed Time       Disk      Query    Current       Rows
------- ------ -------- ------------ ---------- ---------- ---------- ----------
Parse        1    0.000        0.002          0          0          0          0
Execute      1    0.000        0.000          0          0          0          0
Fetch        1    0.000        0.028          3          4          0          0
------- ------ -------- ------------ ---------- ---------- ---------- ----------
Total        3    0.000        0.031          3          4          0          0

-- #보기 2
Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user: APPS (ID=44)

-- #보기 3
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  STATEMENT
      0   TABLE ACCESS BY INDEX ROWID EMP (cr=4 pr=3 pw=0 time=28400 us)
      1    INDEX UNIQUE SCAN EMP_U1 (cr=3 pr=2 pw=0 time=22438 us)(Object ID 6485271)

변환한 218038.txt 파일 설명

구분	항목		설명
보기1	Call	Parse	SQL을 Parsing하는 구간
		Execute	SQL을 실제 수행하는 구간. DML일 경우 이 부분이 표시됨
		Fetch	SQL을 통해 나온 값을 사용자에게 반환하는 구간
	Cpu		CPU에서 수행한 시간(단위 : 초)
	Elapsed		각 구간에서 시작과 종료까지 총 수행한 시간(단위 : 초)
	Disk		Disk에서 Block을 읽은 양(Physical Read)
	Query		Memory에 Block을 읽은 양(Logical Read)
	Current		현재의 Session에서 Commit하지 않은 Block을 읽은 양
	Rows		각 단계별 액세스한 ROWS
보기2	Misses in library cache during parse		Parse 구간에서 해당 SQL을 Library Cache에서 읽지 못하고 잃어버린 횟수
			값은 1씩 증가함
			값이 1이면 Hard Parse. 0이면 Soft Parse를 의미함
보기3	cr(consistent read)		Logical Block Read
	pr(Physical Read)		Physical Block Read
	pw(Physical Write)		Physical Block Write
	time		수행시간(단위 - 1 / 1,000,000 초)