태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'buffer is pinned count'에 해당되는 글 2건

  1. 2009.05.19 Buffer Pinning, Logical Reads, Elapsed Time (4)
  2. 2008.01.21 Oracle 10g vs. Oracle 11g - Buffer Pinning and Logcial Reads (2)

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


Oracle 10g vs. Oracle 11g - Buffer Pinning and Logcial Reads

오라클 2008.01.21 20:52

(실수로 글을 삭제해서 다시 올립니다)

아래의 간단한 테스트 결과를 보자.

create table t_join1(id int, name char(10));
create table t_join2(id int, name char(10));

create index t_join1_idx on t_join1(id);
create index t_join2_idx on t_join2(id);

insert into t_join1
select rownum, 'name' from all_objects where rownum <= 10000;

insert into t_join2
select rownum, 'name' from all_objects where rownum <= 5000;

commit;

exec dbms_stats.gather_table_stats(user, 'T_JOIN1', cascade=>true);
exec dbms_stats.gather_table_stats(user, 'T_JOIN2', cascade=>true);

select /*+ gather_plan_statistics ordered use_nl(t_join1 t_join2) */
   t_join1.id
from t_join1, t_join2
where t_join1.id = t_join2.id;

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

즉, 10000건의 t_join1 테이블과 5000건의 t_join2 테이블을 Index만을 경유해서 Nested Loop 조인해서 가져오는 쿼리를 수행하는 간단한 테스트이다.

결과를 보기 전에 예측을 해볼 수 있다.

1. Hint에 의해 t_join_idx1 인덱스를 Full Scan하면서 t_join2_idx 인덱스를 매번 방문하는 Nested Loop Join 실행 경로를 따른다.
2. 두 인덱스 모두 높이가 2이다. (analyze index <index_name> validate structure 로 확인 가능)
3. t_join1 테이블이 로우 수가 10,000 건이므로 t_join2_idx 인덱스를 10,000번 경유해야 한다. t_join2_idx 인덱스의 높이가 2이므로 한번 액세스마다 2블록을 읽어야 한다.
따라서 t_join2_idx 인덱스에 대한 Logical Reads 20,000 블록 정도가 되어야 하며, 이것이 가장 성능에 많은 영향을 미친다.

아래 결과를 보자. (gather_plan_statistics 힌트를 이용한다. 자세한 내용은 여기를 참조한다)

일단 10g에서의 결과는 다음과 같다.
-----------------------------------------------------------------------------------------------
| Id  | Operation             | Name        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------
|   1 |  NESTED LOOPS         |             |      1 |   5000 |   5002 |00:00:00.04 |   11056 |
|   2 |   INDEX FAST FULL SCAN| T_JOIN1_IDX |      1 |  10000 |  10000 |00:00:00.01 |     378 |
|*  3 |   INDEX RANGE SCAN    | T_JOIN2_IDX |  10000 |      1 |   5002 |00:00:00.05 |   10678 |
-----------------------------------------------------------------------------------------------


일단 예상대로 t_join2_idx 에 대한 일량이 대부분을 차지한다. 하지만 우리가 예상한 20,000 블록의 절반 정도에 불과한 것을 알 수 있다. 왜 이런 현상이 발생할까?

이것은 Buffer Pinning이라고 부르는 효과에 의한 것이다. 오라클은 한번의 콜(Fetch)에서 연속적으로 액세스되는 블록을 "Pin"해서 추가적으로 다시 SGA를 탐색하는 과정없이 재활용할 수 있도록 해준다. 위의 결과를 보면 우리가 예상한 20,000 블록이 아닌 그 절반 정도에 해당하는 10,000 블록만을 읽었음을 보여준다. 오라클은 루트 노드에 해당하는 블록에 대해서 Buffer Pinning을 수행해서 그만큼 블록 읽기 회수를 줄여주었다.

Buffer Pinning에 의한 블록을 재활용한 회수는 buffer is pinned count 라는 통계값으로 확인 가능한데, 실제로 위의 테스트를 수행하면 buffer is pinned count는 약 10,000 블록의 값을 보인다. 즉, 루트 노드에 대한 반복적인 읽기 작업을 절약했다는 의미이다.

