인덱스 CR Read를 분석하기 위한 다양한 트레이싱 기법 설명

지인으로부터 다음과 같은 질문을 받았습니다. “인덱스 블록에 대한 CR Read는 어떻게 이뤄지나요?” 상식적으로 생각하면 테이블 CR Read와 동일한 방식으로 수행될 것 같고, 사실 그러합니다. 그렇다면 어떤 방식으로 이 사실을 명확하게 증명할 수 있을까요? 어찌 보면 사실 그 자체보다 사실을 증명해 나가는 다양한 기법을 알고 있는 것이 엔지니어로서는 좋은 무기가 될 것입니다. 따라서 이번 포스팅에서는 몇 가지 유용한 기법을 통해서 인덱스 CR Read에 대해서 분석하는 내용을 다루려고 합니다.

그럼 본론으로 들어와서, 다음과 같은 예를 들어보겠습니다. 인덱스가 생성된 칼럼을 1건 업데이트한 후 커밋하기 전 시점에, 다른 세션에서 해당 레코드를 읽는 경우를 가정해보겠습니다. 해당 레코드를 읽는 세션은 몇 블록의 IO를 수행할까요? .

인덱스 BLEVEL에 따라서 차이가 있을 수 있지만, BLEVEL이 1이라고 가정하면, 읽어야할 블록은 7개입니다.

그렇다면 실제 검증 작업을 수행해보겠습니다.

1. 테스트 데이터 입력


sqlplus apps/apps

drop table t1 purge;
create table t1 (c1 number, c2 char(100));
create unique index t1_idx01 on t1(c1);

-- update 후에 인덱스 블록 확인 편의성을 위해서 '2'를 제외하고 입력함. 향후에 C1값을 1->2로 변경할 예정임

insert into t1 select * from (select level c1, level c2 from dual connect by level<=1000) where c1 <> 2;
commit;

exec dbms_stats.gather_table_stats(user,'t1');

select object_name, data_object_id from user_objects where object_name like 'T1%';

OBJECT_NAME  DATA_OBJECT_ID
------------ --------------
T1_IDX01              95688
T1                    95687 

-- update 문장

update t1 set c1=2 where c1=1;


2. DBMS_XPLAN을 이용한 UPDATE 수행 전/후 일량 비교


가장 먼저, IO 블록 수의 차이를 파악하기 위해 DBMS_XPLAN을 이용하겠습니다. 아래의 수행 결과에서 보듯이, UPDATE 수행 후에 해당 레코드를 조회하면 7개의 블록 IO가 발생합니다. DBMS_XPLAN 결과를 보면 인덱스 및 테이블 액세스 시에 각각 추가로 2블록을 더 읽은 것을 알 수 있습니다만, 하지만 해당 블록이 테이블 블록인지 CR Read를 위한 언두 블록인지는 확인할 수 없습니다. 이를 분석하기 위해서 10046 트레이스를 수행합니다.

-- 수행 방법

select /*+ index(t1 t1_idx01) gather_plan_statistics */ * from t1 where c1=1;

select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

CASE1> A 세션에서 update 수행 전 B 세션의 수행 결과 

----------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |          |      1 |        |      1 |00:00:00.01 |       3 |      3 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1       |      1 |      1 |      1 |00:00:00.01 |       3 |      3 |
|*  2 |   INDEX UNIQUE SCAN         | T1_IDX01 |      1 |      1 |      1 |00:00:00.01 |       2 |      2 |
-----------------------------------------------------------------------------------------------------------

CASE2> A 세션에서 update 수행 후 B 세션의 수행 결과

-----------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |          |      1 |        |      1 |00:00:00.01 |       7 |      5 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1       |      1 |      1 |      1 |00:00:00.01 |       7 |      5 |
|*  2 |   INDEX UNIQUE SCAN         | T1_IDX01 |      1 |      1 |      1 |00:00:00.01 |       4 |      4 |
-----------------------------------------------------------------------------------------------------------

