태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'SQL*Trace'에 해당되는 글 2건

  1. 2009.09.04 TKPROF 리포트 해석시 시간값을 조심하자 (5)
  2. 2009.05.19 Buffer Pinning, Logical Reads, Elapsed Time (4)

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 : SQL*Trace, tkprof
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


Buffer Pinning, Logical Reads, Elapsed Time

오라클 2009.05.19 11:42
SQL*Trace는 Query가 어떻게 얼마나 효율적으로 수행되는지를 파악하는 가장 기본적인 도구이다.

하지만 그 결과를 해석할 때 조심해야 할 몇 가지 함정들이 있다. 그 중에서도 상당히 해석하기가 까다로운 사례를 하나 보자.

아래 결과를 면밀히 비교해 보면...

SELECT /*+ index(t1 t1(c1)) */ COUNT(C3)
FROM
 T1 WHERE C1 > 0

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    100      0.00       0.00          0          0          0           0
Fetch      100     11.51      11.51          0     178800          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      201     11.51      11.52          0     178800          0         100

Rows     Row Source Operation
-------  ---------------------------------------------------
    100  SORT AGGREGATE (cr=178800 pr=0 pw=0 time=11513907 us)
10000000   TABLE ACCESS BY INDEX ROWID T1 (cr=178800 pr=0 pw=0 time=166705427 us)
10000000    INDEX RANGE SCAN T1_N1 (cr=20000 pr=0 pw=0 time=40426316 us)



SELECT /*+ index(t1 t1(c2)) */ COUNT(C3)
FROM
 T1 WHERE C2 > 0

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute    100      0.00       0.00          0          0          0           0
Fetch      100     25.78      25.77          0    9711400          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      201     25.78      25.78          0    9711400          0         100

Rows     Row Source Operation
-------  ---------------------------------------------------
    100  SORT AGGREGATE (cr=9711400 pr=0 pw=0 time=25775700 us)
9990800   TABLE ACCESS BY INDEX ROWID T1 (cr=9711400 pr=0 pw=0 time=184934979 us)
9990800    INDEX RANGE SCAN T1_N2 (cr=25700 pr=0 pw=0 time=40795883 us)


무언가 비상식적인 것을 발견할 수 있다.

Logical Reads의 차이는 178800:9711400 = 약 54배의 차이
하지만 실행 시간의 차이는 11.52:25.78 = 약 2.2배의 차이

왜 Logical Reads의 차이는 엄청나게 큼에도 불구하고 실행 시간의 차이는 고작 2배 정도에 불과할까? 불행하게도 SQL*Trace(+tkprof)의 결과만으로는 해석이 불가능하다.

우선 Index의 통계정보를 보면 재미있는 사실을 알 수 있다.

UKJA@ukja102> @ind_stat t1
UKJA@ukja102> set echo off
TABLE_NAME                    : T1                                             
INDEX_NAME                    : T1_N1                                          
BLEVEL                        : 1                                              
LEAF_BLOCKS                   : 199                                            
DISTINCT_KEYS                 : 100000                                         
CLUSTERING_FACTOR             : 1588             <-- Good CF                                
SAMPLE_SIZE                   : 100000                                         
GLOBAL_STATS                  : YES                                            
LAST_ANAL                     : 2009/05/19 11:25:16                            
-----------------                                                              
TABLE_NAME                    : T1                                             
INDEX_NAME                    : T1_N2                                          
BLEVEL                        : 1                                              
LEAF_BLOCKS                   : 256                                            
DISTINCT_KEYS                 : 1000                                           
CLUSTERING_FACTOR             : 96947          <-- Bad CF                                   
SAMPLE_SIZE                   : 100000                                         
GLOBAL_STATS                  : YES                                            
LAST_ANAL                     : 2009/05/19 11:25:17                            
-----------------                      
                                        

Index t1_n1과 t1_n2 사이의 큰 차이가 Clustering Factor에 있다는 것을 알 수 있다. 여기까지 오면 경험이 있는 분들은 아항! Clustering Factor의 차이에 의해 buffer pinning이 이루어진 회수의 차이 때문이구나! 라는 추측을 하게 될 것이다.

