태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'티팩'에 해당되는 글 12건

  1. 2010.08.11 Direct Path Insert와 Redo 데이터 (7)
  2. 2010.08.04 [티팩] Session Snapshot Report - Part 2
  3. 2010.07.27 Long Running Query의 바인드 값 알아내기
  4. 2010.07.21 [티팩] Session Snapshot Report - Part 1
  5. 2010.07.13 [티팩] 지능적인 대기 이벤트 분석 - Part3. (대기이벤트 프로파일링)
  6. 2010.07.01 V$SQL 관련 뷰 조회하기 (1)
  7. 2010.06.29 [티팩] 지능적 대기 이벤트 분석 - Part 1
  8. 2010.06.28 [퀴즈] Partitioned Table과 Insert 성능 - 해답편 + 티팩 (4)
  9. 2010.06.24 [티팩] oradebug
  10. 2010.06.22 [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame) (6)

Direct Path Insert와 Redo 데이터

오라클 2010.08.11 15:00
의외로 많은 분들이 아직도 Direct Path Insert(INSERT /*+ APPEND */ ... 포함)와 Redo 생성량간의 관계에 대해서 헷갈려하시는 것 같습니다.

Direct Path Insert에서 Redo 생성량에 영향을 주는 기본적인 요소는 다음과 같습니다.

  • 데이터베이스가 ARCHIVELOG 모드인가, NOARCHIVE LOG 모드인가?
  • 테이블이 LOGGING 모드인가, NOLOGGING 모드인가?
  • 테이블에 인덱스가 존재하는가?
위의 세가지 요소에 대해 Redo 생성량이 어떻게 되는지 아래와 같이 테스트해보겠습니다. (V$SESSTAT에서 redo size, redo entries를 수집하고 그 값을 비교하기 위해 티팩을 사용합니다)
set echo on
set pages 10000
set lines 200
set timing off
set trimspool on
set serveroutput off

drop table t_log_no_idx purge;
drop table t_log_with_idx purge;
drop table t_nolog_no_idx purge;
drop table t_nolog_with_idx purge;

create table t_log_no_idx (c1 char(100)) logging;
create table t_log_with_idx (c1 char(100)) logging;
create table t_nolog_no_idx (c1 char(100)) nologging;
create table t_nolog_with_idx (c1 char(100)) nologging;

create index t_log_with_idx_n1 on t_log_with_idx(c1) ;
create index t_nolog_with_idx_n1 on t_nolog_with_idx(c1) ;

----------------------------------------------
-- case 1: noarchive log mode + no_index
select name, log_mode from v$database;   -- NOARCHIVELOG

truncate table t_log_no_idx;
truncate table t_log_with_idx;
truncate table t_nolog_no_idx;
truncate table t_nolog_with_idx;

exec tpack.begin_session_snapshot;

insert into t_log_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_log_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_nolog_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

col type format a6 
col item format a30 
col deltas format a30
select type, item, deltas 
from table(tpack.session_snapshot_report)
where type = 'STAT' and item in ('redo size', 'redo entries')
;

----------------------------------------------
-- case 2: noarchive log mode + with_index
select name, log_mode from v$database;

truncate table t_log_no_idx;
truncate table t_log_with_idx;
truncate table t_nolog_no_idx;
truncate table t_nolog_with_idx;

exec tpack.begin_session_snapshot;

insert into t_log_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_log_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_nolog_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

commit;

col type format a6 
col item format a30 
col deltas format a30
select type, item, deltas 
from table(tpack.session_snapshot_report)
where type = 'STAT' and item in ('redo size', 'redo entries')
;


-----------------------------------------------
-- alter database to archive log mode
connect sys/password as sysdba
shutdown immediate
startup mount
alter database archivelog;
alter database open;

connect user/password

----------------------------------------------
-- case 3: archive log mode + no_index
select name, log_mode from v$database;   -- ARCHIVELOG

truncate table t_log_no_idx;
truncate table t_log_with_idx;
truncate table t_nolog_no_idx;
truncate table t_nolog_with_idx;

exec tpack.begin_session_snapshot;

insert into t_log_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_log_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_nolog_no_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

col type format a6 
col item format a30 
col deltas format a30
select type, item, deltas 
from table(tpack.session_snapshot_report)
where type = 'STAT' and item in ('redo size', 'redo entries')
;


----------------------------------------------
-- case 4: archive log mode + with_index
select name, log_mode from v$database;

truncate table t_log_no_idx;
truncate table t_log_with_idx;
truncate table t_nolog_no_idx;
truncate table t_nolog_with_idx;

exec tpack.begin_session_snapshot;

insert into t_log_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_log_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

insert /*+ append */ into t_nolog_with_idx select 'x' from dual connect by level <= 100000;

exec tpack.add_session_snapshot;

commit;

col type format a6 
col item format a30 
col deltas format a30
select type, item, deltas 
from table(tpack.session_snapshot_report)
where type = 'STAT' and item in ('redo size', 'redo entries')
;
Redo Size의 측정 결과를 정리해보면 아래 표와 같습니다.

.

NOARCHIVEARCHIVE

.

LoggingNologgingLoggingNologging

.

No IndexConventional13,327,16413,327,16413,353,08813,353,088

.

Direct 1,317,3721,351,51213,419,2281,360,888

.

With IndexConventional80,755,88480,755,88481,188,59281,188,592

.

Direct 55,740,47248,755,74067,802,16848,652,796

.

간단하게 정리해보면 다음과 같네요.

  1. NOARCHIVELOG 모드일 경우에는 테이블의 Logging 모드 여부에 상관없이 Direct Path Insert는 최소의 Redo를 생성한다.
  2. ARCHIVELOG 모드일 경우에는 테이블이 Nologging 모드여야만 Direct Path Insert가 최소의 Redo를 생성한다.
  3. 인덱스가 존재할 경우에는 Nologging모드에서 Direct Path Insert를 수행하더라도 적지 않은 Redo를 생성한다. 인덱스를 변경하는 과정에서의 Redo는 여전히 생성되기 때문이다.
세 번째 이유 때문에 보통 대량의 데이터를 Direct Path Insert로 추가할 경우에는 인덱스를 비활성화시킨 후 Insert가 끝나고 나면 리빌드하는 방법을 많이 사용합니다.

이 외에 Direct Path Insert에서 헷갈려하시는 내용들에는 다음과 같은 것들이 있습니다.

  • INSERT ... VALUES ... 구문도 Direct Path Insert가 되는가? 이 문제는 이 블로그 포스트에서 상세하 다룬바 있습니다. 요약하면, Oracle 10g까지는 불가능, Oracle 11gR1에서는 APPEND 힌트, Oracle 11gR2에서는 APPEND_VALUES 힌트를 사용하면 됩니다.
  • UPDATE나 DELETE 문장에서도 Direct Path Mode가 가능한가? 더 정확하게 말하면 최소한의 Redo를 생성하는 방식의 UPDATE나 DELETE 수행이 가능한가?입니다. 상식적으로 생각해보면 불가능하다는 판단을 내릴 수 있습니다. INSERT 문장이 Direct Path Mode가 가능한 것은 새로운 데이터의 추가이기 때문입니다. 기존 데이터를 변경하지 않기 때문에 테이블에 TM 락을 Exclusive하게 걸어버리고, High Water Mark 위에 데이터를 Append해버리면 됩니다. 중간에 에러가 생기면 추가된 공간을 무시해버리면 되기 때문에 Redo를 생성하지 않는 옵션이 가능합니다. 하지만 UPDATE나 DELETE는 기존 데이터를 변경하는 것이기 때문에 반드시 Redo가 생성됩니다.
제가 자주 접했던 질문에 대한 대답은 위의 내용 정도로 정리가 가능하겠습니다. 그 외에도 Redo 생성과 관련해서 이슈들이 많을텐데 기회가 닿은 대로 논의하면 좋겠네요.
저작자 표시
신고
tags : APPEND, Redo, 티팩
Trackback 0 : Comments 7
  1. 라튜니 2010.08.11 20:33 신고 Modify/Delete Reply

    항상 좋은 정보를 얻고 있습니다. 먼저 감사의 말씀을 드립니다.

    다름이 아니라 글을 보고 궁금한 점이 있어 염치불구 하고 이렇게 질문 드립니다.

    NOARCHIVE, ARCHIVE 모드 관계없이 인덱스가 있을 경우는 상당량의 REDO가 발생하는데요.

    인덱스가 있는 경우 해당 인덱스에도 NOLOGGING 모드로 설정해 버리면

    생성되는 REDO가 줄어드나요? 아님 인덱스 자체도 NOLOGGING 모드로 설정가능하지만,

    인덱스의 경우 KEY값의 순서에 해당하는 블록에 INSERT 되어야 하기 때문에

    NOLOGGING 모드 설정 자체가 큰 의미가 없는건지요? 궁금하네요~ 답변 부탁드립니다.


    여름철 건강 관리 잘 하시고 좋은 하루 되시길~

    • 욱짜 2010.08.12 09:11 신고 Modify/Delete

      말씀하신 것처럼 위의 예에서는 인덱스에 대한 Logging 모드는 의미가 없습니다. 스크립트에 오해의 소지가 있으므로 그 부분은 수정하도록 하겠습니다.

  2. 2dong0 2010.08.13 14:51 신고 Modify/Delete Reply

    언제나 좋은 정보 감사합니다.^^
    저도 욱짜님처럼 오라클을 완벽하게 이해하고 있으면 좋겠습니다^^ㅋㅋ

    • 욱짜 2010.08.13 15:21 신고 Modify/Delete

      완벽하게 이해하고 있다는 것은 오해의 소지가 있는데요?

      저는 성능 문제에 있어 가능한 많은 데이터를 분석하고 가능한 정확한 결론을 내리게끔 노력할 뿐입니다. 그리고 그런 방법을 공유하는 것 뿐이구요.

      완벽하게 이해했다면 이미 이 업계를 떠났을 겁니다. :)

  3. 2dong0 2010.08.15 20:41 신고 Modify/Delete Reply

    그저 제가 보기에 완변해보이실뿐입니다^^
    언제나 좋은 정보 공유해 주셔서 감사할 따름입니다
    업계를 떠나시는 그날까지 화이팅!!! 하세요^^

  4. 열심남 2010.08.16 13:24 신고 Modify/Delete Reply

    저도 담부터는 대량 작업이 잇으면 인덱스 disable하고 리빌드 하는 방식으로 가이드를 해야겠네요 ^^: 감사합니다.

    • 욱짜 2010.08.16 14:17 신고 Modify/Delete

      한가지 주의할점이 있습니다. 만일 새롭게 추가되는 데이터의 양에 비해 인덱스의 크기가 매우 크다고 하면(즉 기존의 데이터가 훨씬 많으면) 오히려 인덱스를 리빌드하는 것이 더 부담이 될 수도 있습니다. 데이터의 양에 따라 적절히 안배하면 되겠습니다.

