오라클 성능 문제에 대한 통찰 - 조동욱 :: [티팩] Session Snapshot Report

[티팩] Session Snapshot Report - Part 1

오라클 2010/07/21 15:14

일전에 이런 질문을 다룬 적이 있습니다.

특정 세션의 성능 문제를 분석하는데 있어 가장 기본적인 뷰는 무엇일까요?

제가 이 질문을 받는다면 주저없이 V$SESSTAT이라고 대답할 것입니다.

오라클은 세션이 특정 작업을 수행할 때마다 항상 그 작업의 통계값(대부분의 경우 회수와 크기)을 V$SESSTAT 뷰에 기록합니다. 거꾸로 말하면, V$SESSTAT 뷰를 통하면 특정 세션이 어떤 작업을 수행하는지 알 수 있다는 말입니다.

이런 이유 때문에 성능 문제를 분석할 때 자연스럽게 V$SESSTAT 뷰를 많이 사용합니다. 이 뷰를 사용하다 보면 자연스럽게 다음과 같은 요구 사항이 생깁니다.

누적치를 가지고 있기 때문에 반드시 델타(Delta) 값을 계산해야 합니다.
여러 작업간의 차이를 비교할 수 있어야 합니다. 가령 작업A, 작업 B, 작업 C, 작업 D의 네 개의 작업간에 session logical reads 값이 얼마나 차이가 나는지 보고 싶은 경우들이 있습니다.

아마 성능 테스트나 트러블슈팅을 직접 해보신 경험이 있다면, 반드시 위와 유사한 요구 사항을 경험하셨을 겁니다.

특정 작업의 Snapshot을 구하고, Snapshot간의 차이를 비교하는 것. 이것이 티팩의 핵심 방법론 중 하나죠.

티팩이 제공하는 Session Snapshot Report는 위와 같은 작업을 자동화한 것입니다. 다음과 같은 방식으로 사용합니다.

exec tpack.begin_session_snapshot;

작업 A;

exec tpack.add_session_shapshot;

작업 B;

exec tpack.add_session_snapshot;

작업 C;

exec tpack.add_session_snapshot;

작업 D;

exec tpack.add_session_snapshot;

select * from table(tpack.session_snapshot_report);

Session Snapshot Report는 실제로는 V$SESSTAT 뷰 뿐만 아니라 더욱 다양한 뷰들로부터 Snapshot을 얻습니다. 각 뷰마다 중요도는 틀리지만, 상황에 따라 매우 중요한(그리고 다른 방법으로는 도저히 알 수 없는) 데이터를 제공해줍니다.

V$SESSTAT, V$SYSSTAT - 세션 혹은 시스템 레벨 STAT 정보
V$SESSION_EVENT, V$SYSTEM_EVENT - 세션 혹은 시스템 레벨 대기 정보
V$SESS_TIME_MODEL, V$SYS_TIME_MODEL - 세션 혹은 시스템 레벨 타임 모델 정보
V$LATCH - 시스템 레벨 래치 획득 정보
V$ROWCACHE - 시스템 레벨 로우 캐시 액세스 정보
V$MUTEX_SLEEP(_HISTORY) - 시스템 레벨 뮤텍스 획득 정보
Buffer Get(X$KCBSW, X$KCBWH, X$KCBUWHY) - 시스템 레벨 Buffer Get 정보
V$SGA_RESIZE_OPS - 시스템 레벨 SGA Resize 정보
V$LIBRARYCACHE - 시스템 레벨 라이브러리 캐시 액세스 정보
V$OSSTAT - 시스템 레벨 STAT 정보

결국 목적은 보다 다양한 성능 데이터를 체계적으로 분석할 수 있는 체계를 갖추는 것입니다.

간단한 예를 통해 Session Snapshot Report의 유용성을 살펴보겠습니다.

