Oracle SQL Trace[기초]

(1) 자기 세션에 트레이스 걸기

  

• 자신이 접속해 있는 세션에만 트레이스를 거는 방법.

    

alter session set sql_trace = true;

--트레이스 걸기

  

  

  

화면 캡처: 2011-12-26 오전 9:15

  

  

select * from employees where employee_id = 100;

--SQL 실행

  

  

  

화면 캡처: 2011-12-26 오전 9:15

  

  

alter session set sql_trace = false;

--걸어놓은 트레이스 해제

  

  

화면 캡처: 2011-12-26 오전 9:17

  

• 그러고 나면, 지정된 서버 디렉토리에 트레이스파일(.trc)이 생성됨

  

  

화면 캡처: 2011-12-26 오전 9:16

  

  

하지만, 트레이스파일을 직접분석하기에는 보기 힘들다.

  

  

화면 캡처: 2011-12-26 오전 9:18

  

• 그러므로 TKProf유틸리티를 사용하여, 분석하기 쉽도록 보기 쉽게 포맷팅해서 보면 됨.

  

  

tkprof gbpr_ora_4692.trc report.prf sys=no

  

• gbpr_ora_4692.trc 파일을 보기 좋게 포맷팅해서 report.prf으로 만들어주고, SQL을 파싱하는 과정에서 내부적으로 수행되는 SQL은 제외한다(sys=no).

  

  

화면 캡처: 2011-12-26 오전 9:21

  

Report.prf 파일

  

  

화면 캡처: 2011-12-26 오전 9:22

  

  

오랜지를 통해서 트레이스 보기

  

  

  

화면 캡처: 2011-12-26 오전 9:24

  

  

  

화면 캡처: 2011-12-26 오전 9:39

  

  

  

화면 캡처: 2011-12-26 오전 9:39

  

  

  

화면 캡처: 2011-12-26 오전 9:39

  

  

  

화면 캡처: 2011-12-26 오전 9:39

  

  

• 그리고, 보기 좋게 만든 트레이스파일 분석하기

  

  

  

• Parse : SQL문의 파싱되는 단계에 대한 통계, 단 PL/SQL 내에서 반복수행(LOOP)된 SQL이나 PL*SQL에서 보존커서(Hold cursor)를 지정할 경우 한 번만 파싱

  

• Evecute : SQL문의 실행 단계에 대한 통계, INSERT, UPDAT, DELETE 문은 여기서 수행한 결과를 보여줌

                   전체범위 방식으로 처리된 결과가 여러 건인 경우 주로 여기에 많은 값이 나타나며 fetch에는 아주 적은 값이 나타남

  

• Fetch : SQL문이 실행되면서 fetch된 통계

               부분범위 방식으로 처리된 SELECT 문들이나 전체범위 처리를 한 후 한 건을 추출하는 경우 주로 여기에 많은 값들이 나타나고

execute에는 아주 적은 값이 나타남.

               ex) AGGREGATE, 전체집계, COUNT 등

  

  

• count : SQL문이 파싱되는 횟수, 실행횟수, fetch가 수행된 횟수

    

• cpu : pares, execute, fetch 가 실제로 사용한 CPU 시간(1/100초 단위)

    

• elapsed : 작업의 시작에서 종료 시까지 실제 소요된 총 시간

    

• disk : 디스크에서 잃혀 진 데이터 블록의 수 disk가 0이면 메모리 ACCESS

    

• query : 메모리 내에서 변경되지 않은 블록을 읽거나 다른 세션에 의해 변경되었으나 아직 Commit되지 않아 복사해 둔 스냅샷 블록을 읽은 블록의 수, SELECT 문에서는 거의 여기에 해당하며, INSERT,UPDATE,DELETE 시에는 소량만 발생

  

• current : 한 세션에서 작업한 내용을 Commit하지 않아 오로지 자신에게만 유효한 블록(Dirty Block)을 액세스한 블록의 수

                  주로 INSERT, UPDATE, DELETE  작업 시 많이 발생, SELECT 문에서는 거의 없으나 아주 적은 양인 경우가 대부분이다.

  