이제 11g에서의 테스트 결과를 보자.

-----------------------------------------------------------------------------------------------
| Id  | Operation             | Name        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------
|   1 |  NESTED LOOPS         |             |      1 |   5000 |   5000 |00:00:00.12 |    1716 |
|   2 |   INDEX FAST FULL SCAN| T_JOIN1_IDX |      1 |  10000 |  10000 |00:00:00.02 |     673 |
|*  3 |   INDEX RANGE SCAN    | T_JOIN2_IDX |  10000 |      1 |   5000 |00:00:00.07 |    1043 |
-----------------------------------------------------------------------------------------------


놀랍게도 t_join2_idx 인덱스에 대한 Logical Reads 10g에서의 1/10 수준에 불과하다. 이것은 오라클이 Buffer Pinning에 의한 Logical Reads 줄이기를 매우 적극적으로 수행한다는 것을 암시하며, 인덱스의 리프 노드에 대해서도 Buffer Pinning이 적용된다는 것을 의미한다. 즉 한번의 콜(Fetch)에서 연속적으로 액세스되는 리프 노드에 대해서도 오라클은 추가적인 Logical Reads를 일으키지 않는다.

한가지 이상한 것은 이러한 개선된 Buffer Pinning을 관찰할 지표를 알 수 없다는 것이다. buffer is pinned count 통계값에는 이러한 현상이 반영되지 않는다. 아쉽게도 어떤 값을 통해서 리프 노드에 대한 Buffer Pinning이 발생했는지 확인할 수 있는지는 아직 밝혀내지 못한 상태이다.

한 가지 주의할 것은 위와 같은 Buffer Pinning의 효과는 한번의 콜(Fetch)에서 동일 블록을 액세스할 때만 의미가 있다는 것이다. 위의 테스트에서는 t_join1_idx 인덱스와 t_join2_idx 인덱스가 거의 동일하게 정렬이 되어 있으므로 성능 개선 효과가 아주 극단적으로 개선된 것처럼 보인다.
만일 정렬 순서가 심하게 흩어져 있다면 효과는 크게 반감될 것이다.

위의 테스트 결과는 오라클이 Nested Loop Join에 의한 Random Access I/O를 줄이기 위해 얼마나 많은 노력을 기울지는를 잘 보여준다. Nested Loop Join에 의한 Random I/O는 비용이 매우 크기 때문에 일반적으로 대량의 데이터에대해서는 Nested Loop Join보다는 Hash Join을 선호하게 된다. 하지만 위의 테스트 결과가 보는 것처럼, 11g에서는대량의 데이터에 대한 Nested Loop Join이 더 이상 과거처럼 비효율적인지 않을 수도 있음을 알 수 있다.

오라클의 노력이 가상할 뿐이다.

(참고) 위와 같은 확장된 Buffer Pinning 효과는 굳이 NL Join 뿐만 아니라 인덱스 리프 노드를 반복적으로 액세스하는 모든 오퍼레이션에서 동일하게 적용된다. 가령 In (1,2,3,4, ..., 100) 과 같은 InList Operation도 동일한 혜택을 받게 된다.

신고
Trackback 1 : Comments 2
  1. 멀더엄마 2008.02.01 11:05 신고 Modify/Delete Reply

    EXPLAIN PLAN FOR
    select /*+ gather_plan_statiscs ordered use_nl (tmp_join1 tmp_join2) */
    tmp_join1.id
    from tmp_join1, tmp_join2
    where tmp_join1.id = tmp_join2.id;

    SELECT * FROM TABLE(dbms_xplan.display);

    이렇게하면 플랜이 조회가 되는데...


    select * from table(dbms_xplan.display_cursor(null, null, 'ALLSTATS LAST'));
    이 쿼리를 수행할때 ORA-00904 열명이 부적합합니다. 이러케 나오네용. 아....... 9i 라서 그런감?

  2. 욱짜 2008.02.01 14:05 신고 Modify/Delete Reply

    gather_plan_statistics 힌트와 dbms_xplan.dispaly_cursor는 10g부터만 지원되는 기능이라서~

Write a comment

티스토리 툴바