Write a comment


[티팩] Session Snapshot Report - Part 2

오라클 2010.08.04 14:13
얼마전 오라클에서 가장 가벼운 작업은?이라는 퀴즈를 낸 적이 있었습니다. 그 때 답변으로 제시된 것은 이것입니다.
begin 
   null;
end;
/
의문을 가질 수 있습니다? 정말 제일 가벼운가? 얼마나 가벼운가? 특히 { select 1 from dual (fast dual일 경우) }와 비교하면 어떠한가?

이런 의문에 답을 할 수 있는 제일 좋은 도구가 티팩이 제공하는 Session Snapshot Report입니다. Session Snapshot Report는 V$SES[SYS]STAT, V$LATCH, V$SES[SYS]_TIME_MODEL, V$SESSION[SYSTEM]_EVENT 등 성능 분석에 필요한 핵심적인 뷰들에 대한 비교를 가능하게 해주기 때문입니다.

Session Snapshot Report를 이용해서 { select 1 from dual }{ begin null; end; }의 성능이 어떤 차이를 보이는지 분석해보겠습니다.

1. 두 경우를 루프를 돌면서 각각 100,000번 수행하고 그 차이를 Session Snapshot Report를 통해 분석해보겠습니다.

TPACK@ukja1021> exec tpack.begin_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
TPACK@ukja1021> 
TPACK@ukja1021> declare
  2  	     v1      number;
  3  begin
  4  	     for idx in 1 .. 100000 loop
  5  		     select 1 into v1 from dual;
  6  	     end loop;
  7  end;
  8  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:02.70
TPACK@ukja1021> 
TPACK@ukja1021> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
TPACK@ukja1021> 
TPACK@ukja1021> declare
  2  	     v1      number;
  3  begin
  4  	     for idx in 1 .. 100000 loop
  5  		     begin null; end;
  6  	     end loop;
  7  end;
  8  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.00
TPACK@ukja1021> 
TPACK@ukja1021> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.10
TPACK@ukja1021> 
TPACK@ukja1021> col type format a10
TPACK@ukja1021> col item format a40
TPACK@ukja1021> col deltas format a20
TPACK@ukja1021> select type, item, deltas from table(tpack.session_snapshot_report);
Report는 아래와 같습니다(큰 차이를 보이는 부분만 편집). Call수, Execute Count, Time, Library Cache 래치와 Library Cache Pin의 획득 개수에서 { select 1 from dual }이 압도적으로 불리한 것을 알 수 있습니다. { begin null; end; }가 가장 가벼운 작업이라는 것이 증명된 것일까요?
TYPE       ITEM                                     DELTAS
---------- ---------------------------------------- --------------------
STAT       recursive calls                          100038->36
STAT       calls to get snapshot scn: kcmgss        100024->23
STAT       execute count                            100014->14

TIME       DB time                                  2792453->97955
TIME       sql execute elapsed time                 2791349->96441
TIME       DB CPU                                   2792453->92407

LATCH      library cache                            200066->56
LATCH      library cache pin                        200046->40
사실 위의 테스트는 함정을 가지고 있습니다. PL/SQL 블록내에서 수행되기 때문에 일반적인 쿼리의 수행 패턴이 아니라는 함정입니다. 일반적인 쿼리는 클라이언트에서 SQL*Net을 통해 쿼리를 수행 요청하고, 서버는 그 결과 중 일부를 클라이언트에게 보내주고, 클라이언트는 다시 다음 번 결과를 요청(페치)하는 일련의 과정을 거칩니다.

2. 이 함정을 피하기 위해 다음과 같이 개별 쿼리를 각각 10,000번씩 수행하도록 스크립트를 생성합니다.

spool select_dual.sql
select 
	'select 1 from dual; '
from dual 
connect by level <= 10000;
spool off


spool null.sql
select 
	'begin null; end; ' || chr(10) || '/'
from dual 
connect by level <= 10000;
spool off
3. 위에서 생성한 스크립트를 이용해 동일한 성능 비교를 수행합니다.
TPACK@ukja1021> exec tpack.begin_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.10
TPACK@ukja1021> 
TPACK@ukja1021> @select_dual
...

TPACK@ukja1021> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
TPACK@ukja1021> 
TPACK@ukja1021> @null
...

TPACK@ukja1021> exec tpack.add_session_snapshot;

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
TPACK@ukja1021> 
TPACK@ukja1021> col type format a10
TPACK@ukja1021> col item format a40
TPACK@ukja1021> col deltas format a20
TPACK@ukja1021> select type, item, deltas from table(tpack.session_snapshot_report);
Report는 아래와 같습니다(큰 차이를 보이는 부분만 편집). 전혀 다른 모습을 보입니다.
  • User Calls 수에서는 { select 1 from dual }이 더 많습니다.
  • Network을 통한 데이터 전송도 { select 1 from dual }이 더 많습니다. 한건이라고는 사지만 페치가 이루어지기 때문입니다.
  • Execute Count는 동일합니다. 앞서의 비교에서는 { select 1 from dual }의 Execute Count가 훨씬 많았던 것과는 차이가 있습니다.
  • 수행 시간(DB time)의 차이도 크게 줄었습니다. 시간면에서의 차이는 거의 없다고 보입니다.
  • 재미있는 것은 { begin null; end; }가 Library Cache 래치를 두 배 정도 더 획득한다는 것입니다.
TYPE       ITEM                                     DELTAS
---------- ---------------------------------------- --------------------
STAT       bytes sent via SQL*Net to client         4040131->1310178
STAT       user calls                               30002->20002
STAT       SQL*Net roundtrips to/from client        20001->10001
STAT       execute count                            10013->10012
STAT       parse count (total)                      10001->10002
STAT       opened cursors cumulative                10001->10001
STAT       session cursor cache hits                10001->10000

TIME       DB time                                  1236939->1005865
TIME       DB CPU                                   1236939->1000893
TIME       sql execute elapsed time                 515669->437225

LATCH      session idle bit                         60023->40016
LATCH      library cache                            20309->40089
LATCH      library cache pin                        20168->40062
테스트 방식에 따라 전혀 의외의 결과가 나온다는 것을 알 수 있습니다. 실제로 쿼리가 수행되는 방식으로 시뮬레이션해보면 두 경우의 성능 차이가 생각보다 그렇게 크지 않다고 할 수 있습니다. 그 이유는 서버에서의 작업보다는 클라이언트와의 통신에서 발생하는 부하가 더 비중이 높기 때문이라고 볼 수 있습니다.

여기서 한가지 의문을 가질 수 있습니다.

{ begin null; end; } 가 오라클에서 가장 가벼운 작업이라는 것은 올바른 답인가? 여러분들의 판단은 어떤 것인가요?

PS) 이 포스트의 목적은 티팩의 Session Snapshot Report의 효용성을 설명하기 위한 것입니다. 무엇이 가장 가벼운 작업인가는 사실 중요한 것이 아니죠. 그것이 가장 가벼운 작업인지를 어떻게 증명하느냐가 핵심입니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
  2. [티팩] oradebug
  3. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 1
  4. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 2 (핫 블록?)
  5. [티팩] 지능적인 대기 이벤트 분석 - Part3. (대기이벤트 프로파일링)
  6. [티팩] Session Snapshot Report - Part 1
저작자 표시
신고
tags : 티팩
Trackback 0 : Comment 0

Write a comment


Long Running Query의 바인드 값 알아내기

오라클 2010.07.27 13:53
이런 질문을 받았습니다.
  • 현재 장시간 수행되는 쿼리가 있습니다. 이 쿼리가 사용한 바인드 값을 알아낼 수 있나요?
종종 이런 요구사항이 생기게 됩니다. 아주 단순해 보이는 이 요구사항을 만족시키기 어려운 이유는 이것입니다.
  • 바인드 값은 프로세스의 값이다. 즉 PGA에 존재하는 값이다. 개별 프로세스의 메모리 영역에 존재하는 값이므로 이것을 직접 조회하는 것은 불가능하다.
즉, 오라클의 아키텍처로 인해 V$ 뷰를 조회하는 것과 같은 일반적인 방법으로는 불가능합니다. V$SQL_BIND_CAPTURE 뷰는 특정 SQL이 사용했던 바인드 정보를 보여주지만 1) 15분마다 캡처하며, 2) WHERE 절에 사용된 바인드 변수만 캡처하며, 3) 바인드 변수가 많을 경우 일부만 캡처하는 등의 문제가 있습니다. 무엇보다 현재의 값을 캡처하지 않는다는 제약이 걸림돌입니다.

레벨 4로 10046 이벤트를 수행하는 방법도 있지만, 현재 수행 중인 쿼리인 경우에는 바인드 값의 지정 단계가 이미 지났을 것이기 때문에 바인드 값이 기록되지 않는다는 문제가 있습니다.

이때 사용 가능한 방법이 Error Stack Dump입니다. 간단한 예를 볼까요?

1. Session #1에서 다음과 같이 장시간(30초) 수행되는 쿼리를 실행합니다. 바인드 변수 b1을 선언하고 값으로 'X'를 지정합니다.

-- session #1
create or replace function fsleep(p1 number) return number
is
begin
	dbms_lock.sleep(p1);
	return 1;
end;
/

exec dbms_application_info.set_client_info('SESSION1');

var b1 varchar2(1);
exec :b1 := 'X';

select fsleep(30) from dual where dummy =  :b1;
...
2. Session #1에서 Long Running Query를 수행하는 동안 Session #2에서 oradebug를 이용해 Error Stack Dump(Level 3)를 남깁니다.
conn sys/oracle@ukja1106 as sysdba