• row : SQL문을 수행한 결과에 의해 최종적으로 액세스한 ROW의 수

               서브쿼리에 의해서 추출된 ROW는 제외됨, SUM, AVG, MAX, MIN, COUT 등의 그룹수를 사용한 경우라면 큰 의미가 없음

  

  

• Auto Trace의 실행통계 항목과 비교하기

  

db block gets	current
consistent gets	query
physical reads	disk
SQL*Net roundtrips to/from client	fetch count
rows processed	fetch rows

  

10046 Trace 사용 방법

  

• 오라클은 오래전부터 다양한 종류의 이벤트 트레이스를 제공해 왔고, 이를 통해서도 SQL트레이스를 걸 수 있다.

  

  

SQL> SELECT P.SPID SERVER FROM V$PROCESS P, V$SESSION S WHERE P.ADDR = S.PADDR AND S.AUDSID = USERENV('SESSIONID');	SPID확인
SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 1';	활성화
SQL> ALTER SESSION SET SQL_TRACE=FALSE;	비활성화

  

10046 Trace LEVEL-1

  

SELECT DISTINCT TO_CHAR(CREATION_DATE ,'MM-YYYY')

FROM

CBO_PA_BUDGET_FIRST_V WHERE PROJECT_ID = 508

  

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 2 0.00 0.00 0 0 0 0

Execute 2 0.00 0.00 0 0 0 0

Fetch 4 0.01 0.05 11 290 0 2

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 8 0.01 0.05 11 290 0 2

  

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 60

  

Rows Row Source Operation

------- ---------------------------------------------------

1 HASH UNIQUE (cr=145 pr=11 pw=0 time=49717 us)

5 FILTER (cr=145 pr=11 pw=0 time=49581 us)

25 HASH GROUP BY (cr=145 pr=11 pw=0 time=49570 us)

125 NESTED LOOPS (cr=145 pr=11 pw=0 time=31455 us)

125 NESTED LOOPS (cr=143 pr=10 pw=0 time=19627 us)

25 NESTED LOOPS OUTER (cr=116 pr=10 pw=0 time=19484 us)

25 HASH JOIN (cr=116 pr=10 pw=0 time=19405 us)

25 NESTED LOOPS (cr=101 pr=1 pw=0 time=7877 us)

25 NESTED LOOPS (cr=24 pr=1 pw=0 time=7594 us)

5 TABLE ACCESS BY INDEX ROWID PA_BUDGET_VERSIONS (cr=7 pr=1 pw=0 time=7525 us)

5 INDEX RANGE SCAN PA_BUDGET_VERSIONS_U2 (cr=2 pr=1 pw=0 time=7473 us)(object id 140787)

25 TABLE ACCESS BY INDEX ROWID PA_BUDGET_LINES (cr=17 pr=0 pw=0 time=139 us)

25 INDEX RANGE SCAN PA_BUDGET_LINES_N3 (cr=12 pr=0 pw=0 time=63 us)(object id 141887)

25 TABLE ACCESS BY INDEX ROWID PA_RESOURCE_ASSIGNMENTS (cr=77 pr=0 pw=0 time=219 us)

25 INDEX UNIQUE SCAN PA_RESOURCE_ASSIGNMENTS_U1 (cr=52 pr=0 pw=0 time=126 us)(object id 146724)

236 TABLE ACCESS FULL PA_RESOURCE_LIST_MEMBERS (cr=15 pr=9 pw=0 time=10276 us)

0 TABLE ACCESS BY INDEX ROWID PA_EXPENDITURE_TYPES (cr=0 pr=0 pw=0 time=51 us)

0 INDEX UNIQUE SCAN PA_EXPENDITURE_TYPES_U1 (cr=0 pr=0 pw=0 time=25 us)(object id 133736)

125 INDEX RANGE SCAN PA_BUDGET_VERSIONS_N6 (cr=27 pr=0 pw=0 time=139 us)(object id 140788)

125 INDEX UNIQUE SCAN PA_EXPENDITURE_CATEGORIES_U1 (cr=2 pr=1 pw=0 time=11225 us)(object id 141547)

  

10046 Trace LEVEL-4

  

Bind변수 값 확인

  아래 그림과 같이 바인드변수 값을 확인 할 수 있다.

  

원본 위치 <http://www.oracleclub.com/lecture/2131>

  

10046 Trace LEVEL-8

  