Oracle 10gR2(10.2.0.1 ~ 10.2.0.4)까지는 인덱스를 리빌드하면 Nested Loops Join 방식으로 해당 인덱스를 읽을 때 Logical Reads가 증가하는 버그가 있습니다. 이 버그를 Session Snapshot Report를 통해 살펴 보겠습니다.

1. 오라클 버전은 10.2.0.1입니다.

SQL> select * from v$version where rownum = 1;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod

2. 다음과 같이 테이블과 인덱스를 만듭니다.


SQL> create table t1(c1 int, c2 int);

Table created.

SQL> create table t2(c1 int, c2 int);

Table created.

SQL> create index t2_n1 on t2(c1);

Index created.

SQL> insert into t1
  2  select level, level
  3  from dual
  4  connect by level <= 200000;

200000 rows created.

SQL> insert into t2
  2  select level, level
  3  from dual
  4  connect by level <= 200000;

200000 rows created.

SQL> commit;

Commit complete.

3. 인덱스를 리빌드하기 전에는 INDEX RANGE SCAN(5번 단계)에서의 일량은 200,000 블록입니다. 선행 테이블 T1에서 200,000건의 로우가 추출되므로 한번의 인덱스 T2_N1에 대한 액세스마다 Logical Reads가 1씩 발생한다는 것을 알 수 있습니다.

SQL> -- before index rebuild
SQL> select /*+ gather_plan_statistics
  2  		 leading(t1) use_nl(t2) index(t2) */
  3    count(t2.c2)
  4  from
  5    t1, t2
  6  where t1.c1 = t2.c1
  7  	   and t1.c1 > 0
  8  ;

COUNT(T2.C2)
------------
      200000

SQL> select * from table(dbms_xplan.display_cursor(null, null, 'allstats last'));
--------------------------------------------------------
| Id  | Operation                    | Name  | Buffers |
--------------------------------------------------------
|   1 |  SORT AGGREGATE              |       |     201K|
|   2 |   TABLE ACCESS BY INDEX ROWID| T2    |     201K|
|   3 |    NESTED LOOPS              |       |     200K|
|*  4 |     TABLE ACCESS FULL        | T1    |     436 |
|*  5 |     INDEX RANGE SCAN         | T2_N1 |     200K|
--------------------------------------------------------

4. 인덱스 T2_N1을 리빌드합니다.

SQL> -- rebuild the index
SQL> alter index t2_n1 rebuild;

Index altered.

리빌드 후의 Logical Reads는 400,000 블록으로 정확하게 2배가 늘었습니다. 이 말은 인덱스 T2_N1을 한번 액세스할 때마다 Logical Reads가 2 발생한다는 것을 의미합니다.

SQL> -- after index rebuild
SQL> select /*+ gather_plan_statistics
  2  		 leading(t1) use_nl(t2) index(t2) */
  3    count(t2.c2)
  4  from
  5    t1, t2
  6  where t1.c1 = t2.c1
  7  	   and t1.c1 > 0
  8  ;

COUNT(T2.C2)
------------
      200000

--------------------------------------------------------
| Id  | Operation                    | Name  | Buffers |
--------------------------------------------------------
|   1 |  SORT AGGREGATE              |       |     401K|
|   2 |   TABLE ACCESS BY INDEX ROWID| T2    |     401K|
|   3 |    NESTED LOOPS              |       |     400K|
|*  4 |     TABLE ACCESS FULL        | T1    |     436 |
|*  5 |     INDEX RANGE SCAN         | T2_N1 |     400K|
--------------------------------------------------------

5. 이 현상을 Session Snapshot Report를 통해 분석해보겠습니다.

-- 인덱스를 재생성한 후(drop & create)

-- Session #1
exec tpack.begin_session_snapshot;

select /*+ gather_plan_statistics 
            leading(t1) use_nl(t2) index(t2) */
  count(t2.c2)
from 
  t1, t2
where t1.c1 = t2.c1
      and t1.c1 > 0