col pid new_value pid
select spid as pid from v$process 
where addr = (select paddr from v$session where client_info = 'SESSION1');

oradebug setospid &pid

oradebug dump errorstack 3
oradebug tracefile_name
3. 트레이스 파일을 열어보면 이런 부분이 있습니다. Cursor 번호 10번이 현재 실행중인 Cursor라는 의미입니다.
----- Session Cursor Dump -----
Current cursor: 10, pgadep=0
...
이 값을 이용해 트레이스 파일 내에서 Cursor#10을 찾으면 됩니다.
----------------------------------------
Cursor#10(0x0C731064) state=FETCH curiob=0x0D7809E4
 curflg=46 fl2=0 par=0x00000000 ses=0x345175D4
----- Dump Cursor sql_id=aanj0fskcmr4t xsc=0x0D7809E4 cur=0x0C731064 -----
Dump Parent Cursor sql_id=aanj0fskcmr4t phd=0x26D23F78 plk=0x3487F4A8
 sqltxt(0x26D23F78)=select fsleep(30) from dual where dummy =  :b1
  hash=227eaca42a9d50c9a552207624c9dc99
  parent=0x21F95C00 maxchild=02 plk=0x3487F4A8 ppn=n
cursor instantiation=0x0D7809E4 used=1279600018 exec_id=16777219 exec=1
 child#1(0x2C49E808) pcs=0x21F9594C
  clk=0x3487A930 ci=0x21F94710 pn=0x349254BC ctx=0x24DB5C80
 kgsccflg=0 llk[0x0D7809E8,0x0D7809E8] idx=0
 xscflg=c0110476 fl2=5200009 fl3=42222008 fl4=100
----- Bind Byte Code (IN) -----
  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy 
  oacdef = 21F944CC   Offsi = 36, Offsi = 0
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=846 siz=32 off=0
  kxsbbbfp=0ceb0e3c  bln=32  avl=01  flg=05
  value="X"
4. 티팩을 사용하면 위의 과정을 어느 정도 자동화할 수 있습니다. 티팩에서 제공하는 SQL Detail Report에서 CURSOR_DUMP 옵션을 사용하면 위의 과정을 자동화해서 그 결과를 보여줍니다.

Session #2에서 다음과 같이 티팩의 SQL Detail Report를 생성합니다.

col sid new_value sid
select sid from v$session where client_info = 'SESSION1';

col name format a15
col value format a60
set pages 10000
set long 100000
select * from table(tpack.sql_detail(session_id=>&sid, options=>'cursor_dump'));
아래와 같이 현재 Cursor를 찾아서 출력해줍니다.
NAME            VALUE
--------------- ------------------------------------------------------------
SQL ID          aanj0fskcmr4t
Child Number    1
SQL Text        select fsleep(30) from dual where dummy =  :b1
Hash Value      617208985
Address         26D23F78
Plan Hash Value 272002086
Bind Sensitive  Y
Bind Aware      N
Cursor Dump     Cursor#7(0x0C730F44) state=FETCH curiob=0x0D7809E4
                 curflg=46 fl2=0 par=0x00000000 ses=0x345175D4
                ----- Dump Cursor sql_id=aanj0fskcmr4t xsc=0x0D7809E4 cur=0x
                0C730F44 -----
                Dump Parent Cursor sql_id=aanj0fskcmr4t phd=0x26D23F78 plk=0
                x3487F4A8
                 sqltxt(0x26D23F78)=select fsleep(30) from dual where dummy
                =  :b1
                  hash=227eaca42a9d50c9a552207624c9dc99
                  parent=0x21F95C00 maxchild=02 plk=0x3487F4A8 ppn=n
                cursor instantiation=0x0D7809E4 used=1279600616 exec_id=1677
                7221 exec=2
                 child#1(0x2C49E808) pcs=0x21F9594C
                  clk=0x3487A930 ci=0x21F94710 pn=0x349254BC ctx=0x24DB5C80
                 kgsccflg=1 llk[0x0D7809E8,0x0D7809E8] idx=9a
                 xscflg=c0110476 fl2=5200009 fl3=42222008 fl4=100
                ----- Bind Byte Code (IN) -----
                  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy

                  oacdef = 21F944CC   Offsi = 36, Offsi = 0
                ----- Bind Info (kkscoacd) -----
                 Bind#0
                  oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
                  oacflg=03 fl2=1000000 frm=01 csi=846 siz=32 off=0
                  kxsbbbfp=0d776cc4  bln=32  avl=01  flg=05
                  value="X"
                 Frames pfr 0x0DA46A30 siz=2904 efr 0x0DA46858 siz=2528
꼭 필요한 경우에 활용할 수 있으면 아주 효과적인 방법이 될 수 있겠습니다.

요즘은 Jennfier같은 Java 모니터링 툴이 보편화되면서 바인드 변수의 값을 보는 것이 가능해졌습니다. 하지만 이런 툴들도 JDBC를 통해 호출된 경우에만 모니터링 가능하기 때문에 여전히 제약이 있다고 하겠습니다.

저작자 표시
신고
tags : errorstack, 티팩
Trackback 0 : Comment 0

Write a comment


[티팩] Session Snapshot Report - Part 1

오라클 2010.07.21 15:14
일전에 이런 질문을 다룬 적이 있습니다.
  • 특정 세션의 성능 문제를 분석하는데 있어 가장 기본적인 뷰는 무엇일까요?
제가 이 질문을 받는다면 주저없이 V$SESSTAT이라고 대답할 것입니다.

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

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

  1. 누적치를 가지고 있기 때문에 반드시 델타(Delta) 값을 계산해야 합니다.
  2. 여러 작업간의 차이를 비교할 수 있어야 합니다. 가령 작업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라고 할 정도로 저에게는 중요한 데이터입니다. 또는 제가 전문가라고 불리는 비결 중 하나?라고 할 수도 있겠네요. 전문가라는 것이 사실은 별 것 없고 남이 잘 보지 못하는 데이터를 추출해서 합리적으로 해석해서 문제를 해결하는 능력을 가진 자라고 본다면 말입니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
  2. [티팩] oradebug
  3. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 1
  4. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 2 (핫 블록?)
  5. [티팩] 지능적인 대기 이벤트 분석 - Part3. (대기이벤트 프로파일링)
저작자 표시
신고
tags : 티팩
Trackback 0 : Comment 0

Write a comment


[티팩] 지능적인 대기 이벤트 분석 - Part3. (대기이벤트 프로파일링)

오라클 2010.07.13 15:06
특정 세션이 어떤 이벤트를 주로 대기하는지 직관적으로 관찰하는 가장 좋은 방법은 무엇입니까?

아마 위의 문제에 대한 가장 정확한 대답은 Oracle 10g부터 제공되는 ASH(Active Session History)일 것입니다. ASH의 가치는 이루 말할 수가 없습니다. 좀 과장하면 오라클 행(Hang) 현상을 트러블슈팅하는 오라클의 핵심 지원 엔지니어들의 10년 소원이었을 것으로 봅니다.

이것이 단순히 과장이 아닌 것이, DMA(Direct Memory Access)에 의해 Active Session History를 수집하고 보여주는 솔루션이 고가로 시장에 팔리는 것을 보면 알 수 있습니다.

Oracle 10g부터는 DMA에 의한 ASH 데이터를 기본적으로 제공하니 당연히 이것을 적극 활용해야 합니다. 사용법은 아래와 같이 매우 간단합니다.

1. Session #1에서 ALL_OBJECTS를 읽습니다. 당연히 I/O 관련 대기 이벤트들(db file sequential read나 db file scattered read와 같은)이 나타날 것입니다.

-- session #1
exec dbms_application_info.set_client_info('SESSION1');

alter system flush buffer_cache;

select count(*) from all_objects;

2. ASH를 이용하면 Session #1이 어떤 이벤트들을 대기했는지를 초(Second)단위로 알 수 있습니다.

col sid new_value sid
select sid from v$session where client_info = 'SESSION1';

-- active session history
col event format a30
select * from (
	select to_char(sample_time,'hh24:mi:ss'), session_id, session_state, sql_id, event 
	from v$active_session_history
	where session_id = &sid
	order by sample_time desc
) where rownum <= 10;