3. 10046 트레이스를 이용한 블록 유형 분석


10046 트레이스 결과를 보면, 언두 헤더 블록 및 언두 블록에 대한 디스크 IO가 2블록 발생한 것을 알 수 있습니다. 이를 통해서 4블록의 차이 중에서 2블록의 차이는 확인한 셈입니다. 하지만 아직도 여전히 2블록의 차이가 어디서 발생하는지를 확인할 수가 없습니다. 추정을 해보면, 인덱스 CR Read를 위해 디스크 IO를 이용해서 읽어 들인 언두 헤더 및 언두 블록을 테이블 CR Read시에 메모리 IO를 통해서 다시 읽었다고 볼 수 있습니다. 그렇다면 이것을 증명할 수 있을까요? 오라클에서 제공하는 다양한 이벤트 중에서 10020 이벤트를 이용해서 확인해보겠습니다.

-- 수행 방법

alter session set events '10046 trace name context forever, level 8';

select /*+ index(t1 t1_idx01) */ * from t1 where c1=1;


CASE1> A 세션에서 update 수행 전 B 세션의 수행 결과

WAIT #140190168168536: nam='db file sequential read' ela= 3605 file#=6 block#=57859 blocks=1 obj#=95688 tim=13391503447
WAIT #140190168168536: nam='db file sequential read' ela= 777  file#=6 block#=57863 blocks=1 obj#=95688 tim=13391504424
WAIT #140190168168536: nam='db file sequential read' ela= 541  file#=6 block#=57854 blocks=1 obj#=95687 tim=13391506337


CASE2> A 세션에서 update 수행 후 B 세션의 수행 결과

WAIT #140190168168536: nam='db file sequential read' ela= 2140 file#=6 block#=57859 blocks=1 obj#=95688 tim=13540188640
WAIT #140190168168536: nam='db file sequential read' ela= 666  file#=6 block#=57863 blocks=1 obj#=95688 tim=13540189547
<b>WAIT #140190168168536: nam='db file sequential read' ela= 759  file#=4 block#=272   blocks=1 obj#=0 tim=13540190437
WAIT #140190168168536: nam='db file sequential read' ela= 673  file#=4 block#=3978  blocks=1 obj#=0 tim=13540191256</b>
WAIT #140190168168536: nam='db file sequential read' ela= 698  file#=6 block#=57854 blocks=1 obj#=95687 tim=13540192838

-- 272 블록 클래스는 35이므로 언두 헤더 블록

alter system dump datafile 4 block 272;

BH (0xa2f3e1b0) file#: 4 rdba: 0x01000110 (4/272) class: 35 ba: 0xa2bc0000

-- 3987 블록 클래스는 36이므로 언두 블록

alter system dump datafile 4 block 3978;

BH (0x84ef9fd8) file#: 4 rdba: 0x01000f8a (4/3978) class: 36 ba: 0x845b2000


-- 블록 클래스는 V$WAITSTAT을 이용해서 확인

select * from (select rownum rn , a.* from v$waitstat a) where rn in (35,36);
RN CLASS                   COUNT       TIME     CON_ID
---------- ------------------ ---------- ---------- ----------
35 undo header                 0          0          2
36 undo block                  0          0          2

4. 10020 이벤트를 이용한 분석


10020 이벤트는 버퍼 IO를 추적할 수 있는 좋은 방법입니다. 하지만 아쉽게도 언두에 대한 버퍼 IO 정보는 제공하지 않습니다. 따라서, 10020 이벤트의 결과는 UPDATE 전/후가 거의 동일합니다. 그렇다면 또 다른 이벤트인 10021 이벤트를 이용해서 언두에 대한 추가적인 정보를 확인해보도록 하겠습니다.

-- 수행 방법

alter session set events '10200 trace name context forever, level 1';

select /*+ index(t1 t1_idx01) */ * from t1 where c1=1;


CASE1> A 세션에서 update 수행 전 B 세션의 수행 결과