;

-- Session #2
alter index t2_n1 rebuild;

-- Session #1
exec tpack.add_session_snapshot;

select /*+ gather_plan_statistics 
            leading(t1) use_nl(t2) index(t2) */
  count(t2.c2)
from 
  t1, t2
where t1.c1 = t2.c1
      and t1.c1 > 0
;

exec tpack.add_session_snapshot;

col type format a10
break on type skip 1
col item format a20
col deltas format a20

select * from table(tpack.session_snapshot_report);

Session Snapshot Report의 결과 중 위의 현상과 관련 있는 것들을 추려보면 다음과 같습니다. { START_VAL = 최초의 작업이 시작하기 전의 값, END_VAL = 마지막 작업이 끝난 후의 값, TOTAL_DELTA = END_VAL - START_VAL, DELTAS = 각 단계별 Delta } 값입니다.

TYPE       ITEM                       START_VAL    END_VAL TOTAL_DELTA DELTAS
---------- ------------------------- ---------- ---------- ----------- --------------------
STAT       buffer is pinned count       1399292    2797644     1398352 799175->599177
           session logical reads         642598    1253969      611371 207133->404238
           buffer is not pinned coun     209197     410473      201276 863->200413
           t

LATCH      cache buffers chains        13161310   14396639     1235329 420897->814432

BUFF GET   kdiwh09: kdiixs               639636    1039734      400098 200098->200000
           kdiwh42: kdiixs               247335     447338      200003 4->199999

325 rows selected.

session logical reads가 200,000에서 400,000으로 증가한 것을 확인할 수 있습니다.
session logical reads가 증가한 만큼 buffer is pinned count는 줄고, buffer is not pinned count는 늘어났습니다.
kdiwh42: kdiixs 라는 오퍼레이션이 session logical reads가 증가한 만큼 증가한 것을 알 수 있습니다.

위의 지표를 분석해보건대, Buffer Pinning의 효과가 없어지면서 Logical Reads가 증가했다고 판단할 수 있습니다.

실제로 위의 현상은 인덱스를 리빌드할 경우 인덱스 루트 블록(Index Root Block)에 대한 Buffer Pinning 효과가 없어지면서 Logical Reads가 증가하는 버그입니다.(버그 번호 6455161에 해당)

아주 간단한 예같지만, V$SESSTAT 뷰에서 얼마나 중요한 데이터를 얻을 수 있는지 잘 알 수 있습니다.

티팩을 사용하는 이유가 이 Session Snapshot Report라고 할 정도로 저에게는 중요한 데이터입니다. 또는 제가 전문가라고 불리는 비결 중 하나?라고 할 수도 있겠네요. 전문가라는 것이 사실은 별 것 없고 남이 잘 보지 못하는 데이터를 추출해서 합리적으로 해석해서 문제를 해결하는 능력을 가진 자라고 본다면 말입니다.

이전 글 보기

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

인트라 블록 로우 체이닝(Intra-Block Row Chaining) (3)	2010/08/02
Long Running Query의 바인드 값 알아내기 (0)	2010/07/27
[티팩] Session Snapshot Report - Part 1 (0)	2010/07/21
엑셈의 오라클 퀴즈에 도전해보세요. (0)	2010/07/21
[퀴즈] 성능 튜닝의 절대 원칙 - 오라클에서 가장 가벼운 작업은? - 해답편 (7)	2010/07/20

tags : 티팩

Trackback 0 : Comment 0

Trackback Address :: http://ukja.tistory.com/trackback/329

Write a comment

: name

: password

: homepage secret mode

◀ PREV : [1] : ... [30] : [31] : [32] : [33] : [34] : [35] : [36] : [37] : [38] : ... [354] : NEXT ▶

태터데스크 관리자

태터데스크 메시지

티스토리 툴바

욱짜의 블로그

[티팩] Session Snapshot Report - Part 1

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

Write a comment