이것을 증명하기 위해서는 SQL*Trace 외에도 V$SESSTAT 같은 뷰를 통해 실행 시점의 일량을 파악해야 한다.

NAME                                           VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
buffer is pinned count                     19,841,100   10,295,800   -9,545,300
...
consistent gets                               178,815    9,711,414    9,532,599

Logical Reads의 차이만큼 buffer is pinned count가 이루어진 것을 알 수 있다. Buffer Pinning에 의해 Block을 다시 읽을 때는 Latch를 획득하고 Cache Chain을 탐색하는 일련의 과정은 없어지지만 Buffer를 읽는 행위 자체는 발생할 수 있다. 따라서 수행 시간이 수행 회수에 비례해서 감소하지는 않는 것이다.

그렇다면 Latch 획득은 얼마나 차이가 날까?

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS     
------------------------------ ---------- ---------- ---------- ----------     
cache buffers chains             19065334          0          0         17     
simulator hash latch               577910          0          0          0     
simulator lru latch                577909          1          0          1     
...


cache buffers chains latch의 획득 회수의 차이는 19,065,334인데 이 값은 Logical Reads의 차이인 9,532,59의 2배에 해당한다는 것을 알 수 있다.

Oracle은 한번의 Logical Reads에 대해 2번의 Latch 획득과 한번의 Latch Upgrade를 한다는 것의 간접적인 증명이기도 하다.

SQL*Trace(+tkprof)의 결과를 항상 100% 숫자 그대로 믿을 수 없는 상황이 의외로 많이 존재한다는 사실을 명심하기를! 분석할 Data는 많을수록 좋고 서로가 서로를 보완 설명하는 경우가 많다는 것도 기억하자.

PS) Buffer Pinning의 개념은 여기에서 얻을 수 있다.
신고

'오라클' 카테고리의 다른 글

SIMILAR cursor sharing의 문제  (0) 2009.06.02
Index 공간 재활용에 대한 오해는 뿌리 깊다.  (0) 2009.05.27
Buffer Pinning, Logical Reads, Elapsed Time  (4) 2009.05.19
Bind 변수 값 알아내기  (1) 2009.05.07
V$SQL_HINT View  (0) 2009.05.04
Trackback 0 : Comments 4
  1. 김진호 2009.09.03 13:24 신고 Modify/Delete Reply

    동욱님 죄송한데 질문하나 드려도 될런지..
    tkprof 분석결과가
    select *
    from
    big_emp


    call count cpu elapsed disk query current rows
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    Parse 1 0.03 0.01 0 0 0 0
    Execute 1 0.00 0.00 0 0 0 0
    Fetch 1932 0.01 0.04 0 2109 0 28955
    ------- ------ -------- ---------- ---------- ---------- ---------- ----------
    total 1934 0.04 0.05 0 2109 0 28955

    Misses in library cache during parse: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 54
    이렇게 나왔습니다.
    제가 질문드리고 하는게 cpu time이 elapsed time보다 왜 더 많이 나오는것일까요? 제상식으로는 이해가 안되네요. 조언좀 부탁드립니다.

    • 욱짜 2009.09.03 17:02 신고 Modify/Delete

      번거로우시겠지만, 위의 질문을 다른 분들도 공유할 수 있도록 Ask Exem에 올려주시겠습니까?

      http://ask.ex-em.com

      Email 주소만 정확하게 적어주시면 게시판을 통해 질문/답변/의견 교환이 가능합니다. Email 주소는 외부에 노출되지 않으므로 걱정하지 않으셔도 됩니다.

  2. 그와함께 2009.09.04 09:51 신고 Modify/Delete Reply

    Tom Kyte의 Effective Oracle by Design 책에 이 문제에 관한 답이 나와 있습니다. 확인해보세요.

  3. 햇살아이 2011.03.23 10:57 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment

티스토리 툴바