ktrgtc2(): started for block <0x0004 : 0x0180e203> objd: 0x000175c8 --> 인덱스블록 (OBJD: 95688)
ktrgtc2(): started for block <0x0004 : 0x0180e207> objd: 0x000175c8 --> 인덱스블록 (OBJD: 95688)
ktrgtc2(): started for block <0x0004 : 0x0180e1fe> objd: 0x000175c7 --> 테이블블록 (OBJD: 95687)


CASE2> A 세션에서 update 수행 후 B 세션의 수행 결과

ktrgtc2(): started for block <0x0004 : 0x0180e203> objd: 0x000175c8 --> 인덱스블록 (OBJD: 95688)
ktrgtc2(): started for block <0x0004 : 0x0180e207> objd: 0x000175c8 --> 인덱스블록 (OBJD: 95688)
ktrgtc2(): started for block <0x0004 : 0x0180e1fe> objd: 0x000175c7 --> 테이블블록 (OBJD: 95687)

5. 10021 이벤트를 이용한 분석


10021 이벤트는 CR 오퍼레이션을 분석할 수 있는 이벤트입니다. 아래의 결과를 보면, 인덱스 블록과 테이블 블록 각각에 대해서 CR Copy 오퍼레이션이 수행된 것을 알 수 있습니다. 이중에서 인덱스 블록에 대한 CR Copy 시에 언두 헤더 및 언두 블록에 대한 Disk IO가 발생했고 (10046 트레이스 결과로 확인됨), 테이블 블록에 대한 CR Copy 시에도 역시 언두 헤더 및 언두 블록에 대한 IO가 필요하나 이미 메모리에 로딩된 상태이므로 LIO로 처리하게 됩니다. 즉, 이를 통해 추가적인 2개의 버퍼 IO 역시 언두 헤더 및 언두 블록에 대한 IO라는 사실을 알 수 있습니다.

-- 수행 방법

alter session set events '10201 trace name context forever, level 1';

select /*+ index(t1 t1_idx01) */ * from t1 where c1=1;


CASE1> A 세션에서 update 수행 전 B 세션의 수행 결과

언두 READ가 없으므로 트레이스 결과 없음


CASE2> A 세션에서 update 수행 후 B 세션의 수행 결과

1) 인덱스 블록에 대한 CR Copy 작업 수행 (이때 언두 헤더 및 언두 블록에 대한 디스크 IO 발생)
Applying CR undo to block 4 : 180e207 itl entry 02: --> 180e207: file 6 block 57863 (인덱스 블록)

2) 테이블 블록에 대한 CR Copy 작업 수행 (이때 언두 헤더 및 언두 블록에 대한 메모리 IO 발생)
Applying CR undo to block 4 : 180e1fe itl entry 02: --> 180e1fe: file 6 block 57854 (테이블 블록)

추가사항. V$SESSTAT 뷰를 이용한 일량 비교


V$SESSTAT 뷰를 이용한 일량 비교도 문제 분석 시에 아주 유용하게 사용할 수 있습니다. 아주 정교한 스크립트는 아니지만 대략 아래와 같은 방법으로 Delta 일량을 비교할 수 있습니다. 아래 결과를 보면 UPDATE 후에 CR blocks created 지표가 2임을 알 수 있습니다. 즉, CR Copy 오퍼레이션으로 통해 CR 블록이 2개 생성된 것을 알 수 있습니다.

drop table temp_sess1;
drop table temp_sess2;
drop table temp_sess3;
drop table temp_sess4;

create global temporary table temp_sess1 (name varchar2(64), value number);
create global temporary table temp_sess2 (name varchar2(64), value number);
create global temporary table temp_sess3 (name varchar2(64), value number);
create global temporary table temp_sess4 (name varchar2(64), value number);
delete from temp_sess1;

insert into temp_sess1
select a.name, b.value
from   v$statname a,  (select * from v$sesstat where sid=262) b
where  a.statistic# = b.statistic# (+);
commit;