SQL> ALTER SESSION SET EVENTS
'10046 trace name context forever, level 8';

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

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

Misses in library cache during parse: 1
Optimizer goal: ALL_ROWS
Parsing user: APPS (ID=44)

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)

-- Waiting 정보
Wait Event Name Count Wait(sec) Max Wait
-------------------------------------------------- ------- ---------- --------
db file sequential read 3 0.027 0.010
SQL*Net message to client 1 0.000 0.000
SQL*Net message from client 1 0.003 0.003
--------------------------------------------------- ------- --------- --------
Total 5 0.03

  

원본 위치 <http://www.oracleclub.com/lecture/2131>

  

10046 Trace LEVEL-12

  

  

(2) 다른 세션에 트레이스 걸기

  

• 성능문제가 발생한 SQL이 확보되지 않았다면, 커넥션 Pool에 놓인 세션 또는 시스템 레벨로 트레이스를 걸어 SQL정보를 수집해야한다.

(3) Service, Module, Action단위로 트레이스 걸기

  

• 최근의 n-TIer 주고의 애플리케이션은 WAS에서 DB와 미리 맺어놓은 커넥션 풀에서 세션을 할당받으므로 특정 프로그램 모듈이 어떤 세션에서 실행될지 알수 없고, 한 모듈내에서 여러 SQL을 수행할때 각각 다른 세션을 통해 처리될 수도 있다.
• 그러므로 한모듈만 트레이스를 거는것도 어렵고, WAS에서 맺은 세션에만 크레이스를 건 다음에 모든 트레이스 파일을 뒤져 찾는것도 어렵다.
• 10g부터 service, module, action별로 트레이스를 설정하고 해제할 수 있는 dmms_monitor패키지가 소개되면서 위의 불편함이 사라진다.

  

  

(4) 트레이스문서 분석

  

4-1) SQL 문장의 파싱 정보

  

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 60

  

• 'Misses in library cache during parse'의값이0이면 소프트 파싱, 1이면 SGA Cache에 없어서 하드 파싱이 발생한 경우이다.
• 옵티마이저 모드 정보 및 파싱 스키마 정보를 확인할 수 있다.
• Recursive SQL일 경우 Recursive Depth 정보도 나타난다.(되풀이해서 쓰이는 SQL??)

  

4-2) 실행 계획 정보

  

Rows Row Source Operation

------- ---------------------------------------------------

0 HASH GROUP BY (cr=4 pr=0 pw=0 time=284 us)

0 VIEW (cr=4 pr=0 pw=0 time=213 us)

0 HASH GROUP BY (cr=4 pr=0 pw=0 time=209 us)

0 TABLE ACCESS BY INDEX ROWID PAY_INPUT_VALUES_F (cr=4 pr=0 pw=0 time=150 us)

1 NESTED LOOPS (cr=4 pr=0 pw=0 time=136 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=132 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=132 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=130 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=128 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=127 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=127 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=125 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=123 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=122 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=121 us)

0 NESTED LOOPS (cr=4 pr=0 pw=0 time=120 us)

0 TABLE ACCESS BY INDEX ROWID PAY_PAYROLL_ACTIONS (cr=4 pr=0 pw=0 time=117 us)

0 INDEX SKIP SCAN PAY_PAYROLL_ACTIONS_N51 (cr=4 pr=0 pw=0 time=115 us)(object id 129927)

0 TABLE ACCESS BY INDEX ROWID PAY_PAYROLL_ACTIONS (cr=0 pr=0 pw=0 time=0 us)

0 INDEX UNIQUE SCAN PAY_PAYROLL_ACTIONS_PK (cr=0 pr=0 pw=0 time=0 us)(object id 129929)

….

  

• Total count 수 = 4, 사용된 CPU time = 0, elapsed time(실제 소요시간) = 0.002, Query 수= 2, Rows 수 = 1

  

• *cr

  -Consistent Read(읽기 일관성)의 약자로 Consistent Read Mode로 특정 블록을 Buffer Cache에서 읽는 것을 의미

• *pr

  -Physical Read의 약자로 특정 블록을 Disk에서 읽어 Buffer Cache에 적재하는 것을 의미

• *pw

  - Physical Write 총블록수

