'오라클 트레이스'에 해당되는 글 1건



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

'1. IT Story > DB' 카테고리의 다른 글

Oracle SQL Sub-query(기초)  (0) 2012.02.29
Oracle HINT(기초)  (0) 2012.02.29
Oracle SQL Driving Table & JOIN(기초)  (0) 2012.02.29
Oracle SQL INDEX(기초)  (0) 2012.02.29
아카이브 로그 모드 Archive Log Mode  (0) 2012.02.29
Oracle TableSpace  (0) 2012.02.29
Oracle Undo seg  (0) 2012.02.29
Oracle Redo Log  (0) 2012.02.29
블로그 이미지

운명을바꾸는자

IT와 함께 살아가는 삶

,