SQL 성능분석 Oracle Trace (1)
ORACLE trace는 SQL문의 성능 분석을 위해 사용하는 가장 기본적이며 가장 중요한 도구라고 할 수 있습니다.
ORACLE trace는 sql_trace라는 parameter 값을 변경하거나 dbms_system.set_ev procedure를 이용해 설정할 수 있습니다.
trace의 결과는 user_dump_dest parameter에 지정된 directory에 생성되며 tkprof 명령을 이용해 format할 수 있습니다.
tkprof의 결과로 생성된 파일에는 trace가 설정된 후로부터 trace가 해제되었거나 세션이 종료된 시점까지 수행된 SQL문과 PARSE, EXECUTE, FETCH 단계별로 소요시간 및 소요 자원량이 기록되어 있으며 수행시점의 ACCESS PATH가 기록되어 있습니다.
다음은 특정 SQL문을 수행한 결과 생성된 trace 파일을 tkprof로 format한 결과의 일부분 입니다.
1.
select
o.order_id
,o.order_date
,oi.line_item_id
,p.product_name
,oi.quantity
from
orders o
,order_items oi
,products p
where
o.order_id = oi.order_id
and o.customer_id = 160
and oi.product_id = p.product_id
order by
o.order_id
,oi.line_item_id
2.
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.83 0 0 0 0
Execute 1 0.01 0.01 0 0 0 0
Fetch 2 0.00 0.07 0 29 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.08 0.91 0 29 0 2
3.
Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: 52 (OE)
4.
Rows Row Source Operation
------- ---------------------------------------------------
2 SORT ORDER BY
2 NESTED LOOPS OUTER
2 HASH JOIN
2 HASH JOIN
1 TABLE ACCESS FULL ORDERS
665 TABLE ACCESS FULL ORDER_ITEMS
288 TABLE ACCESS FULL PRODUCT_INFORMATION
2 TABLE ACCESS BY INDEX ROWID PRODUCT_DESCRIPTIONS
2 INDEX UNIQUE SCAN (object id 41543)
5.
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: CHOOSE
2 SORT (ORDER BY)
2 NESTED LOOPS (OUTER)
2 HASH JOIN
2 HASH JOIN
1 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ORDERS'
665 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ORDER_ITEMS'
288 TABLE ACCESS MODE: ANALYZED (FULL) OF
'PRODUCT_INFORMATION'
2 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF
'PRODUCT_DESCRIPTIONS'
2 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'PRD_DESC_PK'
(UNIQUE)
위의 결과는 대략 5가지 부분으로 나누어질 수 있으며 각각의 부분은 다음과 같은 의미를 가집니다.
1. 수행된 SQL문
이 부분은 실제로 수행된 SQL문이 기록된 부분입니다.
2. 일량 및 시간 정보
PARSE - EXECUTE - FETCH 단계별로 기록된 수행횟수, CPU 시간 및 소요시간, Disk I/O, Memory I/O, 처리 건수의 정보를 가지고 있습니다.
이 정보를 활용해 어느 단계에서 시간이 많이 소요됐는지를 알 수 있으며 SQL문 수행시 얼마나 많은 자원을 사용했으며
최종 처리 건수가 몇 건인지를 알 수 있습니다.
주의할 점은 'cpu' 및 'elapsed'에 시간 정보가 나오려면 timed_statistics parameter값이 INSTANCE LEVEL 또는 SESSION LEVEL에서
true로 설정되어 있어야 한다는 점입니다. 만일 이 값이 false로 설정된 경우 'cpu', 'elapsed' 부분에 모두 0이 출력됩니다.
3. PARSE 관련 정보
SQL문 수행 시 Library Cache에 수행하려는 SQL문에 대한 Parse 정보가 존재하지 않아 HARD PARSE를 수행했는지의 여부와
Optimizer Mode, Parsing을 수행한 User의 ID가 표시되는 부분입니다.
4. 실행 중 실행계획
실제 SQL문 수행 중 사용된 실행계획입니다.
5. tkprof 수행시 실행계획
tkprof를 이용해 format 작업 시 생성된 실행계획입니다. 대부분의 경우 동일한 실행계획을 가지지만 실행시간과 tkprof 수행 시
관련 Object가 변경됐거나 bind 변수의 type이 틀리는 경우 서로 다른 실행계획이 나올 수 있습니다.
trace의 내용은 SQL문의 성능 문제 해결에 있어 필수적인 내용이므로 각각의 부분이 의미하는 내용을 정확히 숙지할 필요가 있습니다.
조금 더 심도있는 내용으로 들어가 보겠습니다.
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.83 0 0 0 0
Execute 1 0.01 0.01 0 0 0 0
Fetch 2 0.00 0.07 0 29 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.08 0.91 0 29 0 2
위의 일량 및 시간 정보를 보면 우선 Parse 작업에 상당한 시간이 소요됐음을 알 수 있습니다. CPU 시간을 보면 'Parse'에 소요된 시간이 0.07초, 'Execute'에 사용된 시간이 0.01초로 SQL문의 처리 준비를 위한 Parse 시간이 실제 처리하는데 사용된 시간보다 7배나 크다는 것을 알 수 있습니다. 배꼽이 배보다 커도 한참 크다는 말이지요.
순수한 CPU 시간에 각종 WAIT가 추가된 실제 소요시간은 'Parse' 단계에서는 0.83초, 'Execute'+'Parse' 단계를 합쳐 0.08초로 약 10배의 차이를 보이고 있습니다.
'Parse' 시간이 매우 컸고 이런 현상이 지속된다면 SQL문을 작성시 가능한 Bind 변수를 사용해 Shared Pool에서 최대한 공유가 잘 될 수 있는 형태로 만들어야 할 것입니다.
사용한 자원을 보면 'disk'는 'Parse','Execute','Fetch' 단계 모두 0을 표시하고 있어 물리적으로 DISK에서 읽어온 자료는 없다는 것을 의미합니다. 모두 Buffer Cache에서 읽어왔다는 말이지요.
Buffer Cache에서 읽어온 량이 바로 'query'와 'current'의 합인 29 block을 나타내고 있는 것입니다.
참고로 'query'는 'consistent gets'를 'current'는 'db block gets'와 동일한 의미를 갖습니다. 내부적인 의미가 있지만 일반적으로 두가지를 구분할 필요가 없으며 두가지 값을 더해서 Logical Read 또는 MEMORY I/O 개념으로 생각하시면 됩니다.
2건을 처리하는 과정에서 29 block을 읽어왔으므로 1 block당 8KB로 계산하면 1건 처리를 위해 116KB를 읽었다는 것을 알 수 있습니다. 이 값은 몇 가지 판단 기준이 있습니다만 절대적으로 적용하기는 약간의 무리가 있으므로 이 정도만 아시면 될 것 같습니다.
3번을 보면 처음 'Misses in library cache during parse: 1'라는 내용이 보이죠. 이 말이 의미하는 것은 'Parse' 과정 중 library cache에 수행 하려는 SQL문의 정보가 존재하지 않았다는 말입니다. 그래서 새롭게 Parse 작업을 수행했고 그 시간이 0.83초 소요된 것입니다. Parse와 관련된 좀 더 자세한 자료는 아래의 Hard Parsing에 따른 성능 문제와 효과적인 SQL 작성방법을 참고하시기 바랍니다.
4번과 5번은 어느 시점에서 본 ACCESS PATH인지만 다르므로 INDEX 이름까지 제대로 출력된 5번의 내용으로 분석하도록 하겠습니다.
이 부분에서 볼 수 있는 내용은 SQL문의 ACCESS PATH와 각 단계별 처리된 건수 입니다. 어떤 과정을 통해 2건이라는 자료가 출력됐는지를 보여주고 있기 때문에 이 부분의 내용은 상당히 중요하다고 할 수 있습니다.
예제에서는 ORDERS라는 TABLE을 FULL SCAN해서 1건을 가져왔습니다. 이 것이 효율적으로 일한 것인지 아닌지는 다른 과정을 통해 다루도록 하겠습니다.
그리고 ORDER_ITEMS라는 TABLE을 다시 FULL SCAN해서 665건을 가지고 왔으며 그 정보를 HASH JOIN해서 2건의 자료가 생성됐음을 알 수 있습니다.
PRODUCT_INFORMATION라는 TABLE을 FULL SCAN해서 288건을 가지고 왔으며 위에서 도출된 2건과 HASH JOIN한 결과 2건의 자료가 생성되었습니다.
그 2건의 자료가 PRD_DESC_PK INDEX를 이용해 PRODUCT_DESCRIPTIONS TABLE을 거쳐 역시 2건의 최종 결과가 출력되었습니다.
실제 Performance Tuning 시 위와 같은 내용들에 대한 분석이 이루어지고, 이에 대한 분석을 기초로 보다 최적의 실행계획을 만들어내는 작업을 할 수 있게 됩니다.
출처 : http://blog.daum.net/warmfeel/92