delete from temp_sess2;

insert into temp_sess2
select a.name, b.value
from   v$statname a,  (select * from v$sesstat where sid=262) b
where  a.statistic# = b.statistic# (+);

commit;
delete from temp_sess3;

insert into temp_sess3
select a.name, b.value
from   v$statname a,  (select * from v$sesstat where sid=262) b
where  a.statistic# = b.statistic# (+);
commit;

delete from temp_sess4;

insert into temp_sess4
select a.name, b.value
from   v$statname a,  (select * from v$sesstat where sid=262) b
where  a.statistic# = b.statistic# (+);

commit;

set linesize 180
set pages 100

select a.name, b.value-a.value case1, d.value-c.value case2
from   temp_sess1 a, temp_sess2 b, temp_sess3 c, temp_sess4 d
where  a.name=b.name
and    a.name=c.name
and    a.name=d.name
and    (b.value-a.value>0 or d.value-c.value>0)
and    (b.value-a.value) <> (d.value-c.value)
order by 3;

NAME                                                                  CASE1      CASE2
---------------------------------------------------------------- ---------- ----------
RowCR - row contention                                                    0          2
RowCR attempts                                                            1          2
cleanouts and rollbacks - consistent read gets                            0          2
data blocks consistent reads - undo records applied                       0          2
redo entries                                                              0          2
consistent gets pin                                                       1          2
db block changes                                                          0          2
consistent changes                                                        0          2
free buffer requested                                                     0          2
<b>CR blocks created</b>                                                         0          2
calls to kcmgas                                                           0          2
consistent gets examination (fastpath)                                    2          3
consistent gets examination                                               2          5
session logical reads                                                     3          7
consistent gets                                                           3          7
consistent gets from cache                                                3          7

사족: 인덱스 리프 블록의 변화는 어떻게 되나요?


UDDATE를 수행하기 전/후/COMMIT 후의 인덱스 리프 블록의 변화는 어떻게 될까요? 인덱스 입장에서는 UDPATE가 DELETE & INSERT 오퍼레이션으로 이뤄지니 당연히 UDPATE 후에는 새로운 레코드가 입력되고 기존 레코드는 지워집니다. 그럼 실제 지울까요? DELETE Flag만 활성화 시킬까요? 아래 내용을 통해 확인해보세요. (참고로 블록 덤프를 수행하기 전에 checkpoint를 수행해서 버퍼와 블록을 동기화 시켜야 정확한 정보를 확인할 수 있습니다)

-- 수행 방법

alter system dump datafile 6 block 57863;

-- update 전

row#0[1199] flag: ----S--, lock: 2, len=11, data:(6):  01 80 00 d5 00 00
col 0; len 2; (2):  c1 02

-- update 후 (삭제된 레코드에 -D- Flag 적용)

row#0[4557] flag: ---<b>D</b>S--, lock: 2, len=11, data:(6):  01 80 00 d5 00 00
col 0; len 2; (2):  c1 02
row#1[4568] flag: -------, lock: 2, len=11, data:(6):  01 80 00 d5 00 00
col 0; len 2; (2):  c1 03

-- Commit 후 (삭제된 레코드 유지)

row#0[4557] flag: ---<b>D</b>S--, lock: 2, len=11, data:(6):  01 80 00 d5 00 00
col 0; len 2; (2):  c1 02
row#1[4568] flag: -------, lock: 2, len=11, data:(6):  01 80 00 d5 00 00
col 0; len 2; (2):  c1 03

글을 마치며


오라클 성능 분석을 하다 보면 오라클은 너무나 많은 디버깅 툴(V$, 트레이스, Dump, DBMS 유틸리티)들을 제공하고 있다는 사실에 새삼 놀라게 됩니다. 이런 다양한 기법 중에서 현재 처한 문제를 분석하기 위해서 적절한 기법을 선택한 것도 중요한 부분인 것 같습니다.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s