• *time

  - 전체 처리시간(마이크로초(1/1000000초) 단위)

• *us

  -microsecond – 1000000th of a second

  

* 위의 전체 내용이 실행계획(Execution Plan)이며 접근경로(Access Path)를 포함하고 있음

* SQL을 처리하기 위해서는 해당 데이터에 접근한 후에 연산을 수행함

* 실행 계획 : 데이터 접근 + 연산처리

  

• 접근 경로 : 데이터 내의 데이터에 접근하는 경로(방법)

  - Optimizer가 선택한 접근경로에 따라 성능 차이가 크게 발생하기 때문에 접근경로에 관심을 가져야 함

  - 접근 경로(Access Path)에는 Direct Access, Index Scan, Full Table Scan이 있음

    

• Direct Access

  -TABLE ACCESS BY USER ROWID EMPLOYEES : 실행 결과에서 다음의 내용으로 사용자가 직접 사용한 Rowid를

  통해서 테이블의 데이터에 접큰한 것으로 해석해 볼 수 있음

    

• Index Scan

  - INDEX UNIQUE SCAN EMP_EMP_ID_PK : EMP_EMP_ID_PK 라는 인덱스를 읽고 인덱스내의 Rowid를 통해서

  EMPLOYEES 테이블의 테이터에 접근한 것으로 해석해 볼 수 있음

  * Index Scan 의 종류 : UNIQUE SCAN, RANGE SCAN, FULL SCAN, SKPI SCAN, FAST FULL SCAN

    

• FULL TABLE SCAN

  -TABLE ACCESS FULL 부분으로(예시에는 없음) EMPLOYEES 테이블을 처음부터 끝가지 읽어서 해당 데이터에 접근

  * 테이블의 첫 Row가 들어있는 Block부터 마지막 Block=HWM(High Water Mark = 고수위선)까지 읽는다

  * 한번에 DB_FILE_MULTIBLOCK_READ_COUNT에서 정한 크기 만큼 읽는다 .

  * 한번에 여러 Block을 읽어들이는 MultiBlock I/O를 한다.

  * DB_FILE_MULTIBLOCK_READ_COUNT가 16이면 한번 i/o 할때 16 block 씩 scan 한다.

  * Parallel로 수행 가능하다

    

  

4-3) SQL 문장Wait 정보

  

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.00 0.00

SQL*Net message from client 2 0.14 0.15

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

  

• 이 부분은 10046 Event의8 또는12 레벨에 의해 생성되며, SQL 문장을 실행하는 데 발생되었던 Wait 정보의 요약 값을 나타낸다. 사용자가 느끼는 실행시간은SQL 문장의 실행시간과 Wait 시간의 합이므로 이들 Wait 시간을 주의 깊게 관찰할 필요가 있다.

    

• Times Waited : Wait Event가 발생했던 횟수

    

• Max. Wait : 최대로 길었던Wait 시간(초단위)

    

• Total Waited : 전체Wait 시간(초단위)

  

  

• 실행 계획

    

1. Set autotrace trace explain.

  

  

1. 오랜지나 토드를 통해서 확인.

  

Statement

Table access by index rowid employees (cr=2 pr=0 pw=0 time=39 us)

Index unique scan EMP_EMP_ID_PK (cr=1 pr=0 pw=0 tion=19 us)of EMP_EMP_ID_PK (UNIQUE)

  

• Employees 테이블 -> EMP_EMP_ID_PK(UNIQUE)의 Employees 인덱스 EMP_EMP_ID_PK(UNIQUE)스캔 (ROWS는 1번째만 이용)

  

  

<참고문헌>

Oracle Database 11g : Adminstration Workshop

Oracle Database 10g Documentation Library - councepts

원본 위치 <http://www.oracleclub.com>

원본 위치 <http://blog.daum.net/_blog/hdn/ArticleContentsView.do?blogid=0LDC4&articleno=4653784&looping=0&longOpen=>

원본 위치 <http://www.gurubee.net/pages/viewpage.action?pageId=3900657&>

원본 위치 <http://blog.naver.com/PostView.nhn?blogId=showta3&logNo=104138454&categoryNo=63&parentCategoryNo=0&viewDate=&currentPage=1&postListTopCurrentPage=1&from=search>