TO_CHAR( SESSION_ID SESSION SQL_ID        EVENT
-------- ---------- ------- ------------- ------------------------------
11:29:31        143 WAITING 4c1xvq9ufwcjc db file sequential read
11:29:30        143 ON CPU  9tz4qu4rj9rdp
11:29:29        143 ON CPU  9tz4qu4rj9rdp
11:29:28        143 ON CPU  9tz4qu4rj9rdp
11:29:27        143 ON CPU  9tz4qu4rj9rdp
11:29:26        143 ON CPU  9tz4qu4rj9rdp
11:29:25        143 ON CPU  9tz4qu4rj9rdp
11:29:24        143 ON CPU  9tz4qu4rj9rdp
11:29:23        143 ON CPU  9tz4qu4rj9rdp
11:29:22        143 WAITING 9tz4qu4rj9rdp db file sequential read
우리가 일반적으로 활용하는 최소 시간 단위가 초단위이기 때문에 이 정도면 충분합니다. 오라클 행(Hang) 상황이라서 접속 자체가 안되는 경우에는 아래 방법을 사용하면 됩니다.

3. 만일 초단위보다 더 정밀하게 대기이벤트를 추적하고 싶다면 프로파일링 기법을 사용할 수 있습니다. 아래와 같이 100,000번 루프를 돌면서 V$SESSION_WAIT 뷰를 탐색한 뒤 { event, p1 }에 대해 그룹핑을 수행하면 특정 이벤트의 Parameter1 값의 발생 빈도를 알 수 있습니다.

select /*+ ordered use_nl(w) */ 
	sid, 
	event, 
	p1,
	count(*) as wait_hits
from 
	(select /*+ no_merge */ level as lvl from dual connect by level <= 100000) t1,
	(select /*+ no_merge */ 
		sid, 
		decode(state, 'WAITING', event, 'ON CPU') as event, 
		decode(state, 'WAITING', seq#, 0) as seq#, 
		decode(state, 'WAITING', p1, null) as p1, 
		decode(state, 'WAITING', p2, null) as p2, 
		decode(state, 'WAITING', p3, null) as p3 
		from v$session_wait 
		where
			sid = &sid		
	) w 
where 
 sid = &sid
 and (event like '%%' or event = 'ON CPU')
group by sid, event, p1
order by count(*) desc 
;

       SID EVENT                           P1  WAIT_HITS
---------- ------------------------------ --- ----------
       141 db file sequential read          1      51160
       141 ON CPU                                  45571
       141 db file scattered read           1       3269

4. 티팩에서는 위에서 사용한 쿼리를 좀 더 세련되게 구사해서 대기 이벤트 정보를 수집합니다. 아래와 같이 수행하면 특정 세션의 모든 대기 이벤트(null)에 대해 Parameter1 기준(p1)으로 10초간(10) 대기이벤트 정보를 V$SESSION_WAIT로부터 수집해서 요약해줍니다.

-- wait profiling
col event_name format a25
col p1 format 99
col p2 format 99
col p3 format 99
col wait_pct format 99.9
col avg_wait_time heading AVG_WAIT

select * from table(tpack.wait_profile_report(&sid, null, 'p1', 10));

 SID EVENT_NAME                 P1  P2  P3 WAIT_PCT  WAIT_TIME AVG_WAIT
---- ------------------------- --- --- --- -------- ---------- --------
 143 ON CPU                                    63.3     6334.3   6334.3
 143 db file sequential read     1             23.4     2347.6     14.3
 143 db file scattered read      1             13.1       1318     15.5
마치 10046 이벤트(또는 SQL*Trace)를 수행한 후 TKPROF를 통해 대기 이벤트 정보를 추출한 것과 거의 비슷한 효과가 있습니다. 10046을 수행하지 않고도 간편하게 특정 세션의 대기 현황을 알 수 있습니다. 10046과 비교해서 가장 큰 장점은 이벤트의 Parameter별로 집계할 수 있다는 것입니다.

가령 buffer busy waits 이벤트의 경우 P3 값이 Block Class 정보를 나타냅니다. 이 값을 정확하게 아는 것이 중요합니다. 하지만 이 정보가 TKPROF 리포트에는 나타나지 않습니다(물론 10046 트레이스 원본에는 있습니다). 하지만 위에서 사용한 프로파일링 기법을 이용하면 어떤 P3 값이 가장 많이 나타나는지를 바로 알 수 있습니다.

5. 10046 Trace의 원본 파일(레벨 8 이상)은 가장 상세한 대기 이벤트 정보를 제공합니다.

exec dbms_monitor.session_trace_enable(waits=>true);

select count(*) from all_objects;

exec dbms_monitor.session_trace_disable;
트레이스 파일에는 다음과 같은 대기 이벤트가 기록됩니다.
WAIT #3: nam='db file sequential read' ela= 16023 file#=1 block#=7754 blocks=1 obj#=380 tim=709352877372
WAIT #3: nam='db file sequential read' ela= 369 file#=1 block#=7753 blocks=1 obj#=380 tim=709352877875
Regular Expression(10g부터 제공)을 이용하면 위의 텍스트로부터 Event, P1, P2, P3, Wait Time 정보를 추출할 수 있습니다.
select
regexp_replace(
'WAIT #3: nam=''db file sequential read'' ela= 16023 file#=1 block#=7754 blocks=1 obj#=380 tim=709352877372',
'[[:print:]]+nam=''([[:print:]]+)''[[:space:]]+ela=[[:space:]]*([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]][[:print:]]+=([[:digit:]]+)[[:space:]]obj#=[[:print:]]+',
'\1.\2.\3.\4.\5')
from dual;

REGEXP_REPLACE('WAIT#3:NAM=''DBFILESEQ
--------------------------------------
db file sequential read.16023.1.7754.1
티팩에서도 위와 비슷한 방법으로 트레이스 파일로부터 직접 읽어서 대기 이벤트 정보를 집계할 수 있습니다.
select * from table(tpack.wait_file_report(tpack.get_tracefile_name(&sid)));

   SID EVENT_NAME                 P1  P2  P3 WAIT_PCT  WAIT_TIME AVG_WAIT
------ ------------------------- --- --- --- -------- ---------- --------
     0 db file sequential read                   76.7   2473.378      2.7
     0 db file scattered read                    23.1    744.395      3.3
     0 SQL*Net message from clie                   .1      3.808      1.3
       nt
     0 SQL*Net message to client                   .0       .018       .0
상세한 대기 정보를 얻는데 생각보다 다양한 방법이 있다는 것을 알 수 있습니다. 어떤 상황에서도 대기 이벤트 정보를 추출할 수 있도록 자신만의 기법 또는 툴 사용 체계를 수립할 필요가 있습니다. 대기 이벤트 정보는 그만큼 중요하기 때문입니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
  2. [티팩] oradebug
  3. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 1
  4. [티팩] [티팩] 지능적 대기 이벤트 분석 - Part 2 (핫 블록?)
저작자 표시
신고
tags : 티팩
Trackback 0 : Comment 0

Write a comment


V$SQL 관련 뷰 조회하기

오라클 2010.07.01 14:31
V$SQL, V$SQLAREA와 같은 뷰들을 조회할 때 주의할 점을 아직도 잘 모르시는 경우가 많은 것 같습니다. 이 뷰들들을 조회한다는 것은 Library Cache 영역을 탐색한다는 것과 같은 의미입니다. 따라서 잘못 조회하면 심각한 문제를 일으킬 수도 있습니다.

간단한 예로 설명하겠습니다.

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

TPACK@ukja1021> select * from v$version where rownum = 1;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
2. 간단한 SQL 문장을 수행하고 SQL ID를 얻습니다.
TPACK@ukja1021> col prev_sql_id new_value sql_id
TPACK@ukja1021> 
TPACK@ukja1021> select /* temp */ * from dual;

D
-
X

Elapsed: 00:00:00.00
TPACK@ukja1021> 
TPACK@ukja1021> select prev_sql_id from v$session where sid = userenv('sid');

PREV_SQL_ID
-------------
5xa7hydhm2dnc
3. SQL_TEXT 컬럼을 통해 검색할 경우의 실행 계획입니다. FIXED TABLE FULL로부터 Library Cache 영역을 Full Scan한다는 것을 알 수 있습니다. 즉, 단 하나의 SQL을 찾기 위해 모든 Library Cache 영역을 다 읽어봐야 합니다.
TPACK@ukja1021> explain plan for
  2  select * from v$sqlarea
  3  where sql_text like 'select /* temp */ %';

Explained.

-------------------------------------------------------------
| Id  | Operation        | Name                    | Rows  |
------------------------------------------------------------
|   0 | SELECT STATEMENT |                         |     1 |
|*  1 |  FIXED TABLE FULL| X$KGLCURSOR_CHILD_SQLID |     1 |
------------------------------------------------------------
4. SQL_ID 컬럼을 통해 검색한 경우의 실행 계획입니다. FIXED TABLE FIXED INDEX로부터 Library Cache 영역을 Index를 경유해서 탐색한다는 것을 알 수 있습니다. 따라서 Library Cache 영역을 불필요하게 읽을 필요가 없습니다. 즉, 가능한 한 Index를 경유하도록 작성해야 합니다.

TPACK@ukja1021> explain plan for
  2  select * from v$sqlarea
  3  where sql_id = '&sql_id';
old   3: where sql_id = '&sql_id'
new   3: where sql_id = '5xa7hydhm2dnc'

--------------------------------------------------------------------------
| Id  | Operation               | Name                           | Rows  |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |                                |     1 |
|*  1 |  FIXED TABLE FIXED INDEX| X$KGLCURSOR_CHILD_SQLID (ind:2 |     1 |
--------------------------------------------------------------------------
V$SQLXXX 뷰에 대한 인덱스는 HASH_VALUE, SQL_ID 두 개의 컬럼에 대해서 각각 만들어져 있습니다.
TPACK@ukja1021> select table_name, index_number, column_name
  2  from v$indexed_fixed_column
  3  where table_name = 'X$KGLOB';

TABLE_NAME           INDEX_NUMBER COLUMN_NAME
-------------------- ------------ --------------------
X$KGLOB                         1 KGLNAHSH     -- HASH_VALUE
X$KGLOB                         2 KGLOBT03     -- SQL_ID
5. 티팩의 Session Snapshot Report를 이용해 Library Cache 영역을 Full Scan하는 경우와 Index Scan하는 경우 어느 정도의 성능 차이가 발생하는지 분석해보겠습니다.
-- Session Snapshot 시작
exec tpack.begin_session_snapshot(-1);

-- Full Scan on X$ view
begin
	for idx in 1 .. 1000 loop
		for r in (select * from v$sqlarea where sql_text like 'select /* temp */ %') loop
			null;
		end loop;
	end loop;
end;
/

-- Session Snapshot 추가
exec tpack.add_session_snapshot(-1);

-- Index Scan on X$ View
begin
	for idx in 1 .. 1000 loop
		for r in (select * from v$sqlarea where sql_id = '&sql_id') loop
			null;
		end loop;
	end loop;
end;
/

-- Session Snapshot 추가
exec tpack.add_session_snapshot(-1);

-- Session Snapshot Report 보기
set pages 10000
set lines 200
col item format a30
col deltas format a50

select * from table(tpack.session_snapshot_report(-1));
그 결과는 아래와 같습니다(너무 길어서 편집). 수행 시간은 168초:0.4초로 비교할 수가 없습니다. 결정적인 차이는 library cache 래치 획득 회수에서 알 수 있습니다. Library Cache 영역을 1000번 Full Scan한 경우 무려 8백만번의 획득이 필요합니다.
TYPE       ITEM                            START_VAL    END_VAL TOTAL_DELTA DELTAS
---------- ------------------------------ ---------- ---------- ----------- ------------------------
...
TIME       DB time                        1.5215E+10 1.5384E+10   168639689 168231521->408168
...

LATCH      library cache                    40199550   48532801     8333251 8330082->3169
...
V$ 뷰를 조회하는 것은 메모리 영역을 읽는다는 것이기 때문에 기본적으로 효율적이고 빠릅니다. 하지만 Library Cache나 Shared Pool과 같은 영역을 읽을 때는 대단히 주의해야 합니다. 큰 크기의 메모리 영역을 읽는 것은 기본적으로 CPU를 많이 사용하며 래치나 뮤텍스와 같은 동기화 객체에서 심각한 경합이 발생할 수 있습니다.

아무리 간단해 보이는 쿼리라도 언제나 성능의 최적화를 고려해야겠죠!

저작자 표시
신고
Trackback 0 : Comment 1
  1. 스누피 2010.07.10 11:43 신고 Modify/Delete Reply

    좋은 정보 감사합니다. 생각없이 날리던 쿼리들 조심해야겠네요

Write a comment


[티팩] 지능적 대기 이벤트 분석 - Part 1

오라클 2010.06.29 16:10
오라클이 제공하는 대기이벤트(Wait Event)는 정말 독특합니다. 다른 어떤 제품(DBMS에 국한하지 않고)들을 봐도 대기 현상을 이렇게까지 자세하게 보고해주는 경우는 없습니다.

이것은 오라클 성능 문제를 분석하고 해결해야 하는 우리들에게 있어서는 큰 선물이자 고민거리입니다. 마치 초보 운전자에게 포르쉐를 주는 격이라고 할까요? 당장 운전 욕심이 나겠지만 포르쉐같은 차를 제대로 몰려면 탄탄한 운전 기본기가 있어야 합니다. (아... 포르쉐한번 몰아보고 싶다)

대기 이벤트 분석도 마찬가지입니다. 정확하게 해석하려면 오라클 아키텍처 전반에 대한 일정 수준의 지식이 필요합니다. 이런 것들이 대기 이벤트 분석 기법이 더 실용적이고 광범위하게 사용되는 것을 막는 장벽이 되고 있습니다. 결국 개인이 극복해야할 문제겠지만요.

대기이벤트 분석에서 한가지 명심해야할 것은 대기이벤트만으로는 의미있는 정보를 이끌어내기가 어렵다는 것입니다. 관련된 다른 정보들이 필요한 경우가 많습니다. 티팩에서는 이것을 지능적 대기이벤트 분석이라고 부릅니다. 예를 들어보면 이런 부가적인 정보들이 필요합니다.

  1. cache buffers chains 래치에서 경합이 발생할 경우 주로 어떤 블록(DBA)인지 알 수 있는가?
  2. row cache objects 래치에서 경합이 발생할 경우 주로 어떤 Dictionary Object인지 알 수 있는가?
  3. db file sequential read와 같은 I/O 대기일 경우 어떤 세그먼트의 어떤 종류의 블록에서 발생하는지 알 수 있는가?
  4. 래치, 락(Enqueue), library cache lock, library cache pin, row cache lock, 뮤텍스 등의 동기화 객체에서 경합이 발생할 경우 홀더 정보와 관련 객체 정보를 얻을 수 있는가?
앞으로 몇 차례에 걸쳐서 대기이벤트를 좀 더 지능적으로 분석하기 위해 추가적으로 어떤 데이터를 수집할 필요가 있는지 몇가지 예를 볼려고 합니다. 이 주제만으로도 책 한권을 쓸 수 있을 정도로 방대한 분야라서 몇 가지 핵심적인 내용만을 블로그를 통해서 소개하게 될 것입니다.

1. 홀더를 찾아라!

오라클에서의 경합은 다음 여섯 가지 정도의 동기화 객체에 의해 발생합니다.

  • 래치
  • 락(Enqueue)
  • Library cache lock
  • Library cache pin
  • Row cache lock
  • 뮤텍스
각 동기화 객체가 무엇을 의미하는지는 이미 알고 계신 분들도 많이 때문에 상세하게 설명하지는 않을 것입니다. 제 책이나 블로그나 기타 온라인 자료 등에서 이미 방대한 설명을 제공하고 있습니다.

동기화 객체의 종류별로 제공되는 뷰가 다르기 때문에 홀더 정보를 찾는데도 다른 뷰를 읽어야 합니다. 다행히 최근 버전의 오라클에서는 V$SESSION 뷰의 BLOCKING_SESSION, BLOCKING_INSTANCE등의 컬럼을 통해 대부분의 상황에 대해 홀더 정보를 제공합니다. 대단히 유용한 정보입니다. 하지만 어떤 경우에는 단순히 홀더를 아는 것만으로는 부족한 경우가 많습니다. 정확하게 어떤 오브젝트에서 발생하는지, 어떤 모드로 인해 발생하는지등의 정보가 필요한 경우가 있습니다.

밑에서 보게 될 정보는 아마도(!) 홀더를 찾기 위한 방법을 지금까지의 그 어떤 문서보다 가장 광범위하고 완벽하게 정리한 것일겁니다.(라고 자랑하고 싶지만 그냥 스크립트 정리한 것일뿐입니다)

1.1 래치 홀더 찾기

래치 홀더는 V$LATCHHOLDER를 통해서 얻을 수 있습니다.

-- 래치 홀더 찾기
select h.pid, h.sid, h.laddr, h.name, h.gets
from v$latchholder h, v$session_wait s
where s.sid = &sid
	  and s.p1raw = h.laddr;
래치는 워낙 짧은 시간에 잡고 놓기 때문에 위의 단순한 쿼리만으로는 원하는 결과를 얻지 못하는 경우가 많습니다. (몰론 오라클 버그 등에 의해 특정 래치를 오랫동안 잡는 경우가 있습니다. 이런 경우에는 이런 단순한 쿼리만으로도 추가적인 분석이 가능합니다)

이럴 때 사용할 수 있는 것이 프로파일 방법입니다. 티팩은 1) 스냅샷, 2) 프로파일 두 개의 방법을 사용한다고 말씀드린 바 있습니다. 이 중 프로파일은 짧은 시간 저장되고 사라지는 값을 가능한 여러 번 캡쳐해서 요약해서 보는 것을 말합니다. V$LATCHHOLDER 뷰도 다음과 같이 프로파일링할 수 있습니다.

-- 래치 홀더 프로파일링하기
TPACK@ukja1021> select /*+ ordered use_nl(x) */
  2     x.sid, x.name, count(*)
  3  from
  4     (select /*+ no_merge */ level from dual connect by level <= 10000) t1,
  5     (select  /*+ no_merge */ h.pid, h.sid, h.laddr, h.name, h.gets
  6             from v$latchholder h, v$session_wait s
  7             where s.sid = &sid
  8                             and s.p1raw = h.laddr) x
  9  group by x.sid, x.name
 10  ;
old   7:                where s.sid = &sid
new   7:                where s.sid =        138

       SID NAME                             COUNT(*)
---------- ------------------------------ ----------
       134 shared pool                            33
       134 library cache                         308
1.3 Enqueue 홀더 찾기

Enqueue 홀더는 V$LOCK 뷰를 보는 것만으로 충분합니다. Enqueue 경합을 관찰하는 방법은 이미 많이 알려져 있죠.

-- Enqueue 홀더 찾기
select
	h.sid,  -- 홀더 SID
	h.type,   -- 락 타입
	h.id1,  -- ID1
	h.id2,  -- ID2
	h.lmode, 
	t.name,
	t.id1_tag,
	t.id2_tag,
	t.description
from v$lock h, v$lock w, v$lock_type t
where w.sid = { waiter_sid }
	and h.id1 = w.id1
	and h.id2 = w.id2
	and h.lmode > 0 
	and h.block > 0
	and h.type = t.type
;
1.3 Library cache lock 홀더 찾기

Library cache lock은 LCO(Library Cache Object)를 보호하는 락입니다. 경합이 발생하면 library cache lock 대기이벤트가 발생하죠. Library cache lock 홀더는 X$KGLLK 뷰를 통해서 찾을 수 있습니다.

-- Library cache lock 홀더 찾기
select
	(select sid from v$session where saddr = k.kgllkuse) as sid,  -- 홀더 SID
	k.kglhdnsp,  -- 객체의 종류
	k.kglnaobj,  -- 객체명(SQL문장이나 테이블, 프로시저명 등)
	decode(k.kgllkmod, 3, '3(X)', 2, '2(S)', 1, '1(N)', k.kgllkmod) as lkmode
from x$kgllk k
where k.kgllkhdl = { v$session_wait.p1raw }
	  and k.kgllkmod > 0
;
1.4 Library cache pin 홀더 찾기

Library cache pin은 Cursor나 Procedure의 실행을 보호하는 락입니다. 경합이 발생하면 library cache pin 대기이벤트가 발생하죠. Library cache pin 홀더는 X$KGLPN 뷰를 통해서 찾을 수 있습니다.

-- Library cache pin 홀더 찾기
select
  (select sid from v$session where saddr = n.kglpnuse) as sid, 
  o.kglnaobj,
  o.kglhdnsp,
  decode(n.kglpnmod, 3, '3(X)', 2, '2(S)', 1, '1(N)', n.kglpnmod) as lkmode
from x$kglpn n, x$kglob o
where n.kglpnhdl = { v$session_wait.p1raw }
	  and n.kglpnmod > 0
	  and o.kglhdadr = n.kglpnhdl
;
1.5 Row cache lock 홀더 찾기

Row cache lock은 Dictionary Object에 대한 변경을 보호하는 락입니다. 경합이 발생하면 row cache lock 대기이벤트가 발생하죠. Row cache lock 홀더는 V$ROWCACHE_PARENT 뷰를 통해서 찾을 수 있습니다.

-- Row cache lock 홀더 찾기
select 
	(select sid from v$session where saddr = h.saddr) as sid,  -- 홀더 SID
	h.cache_name,  -- Dictionary Object의 종류
	h.lock_mode,    
	h.inst_lock_type 
from v$rowcache_parent h, v$rowcache_parent w, v$session s
where h.address = w.address
	  and w.saddr = s.saddr 
	  and s.sid = { waiter_sid }
	  and h.lock_mode > 0
;	  
1.6 뮤텍스 홀더 찾기

뮤텍스 홀더는 V$MUTEX_SLEEP_HISTORY 뷰를 통해서 찾을 수 있습니다.

-- 뮤텍스 홀더 찾기
select * from (
	select
		 blocking_session as sid,  -- 홀더 SID
		(select kglnaobj from x$kglob 
		where kglnahsh = mutex_identifier 
		and rownum = 1) as obj_name,   -- Object 명 (11g에서 추가!)
		 mutex_type,  -- 뮤텍스 종류
		 location,  -- 뮤텍스를 획득한 위치 정보, 즉 무슨 일을 하느라고 뮤틱스를 획득하려고 하는지?
		 sleeps,
		 gets,
		 to_char(sleep_timestamp,'yyyy/mm/dd hh24:mi:ss') as sleep_timestamp
	from v$mutex_sleep_history
	where requesting_session = session_id
	order by sleep_timestamp desc
) where rownum <= 1	;
11g에서는 MUTEX_IDENTIFIER라는 유용한 컬럼이 추가되어 뮤텍스 경합을 분석하기가 더 쉬워졌습니다.

위의 정보들에서 알 수 있듯이 홀더를 찾는 것도 중요하지만, 구체적으로 어떤 상태(또는 객체)에서 문제가 발생하는지를 파악하는 것또한 중요합니다. 이런 이유때문에 문서화가 잘 되어 있지 않은 V$ 뷰나 X$ 뷰를 볼 수 밖에 없습니다.

티팩에서는 Session Detail Report를 통해 위의 정보들을 보여줍니다. 위에서 소개한 것과 거의 비슷한 방법을 사용합니다.

Library cache pin 경합을 간단한 예로 소개해보겠습니다.

-- 아주 긴 SQL 문장을 만듭니다. 정확하게 말하면 하드 파스 시간이 긴 SQL 문장입니다.
-- http://sites.google.com/site/ukja/sql-scripts-1/j-m/make_long
TPACK@ukja1021> @make_long
select count(*) from TPACK_REPORT_PARAMS, TPACK_REPORT_CONDITIONS,
TPACK_REPORT_JOB_HIST, TPACK_REPORT_SESSION_TEMP, TPACK_FUNCTION_NAMES,
...

-- Session #1에서 위에서 만든 쿼리를 수행합니다.(제 로컬 노트북에서 2분 50초 정도 소요)
TPACK@ukja1021> exec dbms_application_info.set_client_info('session1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.39
TPACK@ukja1021> @long_parse
....

-- 동시에 Session #2에서 동일한 쿼리를 수행합니다. 
TPACK@ukja1021> exec dbms_application_info.set_client_info('session2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.04
TPACK@ukja1021> @long_parse
...
이렇게 하면 Session #2는 Session #1이 하드 파스를 끝내는 동안 대기 상태에 빠집니다. 다음과 같이 Session #2에 대해 Session Detail Report를 수집해서 대기 정보를 상세하게 분석합니다.
-- Session #2의 SID 구하기
TPACK@ukja1021> col sid new_value sid
TPACK@ukja1021> select sid from v$session where client_info = 'session2';

       SID
----------
       138

1 row selected.

Elapsed: 00:00:00.14

-- Session #2의 Session Detail Reort
TPACK@ukja1021> col name format a30
TPACK@ukja1021> col value format a45
TPACK@ukja1021> set pages 200
TPACK@ukja1021> set long 10000000
TPACK@ukja1021> select * from table(tpack.session_detail(&sid, 'wait_detail'));
old   1: select * from table(tpack.session_detail(&sid, 'wait_detail'))
new   1: select * from table(tpack.session_detail(       138, 'wait_detail'))

NAME                           VALUE
------------------------------ ---------------------------------------------
SID                            138
Serial#                        711
SPID                           3724
Program                        sqlplus.exe
Process                        5364:5208
Module                         SQL*Plus
SQL ID
Child No
SQL Text
Status                         ACTIVE
Blocking Instance              1
Blocking Session               134
Event                          library cache pin
Seq#                           4137
P1(P1raw)                      970230240(39D489E0)
P2(P2raw)                      970230240(36A9AB34)
P3(P3raw)                      970230240(000000C8)
Seconds in wait                10
State                          WAITING
Wait Event                     library cache pin
Holder SID                     134
Namespace                      CURSOR
Object                         select count(*) from TPACK_SGA_STAT, TPACK_SG
                               A_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK
                               _SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TP
                               ACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT,
                                TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_ST
                               AT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA
                               _STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_
                               SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_S

                               GA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPAC
                               K_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, T
                               PACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_D
                               UMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_
                               HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP,
                               TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_
                               DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK
                               _HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPA

                               CK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUM
                               P, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HE
                               AP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TP
                               ACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DU
                               MP, TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM,
                                TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM, TP
                               AC

Holding Mode                   3(X)
Namespace와 Object 정보로부터 library cache pin 대기에 대한 보다 정확한 분석이 가능합니다. Oracle 11g에서는 library cache pin이 아닌 뮤텍스에 대한 경합이 발생합니다.
TPACK@ukja1106> select * from table(tpack.session_detail(&sid, 'wait_detail'));
old   1: select * from table(tpack.session_detail(&sid, 'wait_detail'))
new   1: select * from table(tpack.session_detail(       127, 'wait_detail'))

NAME                           VALUE
------------------------------ ---------------------------------------------
SID                            127
Serial#                        1642
SPID                           2656
Program                        sqlplus.exe
Process                        5364:5208
Module                         SQL*Plus
SQL ID
Child No
SQL Text
Status                         ACTIVE
Blocking Instance              1
Blocking Session               139
SQL Exec Start
Event                          cursor: pin S wait on X
Seq#                           631
P1(P1raw)                      3859422310(00000000E60A1C66)
P2(P2raw)                      3859422310(00000000008B0000)
P3(P3raw)                      3859422310(0000000000050256)
Seconds in wait                0
State                          WAITING
Wait Event                     cursor: pin S wait on X
Holder SID                     139
Mutex Type                     Cursor Pin
Location
Target Object                  select count(*) from TPACK_SGA_STAT, TPACK_SG
                               A_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK
                               _SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TP
                               ACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT,
                                TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_ST
                               AT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA
                               _STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_
                               SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPACK_S

                               GA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, TPAC
                               K_SGA_STAT, TPACK_SGA_STAT, TPACK_SGA_STAT, T
                               PACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_D
                               UMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_
                               HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP,
                               TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_
                               DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK
                               _HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPA

                               CK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUM
                               P, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HE
                               AP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DUMP, TP
                               ACK_HEAP_DUMP, TPACK_HEAP_DUMP, TPACK_HEAP_DU
                               MP, TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM,
                                TPACK_HEAP_DUMP_SUM, TPACK_HEAP_DUMP_SUM, TP
                               AC

Last Sleep Time                2010/06/29 16:03:51
Gets                           1
Sleeps                         611
중요한 것은 대기 현상이 발생할 때 적절한 뷰에서 적절한 데이터를 관찰할 수 있는가입니다. 티팩은 그 중 핵심적인 데이터들을 자동으로 수집해줄 뿐입니다.

쓰다보니 너무 길어졌네요. 다음 포스트에서는 대기 이벤트 분석에 필요한 다른 기타 추가적인 데이터들을 소개하겠습니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
  2. [티팩] oradebug
저작자 표시
신고
tags : 티팩
Trackback 0 : Comment 0

Write a comment


[퀴즈] Partitioned Table과 Insert 성능 - 해답편 + 티팩

오라클 2010.06.28 15:58
이전 포스트 [퀴즈] Partitioned Table과 Insert 성능에서 제가 생각한 답변이 나왔습니다. 이렇게 적어주셨습니다.
테이블이 파티셔닝에 되어 있어,
insert 할 때 insert 대상 블럭(버퍼)가 계속 바뀌게 되고,
그로 인해 logical reads가 증가하기 때문인 것 같습니다.

음... 마치 미리 답을 알고 있었다는 듯한 간단 명료한 답변입니다. ^^

이 퀴즈에서 예를 들었던 해시 파티션의 경우 매번 Insert가 이루어질 때마다 매번 다른 블록으로 들어갈 활륙이 높습니다(하지만 항상 그런 것은 아닙니다. 해시 파티션의 경우 해시값에 따라 들어갈 파티션을 결정하게 되는데 같은 해시값이 중복해서 나올 수 있기 때문입니다). 같은 원리로 레인지 파티션이나 리스트 파티션에서도 이런 문제가 발생할 수 있습니다.

가령 100개의 로우가 한번에 하나의 블록안에 들어가게 되면 Batch Processing이 이루어집니다. (또는 Array Insert라고도 합니다) Array Insert 효과에 의해서 Logical Reads도 줄어들고 Redo 데이터도 줄어듭니다.

퀴즈에서와 같이 아래와 같이 테이블을 만듭니다.

create table t1(c1 number);
create table t2(c1 number) partition by hash(c1) partitions 4;
Case 1. 가장 성능이 좋은 경우입니다. 가능한 많은 수의 로우가 한번에 하나의 블록안에 들어가므로 Array Insert의 효과가 극대화됩니다.
-- 가장 성능이 좋음. 
insert into t1 select level from dual connect by level <= 500000;
Case 2. 해시 파티션인 경우 각 로우가 매번 다른 블록으로 들어갈 확률이 높습니다. 따라서 Array Insert의 효과가 크게 감소합니다.
-- 성능이 안좋아짐
insert into t2 select level from dual connect by level <= 500000;
Case 3. 가장 성능이 안좋은 경우는 다음과 같이 건건이 Insert하는 경우입니다. Array Insert가 아예 발생하지 않기 때문입니다.
-- 성능이 가장 안좋음
begin
	for idx in 1 .. 500000 loop
		insert into t1 values(idx);
	end loop;
	commit;
end;
/
Case 4. 해시 파티션에 데이터가 추가되는 원리를 이해한다면, 아래와 같은 방법을 사용하면 Case 1과 같이 가장 성능이 좋게 만들 수 있습니다. ORA_HASH 함수를 이용해서 가능한 같은 파티션으로 정렬된 형태로 Insert하는 트릭입니다. 파티션키에 정렬된 형태로 Insert를 하는 것이 핵심입니다. 레인지 파티션이나 리스트 파티션에서도 동일한 방법을 사용할 수 있습니다.
-- 가장 성능이 좋음
insert into t2 select level from dual connect by level <= 500000 order by ora_hash(level, 3);

하지만 중요한 것은 답을 맞추고 안맞추고 아니라, 데이터를 통해서 객관적으로 검증할 수 있는가입니다. 이전에 이런 퀴즈가 있었죠.

1. 오라클에서 특정 세션(혹은 시스템)의 현재 상태를 바로 알 수 있는 가장 좋은 방법은 무엇일까요?

2. 오라클에서 특정 세션(혹은 시스템)을 하는 일을 추적할 수 있는 가장 좋은 방법은 무엇일까요?

첫번째 질문에 대한 제 대답은 "V$SESSTAT 뷰에 대해 Snapshot을 만들고, 각 Snapshot간의 Delta값을 비교한다"입니다. 즉 세션의 성능 문제를 분석하는데 있어서 가장 중요한 Snapshot 데이터는 V$SESSTAT 뷰이며, 이 데이터를 비교라는 방법을 이용해서 분석하는 것이 가장 기본적인 방법입니다. 이것이 티팩의 핵심적인 아이디어라는 것도 이미 말씀드렸습니다.

거창하게 말씀드렸는데, 더 간결 솔직하게 말하면 V$SESSTAT 뷰가 제공하는 데이터를 분석해보면 어느 정도 의미있는 분석을 할 수 있다. 요런 이야기입니다.

티팩의 Session Snapshot Report를 이용해서 위의 내용을 분석해보겠습니다.

create table t1(c1 number);
create table t2(c1 number) partition by hash(c1) partitions 4;

-- Session Snapshot 시작
exec tpack.begin_session_snapshot;

-- Case 1
insert into t1 select level from dual connect by level <= 500000;

exec tpack.add_session_snapshot;

-- Case 2
insert into t2 select level from dual connect by level <= 500000;

exec tpack.add_session_snapshot;

-- Case 3
begin
	for idx in 1 .. 500000 loop
		insert into t1 values(idx);
	end loop;
	commit;
end;
/
	
exec tpack.add_session_snapshot;

-- Case 4
insert into t2 select level from dual connect by level <= 500000 order by ora_hash(level, 3);

exec tpack.add_session_snapshot;

-- Session Snapshot Report 보기
set pages 10000
set lines 200
col item format a30
col deltas format a50
select * from table(tpack.session_snapshot_report);
결과는 다음과 같습니다.(내용이 길어셔 편집했음을 알려드립니다) DELTAS 값을 잘 분석해보시기 바랍니다.
TYPE       ITEM                            START_VAL    END_VAL TOTAL_DELTA DELTAS
---------- ------------------------------ ---------- ---------- ----------- --------------------------------------------------
STAT       redo size                      1343966008 1567241868   223275860 8486656->87223020->119117508->8448676
STAT       undo change vector size         423505332  485865780    62360448 1695312->26462580->32510584->1691972
STAT       session logical reads            14843144   16914592     2071448 15863->1521337->518902->15346
STAT       db block changes                 10655679   12453768     1798089 12623->762448->1010680->12338
STAT       db block gets                    11368998   13058307     1689309 13946->1144031->517777->13555
STAT       db block gets from cache         11368998   13058307     1689309 13946->1144031->517777->13555
STAT       redo entries                      5338577    6240096      901519 7792->381384->504754->7589
STAT       calls to kcmgrs                   5831580    6730131      898551 6973->380346->504279->6953
STAT       HSC Heap Segment Block Changes    4933463    5814688      881225 2827->375425->500125->2848
...
STAT       Heap Segment Array Inserts        2682231    3063258      381027 2785->375297->113->2832
...
STAT       DB time                             26491      31554        5063 162->1280->3406->215
...
위의 결과에서 HSC Heap Segment Block ChangesHeap Segment Array Inserts 두 개의 지표(불행히도 이 두 개의 유용한 지표는 11g에서 추가된 것입니다)를 잘 해석하시면 Array Insert가 미친 영향을 완벽하게 해석할 수 있습니다. 단, 티팩 자체가 발생시키는 Array Insert가 100여회 정도된다는 것을 고려해서 해석해야 합니다.

티팩이 해주는게 고작 이것이냐고 비난하지 마시기 바랍니다. 티팩이 하고자 하는 것은 성능 트러블슈팅을 위해 필요한 기본적인 데이터를 자동으로 수집하고 적절히 리포트해주는 것일 뿐, 결국 최종 해석은 사람의 몫입니다.

중요한 것은 데이터에 기반한 과학적인 분석을 하느냐 아니면 이거 아니면 저거 다 찔러보는 방식의 분석을 하느냐일 것입니다.

저작자 표시
신고
tags : 티팩
Trackback 0 : Comments 4
  1. onsider 2010.06.29 10:24 신고 Modify/Delete Reply

    Blog 내용을 테스트 하던 중 ... 테스트하는 DB User 와 tpack db user와 다를 경우 Error가 발생하네요 ..(권한 문제 때문에 당연한것 이겠지만..)

    그래서 모든 유저에서 사용할수 있도록 스크립트가 추가되면 괜찮을것 같습니다.. (Install시 선택할수 있도록)

    CREATE PUBLIC SYNONYM TPACK FOR TPACK.TPACK;
    CREATE PUBLIC SYNONYM TPACK_SERVER FOR TPACK.TPACK_SERVER;
    GRANT EXECUTE ON TPACK TO PUBLIC;
    GRANT EXECUTE ON TPACK_SERVER TO PUBLIC;

    • 욱짜 2010.06.29 10:40 신고 Modify/Delete

      좋은 지적입니다.

      원래 이 부분을 인스톨 과정에 넣으려고 했는데, 권한 문제가 걱정되어 제거했습니다.

      인스톨 과정에서 선택이 가능하도록 하는 옵션 고민하겠습니다.

  2. salvationism 2010.07.01 00:26 신고 Modify/Delete Reply

    결과값이 여러가지 스냅중 하나 인가요?
    아니면 여러 스냅의 Total 값인가요? 다른 글 안보고 이글을 바로보니 이해가 잘 안되네요.. ^^;;
    Delta 값을 분석하는 내용이 추가되면 좋을거 같습니다.
    욱짜님의 시각도 한번 보고 싶구요 ^^

    • 욱짜 2010.07.01 09:33 신고 Modify/Delete

      제 시각이라는게 별도로 없구요. 데이터를 유심히 볼 뿐입니다. ^^

      Session Snapshot Report에서 각 항목의 의미는 이렇습니다.

      - TYPE: STAT, WAIT, TIME, LATCH, ...
      - ITEM: TYPE에 따른 항목(가령 STAT일 경우 session logical reads 등)
      - START_VAL: 최초 Snapshot의 값
      - END_VAL: 마지막 Snapshot의 값
      - TOTAL_DELTA: END_VAL - START_VAL
      - DELTAS: 각 Snapshot간의 Delta값의 흐름

      STAT.Heap Segment Array Inserts 항목을 보면 DELTAS가

      2785->375297->113->2832

      입니다.

      즉 첫번째 실행(2번째 Snapshot과 1번째 Snapshot의 Delta)시에는 2785회, 두번째 실행(3번째 Snapshot과 2번째 Snapshot의 Delta)시에는 375,297회... 이런 식입니다.

      첫번째 실행의 경우 500,000건의 로우를 Insert하는데 Array Processing이 총 2,500(티팩 라이브러리에서 자체적으로 발생하는 100여회의 값을 빼면)회 정도 발생했으니 한번의 Array Insert에서 대략 200건의 로우를 Insert한다는 것을 의미합니다.

      두번째 실행의 경우 500,000건의 로우를 Insert하는데 Array Processing이 총 375,000회 정도 발생했다고 보고되는 것은 한번의 Array Insert에서 고작 1,2건 정도씩 밖에 Insert가 이루어지지 않았다는 것을 의미합니다.

      반대로 세번째 실행의 경우는 INSERT ... VALUES 구문이므로 아예 Array Insert가 발생하지 않았다는 것을 의미하구요.

      네번째 실행의 경우에는 첫번째 실행과 거의 동일한 정도의 Array Insert가 이루어졌다는 것을 의미합니다.

Write a comment


[티팩] oradebug

오라클 2010.06.24 15:06
Oradebug의 사용법 전체를 설명하려는 것은 아니고 티팩에서 사용하는 oradebug 명령을 간단하게 소개합니다. 아주 간단한 명령들이라 이미 다들 알고 계신 내용일 것입니다.

1. 특정 Process에 바인드 하기

티팩이 oradebug 명령을 사용하는 이유는 특정 Process에 자유롭게 바인딩할 수 있기 때문입니다.

-- SYSDBA 유저로 로그인
sqlplus "/as sysdba"

-- 현재 Process로 바인딩
SQL> oradebug setmypid

-- 특정 Session의 OS Process ID를 얻어서 바인딩
SQL> select sid, serial#,
  	(select spid from v$process where addr = paddr) as ospid
from v$session 
where sid = (select sid from v$mystat where rownum = 1);

       SID    SERIAL# OSPID
---------- ---------- ------------
       144       2446 4872

SQL> oradebug setospid 4872
Oracle pid: 16, Windows thread id: 4872, image: ORACLE.EXE (SHAD)
특정 Process로 Binding하는 방법에는 아래 네가지가 있습니다.
SQL> oradebug help
SETMYPID                                 Debug current process
SETOSPID       {ospid}                   Set OS pid of process to debug
SETORAPID      {orapid} ['force']        Set Oracle pid of process to debug
SETORAPNAME    {orapname}                Set Oracle process name to debug  -- 11g에서 추가
...
SETOSPID 명령을 주로 사용하는 이유는 Unix/Linux 환경에서는 Process ID(PID) 값을 얻기 쉽기 때문입니다. 하지만 티팩에서는 특정 세션을 지정하기 위해 Session ID(SID)를 인자로 사용합니다. 오라클 입장에서는 SID가 가장 인식하기 쉬운 값이기 때문입니다.

2. 트레이스 파일 이름 얻기

티팩에서는 특정 프로세스에 대해 이벤트나 덤프를 수행하고 그 내용을 읽는 작업이 몇몇 있습니다. 따라서 트레이스 파일을 정확하게 얻을 수 있어야 합니다. oradebug tracefile_name 명령으로 얻을 수 있습니다.

SQL> oradebug tracefile_name
c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc
위의 작업은 티팩에서는 다음과 같이 수행됩니다.
-- 143번 세션의 트레이스 파일 이름 얻기
SQL> select tpack.get_tracefile_name(143) from dual;
c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc

-- 트레이스 파일의 내용도 읽을 수 있습니다.
SQL> select * from table(tpack.get_tracefile_contents('c:\oracle\admin\ukja1021\udump\ukja1021_ora_4872.trc'))
또는 다음과 같은 Query를 통해서도 얻을 수도 있습니다. 하지만 정확한 포맷은 Version이나 OS에 따라 바뀔 수 있습니다. 이 방법은 또 하나의 단점은 해당 프로세스가 Server Process인지, Background Process인지를 알아야 하며 Process 종류에 따라 정확하게 어떤 디렉토리에 파일이 남는지도 판단해야한다는 것입니다. 이런 복잡성때문에 티팩에서는 oradebug tracefile_name 명령을 이용합니다.
select
  d.value||'\'||p.value||'_ora_'||s.spid||'.trc'   as trace_file_name
from 
  (
  select value 
  from v$parameter
  where name = 'instance_name'
  ) p, 
  (
  select value
  from v$parameter
  where name = 'user_dump_dest'
  ) d,
  (
  select spid
  from v$process
  where addr = (
    select paddr 
    from v$session
    where sid = {sid here}
    )
  ) s
3. 진단 이벤트 수행

특정 Process에 바인딩한 후 해당 Process에 대해 진단 이벤트를 수행할 수 있습니다.

-- 진단이벤트 켜기
SQL> oradebug event 10046 trace name context forever, level 12

-- 진단이벤트 끄기
SQL> oradebug event 10046 context off

-- 트레이스 파일 열기
SQL> oradebug tracefile_name
SQL> ed {tracefile_name}
위의 작업을 티팩에서는 다음과 같이 수행할 수 있습니다.
-- 진단 이벤트 켜기
SQL> exec tpack.begin_diag_trace(143, 10046, 12);

-- 진단 이벤트 끄기
SQL> exec tpack.end_diag_trace(143, 10046);

-- 트레이스 파일 열기
SQL> select * from table(tpack.get_diag_trace(143));
티팩을 이용하면 oradebug를 이용하기 위해 텔넷으로 접속할 필요가 없고, 클라이언트에서 SQL*Plus로 모든 작업을 할 수 있습니다. 티팩의 또 하나의 장점은 진단 이벤트을 활성한 이후에 생성된 내용만을 읽는다는 것입니다. 즉 진단 이벤트를 활성화하기 전에 이미 다른 작업들에 의해 많은 양의 데이터들이 트레이스 파일에 기록되어 있다고 하더라도 티팩은 최근에 새롭게 기록된 데이터만을 읽어들입니다.

4. Dump 수행

특정 Process에 바인딩한 후 해당 Process에 대해 다양한 덤프 파일을 생성할 수 있습니다. 아래에 간단한 예가 있습니다.

-- Level 1로 Callstack 덤프 수행
SQL> oradebug dump callstack 1

-- PGA Heap Dump. Level 0x20000001은 최상위 Heap 뿐만 아니라 크기가 가장 큰 5개의 Subheap에 대해 Recursive하게 Dump를 수행하라는 의미입니다. 대단히 유용한 기능입니다.
SQL> oradebug dump heapdump 0x20000001
티팩에서는 위에서 읽은 데이터를 가공해서 분석용 리포트를 제공합니다.
-- 143번 세션에 대해 Callstack 덤프를 1초동안 10회 수행하고 그 결과를 요약해서 리포트할 것
SQL> select * from table(tpack.callstack_prof_report(143));

-- 143번 세션에 대해 PGA Heap Dump를 0x20000001 레벨로 수행하고 그 결과를 해석해서 리포트할 것
SQL> select * from table(tpack.pga_heap_report(143, 2));
티팩은 성능 트러블슈팅에 필요한 기본적인 데이터들 중 일부를 Process에 대한 진단 이벤트나 덤프를 통해 얻습니다. PGA Heap Dump나 Callstack Dump가 대표적인 예입니다. 이런 데이터를 얻기 위한 가장 쉬운(어쩌면 유일한?) 방법으로 oradebug를 사용하고 있습니다.

한가지 기술적인 난관(?)은 SQL 명령내에서 oradebug를 어떻게 호출하느냐입니다. 티팩에서는 Java Stored Procedure를 이용합니다. 여기에 대한 자세한 이야기도 다음에 진행할 예정입니다.

성능 트러블슈팅의 단계가 깊어질수록 oradebug의 매력에 깊이 빠지게 될 것입니다. 특히 Oracle 11g에서는 완전히 새롭게 설계된 Oracle Debugging Framework이 등장했고, 더불어서 oradebug의 기능도 더욱 막강해졌습니다. 자세한 내용은 아래 Tanel Poder의 문서를 참조하세요.

PS) 이 글을 적다보니 oradebug의 사용법(11g의 새로운 Framework까지 포함한)을 상세하게 다룬 실용적인 oradebug 매뉴얼이 있으면 좋겠다는 생각이 드네요. 나중게 기회가 되면 한번 도전해보면 재미있겠습니다.

이전 글 보기

  1. [티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)
저작자 표시
신고
tags : oradebug, 티팩
Trackback 0 : Comment 0

Write a comment


[티팩] 성능 문제를 트러블슈팅하는 두가지 틀(Frame)

오라클 2010.06.22 16:14
퀴즈입니다.

1. 오라클에서 특정 세션(혹은 시스템)의 현재 상태를 바로 알 수 있는 가장 좋은 방법은 무엇일까요?

2. 오라클에서 특정 세션(혹은 시스템)을 하는 일을 추적할 수 있는 가장 좋은 방법은 무엇일까요?

(정답 여부를 떠나서 이 두 질문에 주저없이 대답할 수 있으면 성능 트러블슈팅에 있어서 자신감이 있는 분이라고 봅니다)

성능 문제를 분석하는 두가지 틀로 위의 질문에 대한 저의 답을 대신하겠습니다. 저는 오라클 성능 문제를 트러블슈팅하는 모든 툴과 기법을 아래 두 개의 틀로 분류합니다.

  • 스냅샷(Snapshot) - 특정 시점의 작업의 현재 상태를 조회하는 방법
  • 프로파일(Profile) - 어떤 작업을 시간 순으로 추적하는 방법
예를 들어 볼까요?
  • 10053 진단 이벤트 - 옵티마이저가 하는 일을 시간 순으로 추적하는 프로파일 기능
  • V$SESSION_WAIT - Session의 대기 상태를 조회하는 스냅샷 기능
  • Heap Dump - 특정 세션이나 시스템의 현재 메모리 사용 현황을 조회하는 스냅샷 기능
  • System State Dump - 시스템의 현재 상태를 조회하는 스냅샷 기능
  • Call Stack(oradebug dump callstack) - 특정 세션의 현재 상태에서 호출하고 있는 함수의 Call Tree이므로 스냅샷과 프로파일의 중간 성격
  • Active Session History - Active Session 목록을 초당 한번씩 샘플링한 것이므로 스냅샷과 프로파일의 중간 성격
스냅샷 데이터를 시간의 흐름에 따라 전체 혹은 일부를 샘플링하면 그것이 곧 프로파일이 됩니다. 스냅샷은 특정 시점의 상태를 의미하므로 가장 기본적인 데이터라고 할 수 있습니다.

스냅샷은 특정 시점의 상태를 나타내기 때문에 거의 대부분 차이(Delta)와 비교(Diff)를 통해서만 의미를 가집니다. AWR 리포트를 보면 스냅샷간의 값의 차이(Delta)를 계산해서 보여주죠. 차이와 비교를 통해서 직관적으로 시스템의 현재 상태를 알 수 있습니다.

프로파일은 시간의 흐름에 따라 데이터를 추적하는 방식이기 때문에 거의 대부분 집계와 요약(Summary)를 통해서만 의미를 가집니다. 10046 이벤트에 의해 생성된 프로파일 데이터를 TKPROF 라는 툴을 이용해 집계해서 보는 것이 대표적인 예입니다.

티팩은 위와 같은 간단 명료한 틀 위에서 상황에 따라 적절한 스냅샷과 프로파일만 존재하면 비교와 요약을 통해 대부분의 성능 문제를 트러블슈팅할 수 있다는 생각에 기반하고 있습니다. 앞으로 블로그와 세미나 등을 통해서 보다 구체적인 사례들과 함께 오라클에서 사용 가능한 다양한 기법들을 논의하도록 하겠습니다.

PS) 위의 두 질문에 대해 즉각 답이 가능하신 분들은 그 이유와 함께 답변을 달아주셔도 좋겠습니다.

저작자 표시
신고
tags : 티팩
Trackback 0 : Comments 6
  1. unplugg 2010.06.22 16:42 신고 Modify/Delete Reply

    당연한 대답을 글에 써놓고 질문을 하는게 이상하게 느껴지네요.. ㅡㅡa

  2. IFO 2010.06.22 17:24 신고 Modify/Delete Reply

    "티팩"이 현업의 실무자들에게 널리 사용되는 날을 기대해 봅니다.
    그리고 "티팩"의 편함도 기대해 봐도 될까요? ㅎㅎ

    • 욱짜 2010.06.22 20:39 신고 Modify/Delete

      현재 모습은 기본적인 아이디어를 plsql의 형태로 구현해본 것이고 실제로 손쉽게 사용할 툴이 되려면 또다른 노력과 많은 개선이 필요할 겁니다.

  3. onsider 2010.06.25 18:23 신고 Modify/Delete Reply

    1. 답변이 쉽지는 않았습니다.
    저 같은 경우 snapshot 과 Profile을 하나라고 생각하기 쉽더군요.
    당연히 서로 다른 용도이고 다른 frame을 가지는 있는건데두요...
    (답이 너무 잘보이니, 쉬웠다고 생각되는 듯 합니다. 추후에는 질문만 내시고 정답은 사람들의 댓글이 모두 달린후 공개하는게 더 재미있을것 같습니다. )

    2. 티팩관련질문은 어디에다가 하면 좋을까요?
    11g(11.2.0.1 DB) 설치시 에러가 났는데...질문을 할만한 공간이 마땅치 않네요..
    좋은 장소를 알려주시기 바랍니다..

    감사합니다.

    • 욱짜 2010.06.23 16:50 신고 Modify/Delete

      티팩을 테스트해보시다 생기는 문제는 Ask Exem에 질문하시면 됩니다.

      http://ask.ex-em.com

      말씀하신 문제는 최신 버전을 다시 다운받아서 설치해보시기 바랍니다.

Write a comment