태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

TKPROF 리포트 해석시 시간값을 조심하자

오라클 2009.09.04 11:26
SQL*Trace와 그 친구인 Tkprof는 너무나 사용하기 편하고, 또 사랑스러운 친구들이지만 "시간"에 관해서는 종종 혼란을 줍니다. 흔히 접하게 되는 SQL*Trace의 시간 오류는 다음과 같습니다.
  • CPU Wait Time: 보통 대기 시간이라고 하면 경합이 발생해서 CPU를 점유하지 않고 대기하는 시간을 말하지만, CPU 자체를 획득하기 위해 대기하는 시간도 있습니다. 이 시간은 Oracle의 측정 범위 자체를 벗어나는 값입니다. 동시 사용자가 많은 시스템에서는 이 값으로 인한 오류가 더욱 커집니다.
  • CURSOR #0 시간: Oracle이 내부적으로 수행하는 특정 Query는 CURSOR#0으로 표현됩니다. 가령 LOB 데이터를 Fetch하는 과정은 부모 Cursor와는 별개로 CURSOR# 0이라는 Internal Cursor를 사용하게 됩니다. 당연히 이 시간은 부모 Cursor에 반영되지 않습니다. 실제 수행 시간은 100초인데 tkprof의 결과를 보면 1초 이렇게 나오게 됩니다. 이런 사례가 종종 존재합니다.
  • 아직 계산하지 않는 대기시간: Oracle 내부에서 대기가 발생할 때 아직 대기 이벤트로 기록되지 않는 경우도 있습니다. 이런 경우는 당연히 대기 시간에서 빠지게 됩니다.
  • 기타 등등?
아래는 측정 오류를 보여주는 테스트 결과입니다.
create table t1
as 
select level as c1, level as c2, level as c3, level as c4, level as c5
from dual
connect by level <= 1000;

select * from t1;

-- 1st 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.00       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.01       0.02          0         73          0        1000

-- 2nd 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.01       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.03       0.02          0         73          0        1000

-- 3rd 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.03       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.04       0.02          0         73          0        1000


-- 4th 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.00       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.04       0.02          0         73          0        1000
상당히 부정확해보이죠?

하지만 이런 시간 오류들은 Oracle의 잘못이라기 보다는 아키텍처 차원의 문제에 가깝습니다. 계속 보완해 나가겠지만 완전한 측정은 절대 기대해서는 안됩니다. 그래서 해석을 하는 실력이 중요한 것이지요.

저작자 표시
신고
tags : ,
Trackback 0 : Comments 5
  1. 김진호 2009.09.05 19:06 신고 Modify/Delete Reply

    감사합니다. 제가 질문한 내용을 포스팅까지 해주셨네요
    이제 오라클 시작하는 초보단계지만 열심히 해서 저도 엑셈에 도전하고 싶습니다.
    주말 잘보내세요^^

  2. 예맥 2010.04.29 11:40 신고 Modify/Delete Reply

    4th에서의 실행시간은 0.02는 1/100분초 표현한것으로 압니다. 즉, 0.0002초가 수행된것으로 해석하는데
    어느곳은 1/1000초라는 곳도 있어요.. 헷갈리네요.. 또 트레이스에서 (cr=100 pr=1649 time=1234)라고 나오면
    time은 1/1000000라고 알고 있습니다.. 왜 이렇게 오라클은 헷갈리게 표현할까요? 제가 아는 단위가 정확한가요?

    • 욱짜 2010.04.29 15:55 신고 Modify/Delete

      Tkprof의 집계리포트에서 보여주는 부분(Parse/Execute/Fetch)은 초(second)단위입니다. 즉, 0.02는 0.02초입니다.

      최근 버전의 오라클에서는 시간을 측정할 때 항상 Microsecond(1/1000000)초를 사용합니다. 따라서 (cr=100 pr=1649 time=1234)에서의 time은 0.001234초가 됩니다. 10046 트레이스 파일에서도 CPU 사용시간은 Centisecod단위로 계산되는 것으로 알려져 있습니다. 이때문에 CPU 사용시간이 Elapsed Time보다 크게 나타나는 현상이 생깁니다.

      기타 Dynamic View에서는 아직도 많은 경우 Centisecond의 단위를 사용하고 있습니다.

  3. 예맥 2010.04.29 16:50 신고 Modify/Delete Reply

    call count elapsed
    -------------------------------
    Parse 1 0.77
    Execute 1 0.21
    Fetch 1 50583.26
    ------
    Rosw Row Source Operation
    ------------------------------------------
    0 Table Access Full EMP (cr=5393 pr=4804 pw=0 time=5058305us)

    라고 되어있는데 이경우는 row souce가 1/백만 초 이므로 elapse time을 5초로 보아야하지 않나요?
    만약 버전 마다 틀리면 어떻게 해석하죠..
    욱짜님의 parse/execute/fetch 단위가 초이면 틀려지는것이 아닌가요? 참고로 위의 내용은 엔코아의 da#
    으로 트레이스를 남겼을때의 내용입니다.. 더 헷갈립니다..
    늘 빠른 답변, 정확한 답변에 감사드립니다.

    • 욱짜 2010.04.29 20:22 신고 Modify/Delete

      동일한 쿼리를 Oracle이 제공하는 tkprof를 이용하면 어떻게 나오나요?

Write a comment

티스토리 툴바