태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

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

티스토리 툴바