오라클 성능 문제를 트러블슈팅하는 원리는 매우 간단하며, 그 원리를 현실세계에 적용하는 것도 어렵지 않음
그럼에도 불구하고 여전히 오라클 성능 문제를 트러블슈팅하는 것이 어렵게 느껴지는 것은 두 가지에서 기인함
질문
오라클 성능 트러블슈팅의 기본 중의 기본, 핵심 중의 핵심은 무엇일까?
필자가 생각하는 정답은 바로 데이터임
오라클 성능 문제를 트러블슈팅하는 과정은 필요한데이터를 체계적으로 수집하고, 수집한 데이터를 기반해서 문제를 해석하고 해결책을 찾는 일련의 과정임
질문
어떤 데이터를 어떻게 수집할 것인가 ?
데이터를 수집하는 체계적인 방법을 가장 먼저 정의 해야함 (필자: 스냅샷/ 프로파일링 데이터 로 분류)
| 분류 | 의미 | 예제 |
|---|---|---|
| 스냅샷 데이터 | 특정시점의 상태 데이터를 의미함 | 오늘 아침 10시에 V$SESSTAT뷰를 저장했다면, V$SESSTAT뷰에 대한 스냅샷 데이터를 가지고 있음 |
| 프로파일링(트레이스) 데이터 | 특정 구간에서 수행된 작업에 대한 데이터를 의미함 | 오늘 아침 10시부터 10시 10분까지 SQL*Trace를 수행했다면, 10분간의 프로파일링 데이터를 가지고있음 |
스냅샷 데이터는 공간적인 개념이며, 반면에 프로파일링 데이터는 시간적인 개념으로 이 두 가지 종류의 데이터를 합쳐야 완벽한 그림을 그릴수 있음
| 분류 | 종류 | 설명 |
|---|---|---|
| 스냅샷 데이터 | 대부분의 딕셔너리 뷰들 | V$SESSTAT 뷰나 V$SESSION_WAIT뷰 와 같은 뷰들은 인스턴스의 현재상태에 대한 정보를 제공함 |
| AWR 뷰들 | AWR이 제공하는 대부분의 뷰들은 특정 시점의 스냅샷 데이터들임 * 오라클은 한시간에 한번씩 데이터베이스의 전반적인 상태에 대한 스냅샷을 생성함 * AWR 스냅샷은 많은 수의 뷰들에 대한 스냅샷 데이터로 구성되어 있음 | |
| 덤프 파일들 | 오라클이 제공하는 덤프 파일들은 대부분 스냅샷 데이터임 * 예를 들어 PGA 힙 덤프(PGA Heap Dump)는 PGA의 현재 상태를 나타내는 스냅샷 데이터임 | |
| 프로파일링 데이터 | 진단 이벤트들 | SQL문장의 수행시간 정보를 기록하는 10046진단 이벤트, 옵티마이저가 SQL문장을 최적화하는 과정을 기록하는 10053 진단 이벤트등 은 모두 프로파일링 데이터를 생성함 * 이들 데이터들은 프로세스가 하는 일을 시간 순으로 기록한 것들임 |
| 매뉴얼 프로파일링 | V$SESSION_WAIT 뷰 자체는 스냅샷 데이터에 해당함 하지만 이뷰를 반복적으로 액세스하면 마치 프로파일링을 수행한 것과 비슷한 효과를 얻을 수 있음 |
| 분류 | 방법 | 설명 |
|---|---|---|
| 스냅샷 데이터 | 차이(Delta) 값을 구함 | 특정 시점에서의 값 그 자체보다는 시점 A 와 시점 B 사이에 어떤 차이가 있는가가 핵심적인 데이터임 * 가령 Logical Reads가 얼마나 증가하는지, 리두크기는 얼마나 증가하는지 등의 데이터를 얻는 것이 중요함 * AWR 리포트는 두 개의 스냅샷 간의 차이(Delta)값을 효과적으로 보여주는 것을 목적으로 함 |
| 프로파일링 데이터 | 집계(Summary)를 수행 | 프로파일링 데이터는 시간 순으로 모든 작업, 혹은 아주 많은 수의 작업을 기록함 * 이 많은 데이터를 일일이 확인하는 것은 어려우며 대신 효과적으로 집계를 함으로써 의미있는 정보를 얻게 됨 * TKPROF 리포트를 사용해 보신 분이라면 그 의미를 직관적으로 이해하실수 있음 |
내용 요약
스냅샷 데이터와 리포트를 만드는 기본적인 방법
스냅샷 데이터와 리포트를 만드는 간단한 예제
/**
-- STEP1. 우선 다음과 같이 V$SYSSTAT뷰에 대한 스냅샷을 만듬
-- 1) V$SYSSTAT뷰의 내용을 테이블 SYSSTAT1에 저장함으로써 스냅샷을 만들수 있음
**/
SQL> create table sysstat1 as select * from v$sysstat;
테이블이 생성되었습니다.
-- STEP2. 그리고 ALL_OBJECTS뷰를 읽는 작업을 수행함
SQL> select count(*) from all_objects;
COUNT(*)
----------
60078
-- STEP3. 다음으로 두번째 스냅샷을 테이블 SYSSTAT2에 만듬
SQL> create table sysstat2 as select * from v$sysstat;
테이블이 생성되었습니다.
/**
-- STEP4. 스냅샷 간의 차이 값이야말로 두 개의 스냅샷에 해당하는 구간(시간 스냅샷~ 끝 스냅샷)에서 어떤 일이 발생했는지를 말해주기 때문임
-- 1) 아래와 같이 두개의 스냅샷, 테이블 SYSSTAT2 와 SYSSTAT1간의 차이(Delta)값을 구함으로써 어떤 변화가 있었는지 알수 있음
-- 2) 아래의 스냅샷 리포트로부터 얻을수 있는 결론 중 하나는 ALL_OBJECTS 뷰를 읽는 작업에 의해 Physical Reads가 2M 바이트 이상 발생한다는 것임
**/
SQL> -- get delta
SQL> col name format a40
SQL> col delta format 999,999,999,999
SQL> select s1.name , (s2.value - s1.value) as delta
2 from sysstat1 s1, sysstat2 s2
3 where s1.statistic# = s2.statistic#
4 and (s2.value - s1.value) > 0
5 order by 2 desc;
NAME DELTA
---------------------------------------- ----------------
session pga memory max 18,219,008
cell physical IO interconnect bytes 3,028,480
session uga memory max 2,741,368
physical read total bytes 2,383,872
physical read bytes 1,564,672
file io wait time 665,853
physical write total bytes 644,608
session pga memory 196,608
session uga memory 80,680
index scans kdiixs1 69,669
table scan rows gotten 68,216
.... (중략)
성능트러블 슈팅을 위해서는 보다 많은 수의 뷰들에 대한 스냅샷 데이터가 필요하며, 어떤 뷰라도 성능 문제에 대한 데이터만 제공한다면 스냅샷의 대상이 될수 있음
스냅샷 데이터에 대한 리포트 중 가장 광범위한 데이터를 제공하는 것이 AWR리포트임
AWR리포트를 생성하는 방법
AWR스냅샷을 생성 후 스냅샷간의 차이값을 리포팅하는 예제
-- STEP1. DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT함수를 이용해 스냅샷A 를 만듬
SQL> -- 1st snapshot
SQL> col begin_snap new_value begin_snap;
SQL> col db_id new_value db_id;
SQL> col inst_num new_value inst_num;
SQL> select dbid as db_id from v$database;
DB_ID
----------
84928337
SQL> select instance_number as inst_num from v$instance;
INST_NUM
----------
1
SQL> select dbms_workload_repository.create_snapshot as begin_snap from dual;
BEGIN_SNAP
----------
5
-- STEP2. ALL_OBJECTS뷰를 읽는 작업을 수행함
SQL> select count(*) from all_objects;
COUNT(*)
----------
60080
-- STEP3. 스냅샷 B를 만듬
SQL> -- 2nd snapshot
SQL> col end_snap new_value end_snap;
SQL> select dbms_workload_repository.create_snapshot as end_snap from dual;
END_SNAP
----------
6
-- STEP4. DBMS_WORKLOAD_REPOSITORY.AWR_REPORT_TEXT[_HTML]함수를 이용해서 스냅샷 B와 스냅샷 A간의 차이점을 리포팅함
SQL> -- AWR report
SQL> select * from table(dbms_workload_repository.awr_report_text(&db_id, &inst_num, &begin_snap, &end_snap));
Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
OUTPUT
--------------------------------------------------------------------------------
Avg
wait % DB
Event Waits Time(s) (ms) time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU 1 49.3
db file sequential read 80 0 5 29.8 User I/O
control file sequential read 89 0 2 10.7 System I/O
db file scattered read 4 0 3 .8 User I/O
Disk file operations I/O 1 0 1 .1 User I/O
Host CPU (CPUs: 2 Cores: 2 Sockets: 1)
... (중략)
왜? 스냅샷은 다양한 방식으로 사용할수 있는 차이점이 존재하는가
오라클 성능 트러블슈팅을 위해 필요한 스냅샷 데이터의 99%는 오라클이 제공하는 동적성능뷰(Dynamic Performanc View)에서 얻을수 있음
하지만 1% 정도의 문제에 대해서는 동적 성능 뷰만으로 부족한 경우가 있음 (빈도는 1%이지만 중요도로 10%이상이라고 생각됨)
PGA의 크기가 계속증가하면서 세션의 성능이 저하되는 현상
이런 경우에 사용할수 잇는 것이 PGA 힙 덤프임
PGA힙 덤프를 수행하는 예제
-- STEP1. PGA힙 덤프 수행
SQL> -- every dump is snapshot data!!!
SQL> alter session set events 'immediate trace name heapdump level 1';
세션이 변경되었습니다.
-- STEP2. 현재 프로세스의 PGA힙 정보가 트레이스 파일에 기록됨
HEAP DUMP heap name="pga heap" desc=0BBC9830
extent sz=0x206c alt=108 het=32767 rec=0 flg=3 opc=2
parent=00000000 owner=00000000 nex=00000000 xsz=0xfff8 heap=00000000
fl2=0x60, nex=00000000
EXTENT 0 addr=0D230008
Chunk d230010 sz= 65520 free " "
EXTENT 1 addr=0D220008
Chunk d220010 sz= 1628 freeable "diag pga " ds=0CEE04C0
Chunk d22066c sz= 4164 freeable "diag pga " ds=0CEE04C0
Chunk d2216b0 sz= 4164 freeable "diag pga " ds=0CEE04C0
Chunk d2226f4 sz= 8224 freeable "PLS PGA hp " ds=08AE8EA8
Chunk d224714 sz= 2096 freeable "PLS PGA hp " ds=08AE8EA8
Chunk d224f44 sz= 8284 recreate "PLS PGA hp " latch=00000000
PGA 힙 덤프와 같은 덤프 데이터는 가장 자세한 형태의 스냅샷 데이터라고 볼수 있음
이런 종류의 스냅샷 데이터는 지나치게 정밀하기 때문에 다른 종류의 스냅샷 데이터 처럼 차이(Delta)값을 구하는 것이 어려우며 큰 의미도없고 사용시 적절한 형태로 집계할 필요가 있음
프로파일링 데이터를 얻고 리포팅하는 기본적인 방법
프로파일링 데이터와 리포트를 만드는 간단한 예제
-- STEP1. 세션#1 에서 ALL_OBJECTS뷰를 읽는 작업을 수행
SQL> -- session #1
SQL> exec dbms_application_info.set_client_info('session1');
PL/SQL 처리가 정상적으로 완료되었습니다.
SQL> select count(*) from all_objects;
COUNT(*)
----------
60080
-- STEP2. 세션#1 이 작업을 수행하는 동안 세션 #2로 부터 세션1이 어떤 대기 이벤트(WaitEvent)을 대기하는지 프로파일링하는게 예제의핵심
-- 1) 우선 세션#2에서 세션#1의 세션아이디(SID)값을 얻음
SQL> -- session #2
SQL> col sid new_value sid
SQL> select sid from v$session where client_info = 'session1';
SID
----------
12
-- STEP3. 총 1,000회 걸쳐 V$SESSION_WAIT뷰를 반복적으로 읽으면서 대기 이벤트를 얻음
-- 즉 대기 이벤트 정보를 프로파일링 함
SQL> set serveroutput on
SQL> declare
2 v_sw v$session_wait%rowtype;
3 begin
4 for idx in 1 ... 1000 loop
5 begin
6 select * into v_sw
7 from v$session_wait
8 where sid = &sid
9 and state = 'WAITING';
10
11 dbms_output.put_line(
12 'event = ' || v_sw.event ||
13 ', seq# = '|| v_sw.seq# ||
14 ', p1 = ' || v_sw.p1 ||
15 ', elapsed = ' ||
16 trunc(v_sw.wait_time_micro/1000,2) || '(ms)');
17
18 exception when others then null;
19
20 end;
21 end loop;
22 end;
23 /
-- STEP4. 그결과 아래와 같이 대기 이벤트 목록을 얻을 수 있음
--
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.68(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.76(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.84(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.91(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72755.99(ms)
event = SQL*Net message from client, seq# = 39, p1 = 1111838976, elapsed = 72756.07(ms)
V$SESSION_WAIT 뷰 자체는 스냅샷 데이터에 해당하지만, 그 뷰를 시간의 흐름에 따라 반복적으로 엑세스하면 프로파일링 데이터가됨
즉, 프로파일링 데이터는 스냅샷 데이터의 시간 확장판 이라고 할수 있음
프로파일링 데이터에 대해 대기이벤트를 기준으로 히트(Hit) 회수를 집계하는 방법
-- STEP1.우선 프로파일링 데이터를 저장할 테이블 SESSION_WAIT를 만듬
SQL> create table session_wait as select * from v$session_wait where 1=0;
테이블이 생성되었습니다.
-- STEP2. 세션#1 에 대해 대기 이벤트를 프로파일링하면서 그 결과를 테이블 SESSION_WAIT에 저장함
SQL> begin
2 for idx in 1 .. 1000 loop
3
4 insert into session_wait
5 select *
6 from v$session_wait
7 where sid = &sid
8 and state = 'WAITING';
9
10 dbms_lock.sleep(0.001);
11 end loop;
12 end;
13 /
구 7: where sid = &sid
신 7: where sid = 12
PL/SQL 처리가 정상적으로 완료되었습니다.
-- STEP3. 프로파일링 결과가 테이블에 저장되어 있기 때문에 다음과 같이 손쉽게 집계리포트를 만들수 있음
-- 1) 집계(Summary)를 수행함으로써 어떤 대기 이벤트가 주로 발생했는지를 알수 있음
SQL> select event, count(*) as hits
2 from session_wait
3 group by event
4 order by 2 desc;
EVENT HITS
---------------------------------------------------------------- ----------
SQL*Net message from client 1000
-- STEP4. 위의 방법을 응용하면 테이블을 만들고 테이블에 INSERT하는 등의 번거로운 작업 없이
-- 하나의 쿼리로 동일한 결과의 리포트를 만들수 있음
SQL> select /*+ no_query_transformation ordered use_nl(w) */
2 w.event, count(*) as hits
3 from (select level from dual connect by level <= 50000) x,
4 (select decode(state, 'WAITING', event, 'ON CPU') as event
5 from v$session_wait
6 where sid = &sid) w
7 group by w.event
8 order by 2 desc;
EVENT HITS
---------------------------------------------------------------- ----------
SQL*Net message from client 50000
쿼리를 해석하는 방법
위와 같은 효과를 얻기 위해서 다음과 같은 힌트를를 사용하여 SQL제어함
대기 이벤트별 대기 회수와 대기 시간도 어느정도 측정할수 있는 예제
-- STEP1. 대기 이벤트별 대기 회수와 대기 시간 측정가능 SQL작성
SQL> -- session2
SQL> col event format a30
SQL> with w as (
2 select /*+ no_query_transformation ordered use_nl(w) */
3 w.event
4 , count(*) as hits
5 , count(distinct seq#) as dist_waits
6 , 5000 as total_hits
7 from (select level from dual connect by level <= 50000) x
8 , (select decode(state, 'WAITING', event, 'ON CPU') as event
9 , decode(state, 'WAITING', seq#, 0) as seq#
10 from v$session_wait
11 where sid = &sid) w
12 group by w.event
13 order by 2 desc
14 )
15 select /*+ ordered */
16 w.event
17 , trunc(100*w.hits/w.total_hits,1) as wait_pct
18 , trunc((t2.gt - t1.gt)*w.hits/w.total_hits/100,2) as wait_time
19 , trunc((t2.gt - t1.gt)*w.hits/w.total_hits/w.dist_waits/100,3) as avg_wait_time
20 from (select dbms_utility.get_time as gt from dual) t1
21 , w
22 , (select dbms_utility.get_time as gt from dual) t2
23 order by 2 desc;
-- STEP2. 아래에 그 결과가 있음
EVENT WAIT_PCT WAIT_TIME AVG_WAIT_TIME
------------------------------ ---------- ---------- -------------
SQL*Net message from client 1000 4.1 4.1
쿼리를 해석하는 방법
위에서 소개한 프로파일링 기법은
매뉴얼 프로파일링 기법의 한계는 100% 완벽한 데이터(= 샘플링 데이터)가 아니라는 점이만, 오라클 자체적으로 제공하는 프로파일링 데이터는 이런제약사항이 없음
10046 진단 이벤트의 정확한 목적은 SQL 수행의 각 단계별로 시간 정보를 얻는 것임
10046 진단 이벤트 정의
prompt> oerr 10046
"enable SQL statement timing"
// *Cause:
// *Action:
프로파일링 데이터는 시계열데이터이며, 이러한 요구사항을 가장 완벽하게 구현한 것이 10046 진단 이벤트임
아래와 같은 방법으로 대기 이벤트의 대기 시간까지 포함된 프로파일링 데이터를 얻을수 있음
10046 진단 이벤트에 의해 생성되는 프로파일링 데이터를 확인
-- STEP1. 10046 진단 이벤트를 활성화한 상태에서 쿼리를 수행함
SQL> alter session set events '10046 trace name context forever, level 8';
세션이 변경되었습니다.
SQL> select count(*) from all_objects;
COUNT(*)
----------
60081
SQL>
SQL> alter session set events '10046 trace name context off';
세션이 변경되었습니다.
/**
-- STEP2. 10046 진단 이벤트에 의해 생성된 프로파일링 데이터는 서버 프로세스의 트레이스 파일에 기록됨
-- 아래 데이터를 보면 앞서 매뉴얼 프로파일링을 통해서 얻은 데이터와 거의 유사항 포멧으로 기록되는 것을 알 수 있음
**/
PARSING IN CURSOR #4 len=32 dep=0 uid=52 oct=3 lid=52 tim=2454862187 hv=789896629 ad='220f54a4' sqlid='9tz4qu4rj9rdp'
select count(*) from all_objects
END OF STMT
PARSE #4:c=171601,e=256547,p=2,cr=258,cu=2,mis=1,r=0,dep=0,og=1,plh=1743485846,tim=2454862184
EXEC #4:c=0,e=150,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1743485846,tim=2454862732
WAIT #4: nam='SQL*Net message to client' ela= 6 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=2454862904
/**
-- STEP3. 프로파일링 데이터는 집계(Summary)를 통해서 의미있는 정보를 얻을수 있음
-- 10046 진단 이벤트에 의해 생성된 프로파일링 데이터는 TKPROF툴을 이용해 집계 리포트를 얻을수 있음
**/
D:\app_db\engine_oracle\diag\rdbms\ora11gr2\ora11gr2\trace>tkprof ora11gr2_ora_1312.trc ora11gr2_ora_1312.out
TKPROF: Release 11.2.0.1.0 - Development on 금 3월 2 09:07:49 2012
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
D:\app_db\engine_oracle\diag\rdbms\ora11gr2\ora11gr2\trace>noetpad ora11gr2_ora_1312.out
SQL ID: 9tz4qu4rj9rdp
Plan Hash: 1743485846
select count(*)
from
all_objects
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.12 0.12 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1.71 1.74 0 38115 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 1.84 1.87 0 38115 0 1
...(중략)
TKPROF는 Transient Kernel Profiler의 약자이며, Profiler라는 용어에 주목해야함
TKPROF가 다루는 데이터가 프로파일링 데이터라는 것을 스스로 말하고 있음
10053 진단 이벤트는 옵티마이저가 최적화(Optimizer)를 수행하는 과정을 시간 순으로 기록함
10053 진단 이벤트 정의
prompt> oerr 10053
"CBO Enable optimzier trace"
// *Cause:
// *Action:
진단 이벤트의 정의로부터 프로파일링을 수행한다는 것을 명확히 알수 있음
10053 진단 이벤트에 의해 생성되는 프로파일링 데이터를 확인
-- STEP1. 10053 진단 이벤트를 활성화한 상태에서 쿼리를 수행함
SQL> alter session set events '10053 trace name context forever, level 1';
세션이 변경되었습니다.
SQL> select count(*) from all_objects where rownum = 1;
COUNT(*)
----------
1
SQL> alter session set events '10053 trace name context off';
세션이 변경되었습니다.
-- STEP2. 그리고 트레이스 파일의 내용을 확인해보면 옵티마이저가 수행하는 일련의 작업이 시간순으로 기록된 것을 알수 있음
-- 이런 데이터는 "왜 이런 실행계획이 만들어지는가?" 라는 의문을 해결할수 있는 가장 완벽한 정보를 제공함
SQL> @trace_file
-- STEP3. 10053 진단 이벤트에 의해 생성된 프로파일링 데이터(트레이스 파일)는 원본 데이터를 직접이용하는 것이 가장 보편적인 사용방법임
-- 하지만 필요하면 집계를 통해서 원하는 데이터를 얻을수있음
-- 예를 들어 아래와 같은 방법으로 트레이스 파일로 부터 조인 회수를 구할 수 있음
select count(*)
from table(tpack.get_tracefile_contents(tpack.get_tracefile_name))
where column_value like 'Now joining%';
동적 성능 뷰(Dynamic Performance View)와 덤프 파일은 대부분 스냅샷 데이터에 해당하며, 진단이벤트는 프로파일링 데이터에 해당함
하지만 예외적인 데이터들이 있음
V$ACTIVE_SESSION_HISTORY 뷰는 1초 간격으로 저장된 액티브 세션의 과거 목록을 가지고 있음
따라서 V$ACTIVE_SESSION_HISTORY 뷰는 동적 성능 뷰임에도 불구하고 프로파일링 데이터로 분류할수 있음
V$ACTIVE_SESSION_HISTORY 뷰로 확인되는 데이터를 확인
-- Note:
SQL> -- v$active_session_history
SQL> col sid format 999
SQL> col sql_text format a20
SQL> col event format a10
SQL> col sid new_value sid
SQL> select to_char(h.sample_time,'mi:ss') as sample_time
2 , h.sample_id
3 , h.session_id as sid
4 , h.session_state as st
5 , h.sql_id
6 , (select sql_text from v$sqlarea a where a.sql_id = h.sql_id) as sql_text
7 , event
8 , blocking_session as blocker
9 from v$active_session_history h
10 where session_id = &sid
11 ;
구 10: where session_id = &sid
신 10: where session_id = 12
SAMPL SAMPLE_ID SID ST SQL_ID SQL_TEXT EVENT BLOCKER
----- ---------- ---- ------- ------------- -------------------- ---------- ----------
44:30 8747 12 ON CPU 9tz4qu4rj9rdp select count(*) from
all_objects
37:40 8338 12 ON CPU 25vwt55t1093f select to_clob(
restart||queue_
schema||'.'||queue_n
ame || '(' || queue_
... (중략)
스냅샷 데이터를 아주 빈번하게 엑세스하면 프로파일링 데이터가 된다는 원리가 가장 이상적으로 구현된 뷰가 V$ACTIVE_SESSION_HISTORY뷰라고 할수 있음
콜 스택 덤프는 특정 프로세스의 현재 시점에서의 함수 히스토리를 시간의 역순으로 출력하는 기능을 제공함
콜 스택 덤프 생성으로 확인되는 데이터를 확인
-- STEP1. 콜 스택 덤프 명령을 수행하면 트레이스 파일에 다음과 같이 함수 호출 히스토리가 출력됨
SQL> -- callstack data is snapshot + profiling
SQL> alter session set events 'immediate trace name callstack level 1';
세션이 변경되었습니다.
-- STEP2. 아래의 결과가 의미하는 것은 서버 프로세스가 현재의 명령을 처리하기 위해
-- 1) { 00000000 -> 76EA3779 -> _OracleThreadStart -> _opimai -> ... -> _ksedst_tracecb -> _skdstdst } 의 순서로 함수를 호출 중이라는 것을 의미함
-- 2) 현재 호출 중인 가장 함수는 가중 위에 있는 _skdstdst 함수임
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
EnumerateLoadedModules64 failed with error -1073741819
_skdstdst()+121 CALLrel _kgdsdst() E8E9768 0
_ksedst1()+93 CALLrel _skdstdst() E8E9768 0 0 436646 435BE2
436646
_ksedst_tracecb()+5 CALLrel _ksedst1() 0 0
4
_dbkdaKsdActDriver( CALLreg 00000000 1
)+3615
06E05165 CALLreg 00000000 DB40454 E8EAEA0
06E05D11 CALLrel 06E04E06 DB40454 5C0D830 20C0003
E8EAEA0 1
06DFE9A5 CALLrel 06E059F2 DB40454 DB4ECF4
075B4D0A CALLrel 06DFE972 DB40454 DB4ECD8
_dbkdParseCmd()+395 CALLrel _dbgdParseCmd() DB40454 BC20380 E13FFD0
DB413C8 1D843C84 26 3 0 0
E8EB4FC
__VInfreq__kkyase() CALLrel _dbkdParseCmd() 1D843C84 26 3 E8EB4FC
+5166
_kksExecuteCommand( CALLrel _kkyase() 1D843C74
)+1024
_opiexe()+17037 CALLrel _kksExecuteCommand( E4902A0 2 E8ECA98
)
_kpoal8()+2109 CALLrel _opiexe() 49 3 E8ECA98
_opiodr()+1248 CALLreg 00000000 5E 1C E8EF070
61AB29CD CALLreg 00000000 5E 1C E8EF070 0
_opitsk()+1404 CALL??? 00000000 BC2AC00 5E E8EF070 0 E8EED00
E8EF19C 53E52E 0 E8EF1C8
_opiino()+980 CALLrel _opitsk() 0 0
_opiodr()+1248 CALLreg 00000000 3C 4 E8EFBC4
_opidrv()+1201 CALLrel _opiodr() 3C 4 E8EFBC4 0
_sou2o()+55 CALLrel _opidrv() 3C 4 E8EFBC4
_opimai_real()+124 CALLrel _sou2o() E8EFBD4 3C 4 E8EFBC4
_opimai()+125 CALLrel _opimai_real() 2 E8EFBFC
_OracleThreadStart@ CALLrel _opimai() 2 E8EFF3C 0 70 FFFFFFFF
4()+830 FFFFFFFF
752EED67 CALLptr 00000000 E7EFF6C E8EFFD4 76EA377B
E7EFF6C 787D2C88 0
76EA3779 CALLreg 00000000 E7EFF6C 787D2C88 0 0 E7EFF6C
0
76EA3749 CALLrel 76EA3754 401326 E7EFF6C 0 0 0 0
00000000 CALL??? 00000000
----- End of Call Stack Trace -----
이처럼 콜 스택 덤프의 결과는 스냅샷이면서 동시에 프로파일링 이기도 한 독특한 데이터임
만일 콜 스택 덤프를 여러 번 수행하면 여러 개의 콜 스택이 기록될 것이며, 콜 스택에 대한 프로파일링 데이터를 얻을수 있음
이 데이터를 분석하면 시간에 따라 콜 스택이 어떻게 변하는지, 어떤 콜 스택이 주로 사용되는지 알 수 있음
콜 스택를 여러번 수행하여 여러 개의 기록을 기반으로 프로파일링 데이터를 확인
SQL> select * from table(tpack.callstack_prof_report(&sid));
10046 진단 이벤트나 10053 진단 이벤트와 같이 진단 이벤트들은 주로 프로파일링 데이터를 얻는데 사용되지만 또 다른 많은 수의 진단 이벤트들은 현재 상태에 대한 정보를 얻는 목적으로 사용되기도함
10032 진단 이벤트 정의
prompt> oerr 10032
"sort statistics (SOR*)"
// *Cause:
// *Action:
10032 진단 이벤트에 의해 생성되는 스냅샷 데이터를 확인
-- STEP1. 10032 진단 이벤트를 활성화한 상태에서 쿼리를 수행함
SQL> -- 10032 trace
SQL> ALTER SESSION SET EVENTS '10032 trace name context forever, level 10';
세션이 변경되었습니다.
SQL> select OWNER, count(*) from ALL_OBJECTS group by OWNER order by OWNER;
OWNER COUNT(*)
------------------------------ ----------
APPQOSSYS 3
DBSNMP 57
EXFSYS 187
MAZAL 3
OLAPSYS 717
ORACLE_OCM 8
OUTLN 8
PUBLIC 24438
SYS 30447
SYSMAN 3404
SYSTEM 503
WMSYS 306
-- STEP3. 10032 진단 이벤트 결과를 확인
-- 마치 V$SESSTAT뷰 처럼 현재 상태에 대한 스냅샷 데이터를 제공하고 있음
---- Sort Parameters ------------------------------
sort_area_size 65536
sort_area_retained_size 65536
sort_multiblock_read_count 1
max intermediate merge width 3
---- Sort Statistics ------------------------------
Input records 60081
Output records 12
Total number of comparisons performed 150601
Comparisons performed by in-memory sort 150601
Total amount of memory used 2048
Uses version 1 sort
---- End of Sort Statistics -----------------------
진단 이벤트가 제공하는 데이터의 다양성을 소개하기 위해서 10032 진단 이벤트를 예제로 다룸
Oracle Event Reference
원문URL : https://netfiles.uiuc.edu/jstrode/www/oraparm/EventReference.html#10013