My Books

My Slides

rss 아이콘 이미지

일반적으로 오라클 성능 분석 방법론은 대기 시간의 분석에 초점이 맞춰져 있습니다. 즉, 응답시간을 CPU 사용시간과 대기시간으로 구분하고 대기시간은 개별 대기이벤트의 대기시간으로 세분화함으로써 성능 저하의 원인을 빠르게 진단하는 방법을 사용합니다. 이러한 분석의 기본 전제는 대기시간보다 CPU 사용시간의 비율이 높다면 현재 수행되는 프로세스는 정상적으로 일을 잘하고 있다는 것입니다. 반대로 말하면 대기시간이 비중이 높을수록 성능 이슈가 있다는 것을 의미하기도 합니다.


그런데 간혹 "CPU 사용률(%)이 높은 프로세스가 정상적으로 일을 처리하고 있는지?" 라는 의문이 생길 때가 있습니다.  일반적으로 이런 경우에 사용할 수 있는 방법은 truss, tusc, strace등과 같은 유틸리티를 이용해서 OS 시스템 콜을 분석하는 것입니다. 하지만 이러한 툴들이 제공하는 최하위 레벨의 시스템 콜을 분석하는 것은 매우 어려운 일입니다. 


이를 보완하기 위한 방법으로 리눅스의 경우에는 "perf" 툴을 이용해서 스택 트레이스를 확인할 수 있으며, 이를 통해 오라클 커널 function을 확인할 수 있습니다. 이를 이용해서 오라클 에이스 중의 한명인 Craig shallahamer는 2014년 OOW에서 아주 흥미롭고 유용한 기법을 발표합니다. 간단히 요약하면, perf 툴과 v$ 데이터를 이용해서 현재 수행중인 프로세스의 CPU Time과 대기 시간을 세분화해서 제공하는 방법입니다. 해당 툴의 이름은 fulltime.sh이며 여기에서 다운로드 받을 수 있습니다. 물론 perf 툴에서 제공하는 커널 function 명 또한 이해하기 쉽지는 않지만 몇 가지 잘 알려진 명명 규칙(예시-1 참조)을 통해 해당 function의 수행 내용을 유추하거나 오라클에 문의할 때 도움이 될 수 있을 것입니다.


예시-1. 몇 가지 커널 function 명명 규칙

  • kcb  (kernel cache buffer)
  • kcbgtcr (kernel cache buffer get CR)
  • smb (sort merge buffer)
  • smbget (sort merge buffer get)

그럼 예제를 통해 확인해보겠습니다.


1. CPU를 과도하게 사용하는 쿼리 수행 후 WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼 값 확인


-- CPU를 과도하게 사용하는 쿼리  
select count(*) from big_t, big_t;

-- 해당 쿼리의 예상 실행 계획
-----------------------------------------------------------------------
| Id  | Operation             | Name  | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------------
|   0 | SELECT STATEMENT      |       |     1 |   580M  (1)| 06:17:51 |
|   1 |  SORT AGGREGATE       |       |     1 |            |          |
|   2 |   MERGE JOIN CARTESIAN|       |   250G|   580M  (1)| 06:17:51 |
|   3 |    TABLE ACCESS FULL  | BIG_T |   500K|  1163   (1)| 00:00:01 |
|   4 |    BUFFER SORT        |       |   500K|   580M  (1)| 06:17:51 |
|   5 |     TABLE ACCESS FULL | BIG_T |   500K|  1161   (1)| 00:00:01 |
-----------------------------------------------------------------------

--WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼 값 확인  
SYS@OOW1:1> @mon_1_sess2 202

       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          716 direct path read                     100.0           .660        1,411.09
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          717 resmgr:cpu quantum                    97.2         14.700          516.28
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          717 resmgr:cpu quantum                    99.3         14.700        2,126.53
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          722 resmgr:cpu quantum                    90.8         29.970          294.57
SCOTT@OOW1:1> /
                                                                                                   TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME       LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs)     (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- ---------------
   202 ON_CPU   ACTIVE          723 resmgr:cpu quantum                    99.5           .760          158.56
결과 분석
해당 SQL 수행 시에 대기시간은 거의 없고 대부분 CPU를 사용하는 것을 알 수 있습니다. CPU를 과도하게 사용함에 따라 리소스 관리 정책에 의해 'resmgr:cpu quantum' 대기이벤트를 대기하지만 대기 시간의 비율은 아주 낮습니다.




2. fulltime.sh를 이용한 CPU Time 분석


fulltime.sh의 사용법은 다음과 같습니다.
$ fulltime.sh <spid> <interval> <loop cnt>


아래의 수행 결과를 보면 CPU 사용 시간의 비율이 99.66%, 대기시간의 비율이 0.34%인것을 알 수 있습니다. 또한 CPU 사용시간 중에서 smbget 커널 function의 사용 비율이 36.26%임을 알 수 있습니다. 


예시-2. pert 수행 결과

PID: 3234  SID: 202  SERIAL: 44156  USERNAME: SCOTT  at 21-Aug-2016 07:57:33
CURRENT SQL:  select count(*) from big_t, big_t

total time: 2.123 secs,  CPU: 2.116 secs (99.66%),  wait: .007 secs (.34%)
                                                                   Time
Time Component                                                     secs       %
------------------------------------------------------------ ---------- -------
cpu : [.] smbget                                                  0.770   36.26
cpu : [.] sorgetqbf                                               0.589   27.74
cpu : [.] qersoFetchSimple                                        0.361   17.02
cpu : [.] rworupo                                                 0.178    8.40
cpu : [.] qeaeCn1Serial                                           0.147    6.94
cpu : [.] kskchk                                                  0.052    2.47
cpu : [?] sum of funcs consuming less than 2% of CPU time         0.017     .80
wait: resmgr:cpu quantum  


모니터링 후 (CTRL+C로 종료)에 엔터를 입력하면 스택 트레이스에 대한 트리 구조의 perf report 결과를 확인할 수 있습니다. (예시-3 참조) 이를 통해 커널 function을 보다 더 세분화해서 분석할 수 있습니다.


예시-3. perf report 수행 결과

                                       
To see the Call Graph, press ENTER or to exit press CNTRL-C.
Samples remaining: 5
Gathering next 3 second sample...
^C

# Overhead          Command      Shared Object                         Symbol
# ........  ...............  .................  .............................
#
    37.21%  oracle_3234_oow  oracle             [.] smbget
            |
            --- smbget
               |
               |--94.84%-- sorgetqbf
               |          qersoFetchSimple
               |          qersoFetch
               |          qerjotFetch
               |          qergsFetch
               |          opifch2
               |          kpoal8
               |          opiodr
               |          ttcpip
               |          opitsk
               |          opiino
               |          opiodr
               |          opidrv
               |          sou2o
               |          opimai_real



글을 마치며


DB 인터널 관련 자료들을 보면 시스템 트레이싱 기법을 자주 접하게 됩니다. 이 글에서 언급된 fulltime.sh 뿐 아니라 Tanel Porder가 사용하는 몇 가지 스크립트에서도 시스템 트레이싱 기법이 소개됩니다. 물론, 과연 이렇게까지 세밀하게 볼 필요가 있을까? 또는 이렇게 자세히 분석할 필요가 있을까? 라는 의문이 들기도 합니다. 또한 대부분의 성능문제는 이러한 것을 모르더라도 충분히 해결 가능하기도 합니다. 하지만 아주 민감하고 어려운, 또는 누구도 풀지 못하는 성능 이슈를 처리해야할 때 이러한 기법은 큰 도움이 될 것입니다. 결국, 엔지니어의 길을 가기 위해서는 끝없는 정진이 필요한 것 같습니다.

저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License
TAG perf

1. SECONDS_IN_WAIT 및 WAIT_TIME 칼럼의 문제점


11g 부터 제공되는 WAIT_TIME_MICROTIME_SINCE_LAST_WAIT_MICRO 칼럼은 기존에 제공되던 SECONDS_IN_WAIT 및 WAIT_TIME 칼럼의 한계를 뛰어넘는 매우 유용한 데이터를 제공합니다. 기존에 제공되는 SECONDS_IN_WAIT 및 WAIT_TIME 칼럼의 한계점은 다음과 같습니다.

  • 세션 상태가 WAITING인 경우, SECONDS_IN_WAIT 칼럼은 대기이벤트가 지속된 시간을 제공합니다. 하지만 enqueue를 제외한 일반적인 대기이벤트 (예를 들어 db file sequential read) 들의 1회 대기 시간은 대략 수 밀리세컨 ~ 수십 밀리세컨 정도이므로 초 단위로 제공되는 SECONDS_IN_WAIT 칼럼에서는 대부분 0으로 표시됩니다.
  • 세션 상태가 WAITING이 아닌 경우 (ON CPU 상태인 경우), CPU를 사용한 시간을  확인할 수 가 없습니다. 
  • 세션 상태가 WAITING이 아닌 경우 (ON CPU 상태인 경우), 이전 대기가 지속된 시간을 확인할 수 없습니다. 단순히 이전 대기가 1/100초 이내였는지 정도의 여부만을 확인할 수 있을 뿐입니다.
이러한 구조적인 한계점으로 인해 11g 부터는 SECONDS_IN_WAIT 및 WAIT_TIME 칼럼 대신에 WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼을 사용하는 것을 권고하고 있습니다.




2. WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼의 이해


세션 상태가 WAITING (V$SESSION.WAIT_TIME=0)인 경우에, WAIT_TIME_MICRO 칼럼은 '대기 지속 시간'을 의미합니다. 이때 TIME_SINCE_LAST_WAIT_MICRO 칼럼 값은 0입니다.


세션 상태가 ON_CPU (V$SESSION.WAIT_TIME<>0)인 경우에, WAIT_TIME_MICRO 칼럼은 '마지막 (바로 직전) 대기 지속 시간'을 의미하고, TIME_SINCE_LAST_WAIT_MICRO 칼럼은 '마지막 대기 이후부터 지금까지의 경과 시간'을 의미합니다. 다시 말해 CPU 사용 지속 시간을 의미합니다. (그림-1 참조)


그림-1. WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 개념도





3. WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼을 이용한 세션 액티비티 모니터링 방안


세션이 현재 ON_CPU 상태인 경우에, "수식-1"을 이용해서 대기시간과 CPU 사용시간의 비율을 계산할 수 있습니다.


수식-1. SESS_ACTIVITY(%) 수식
SESS_ACTIVITY(%) = (TIME_SINCE_LAST_WAIT_MICRO /

                           (WAIT_TIME_MICRO + TIME_SINCE_LAST_WAIT_MICRO)) * 100


SESS_ACTIVITY(%)가 높을수록 세션 활동이 원활히 진행된다는 것을 의미합니다. 다시 말해 대기 시간 대비 CPU 사용 시간의 비율이 높다는 것을 의미합니다. 그럼 실제 부하를 유발시켜 해당 칼럼을 이용한 모니터링의 효율성을 확인해보도록 하겠습니다.




4. db file sequential read 대기이벤트 모니터링 예제


-- 비효율적인 인덱스 스캔을 수행하는 SQL 수행 
SCOTT@OOW1:1> declare
v1 number;
begin
 for i in 1..100000 loop
    execute immediate 'alter system flush buffer_cache';
    select /*+ index(a) */ count(*)  into v1 from big_t a where c1 > ' ';
 end loop;
end;
/

SYS@OOW1:1>@mon_1_sess 183 
                                                                                               TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME   LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs) (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- -----------
   183 WAITING  ACTIVE        51201 db file sequential read                             3.500         .00
SCOTT@OOW1:1> /

                                                                                               TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME   LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs) (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- -----------
   183 WAITING  ACTIVE        51350 db file sequential read                             4.730         .00
SCOTT@OOW1:1> /

                                                                                               TIME_SINCE
       WAIT                                                               SESS      WAIT_TIME   LAST_WAIT
   SID STATUS   STATUS         SEQ# EVENT                          ACTIVITY(%)    (millisecs) (millisecs)
------ -------- -------- ---------- ------------------------------ ----------- -------------- -----------
   183 ON_CPU   ACTIVE        51519 db file sequential read               63.5          2.120        3.68
   
.. 이하 생략
분석결과
싱글 블록 IO에 대한 대기 시간은 대부분 5 밀리세컨 이내이므로 디스크 IO 속도는 양호합니다. 그리고 ON_CPU 상태인 경우를 보면 대기 시간 대비 CPU 사용 시간 비율이 높은 것을 알 수 있습니다.




모니터링 스크립트

set feedback off
set verify   off
set pages 1000

col sid           for 99999
col wait_status   for a8 heading 'WAIT|STATUS'
col event         for a30
col sess_activity for 999.9 heading 'SESS|ACTIVITY(%)'
col wait_time     for 9,999,999.999 heading 'WAIT_TIME|(millisecs)'
col time_since_last_wait for 999.99 heading 'TIME_SINCE|LAST_WAIT|(millisecs)'

define __SID=&1

SELECT
     a.sid ,
     decode(a.wait_time,0,'WAITING','ON_CPU') wait_status ,
     a.status,
     a.seq#,
     a.event ,
     case
       when a.wait_time=0 then null
       else ((a.time_since_last_wait_micro)/(a.time_since_last_wait_micro+a.wait_time_micro))*100
     end sess_activity,
     round(a.wait_time_micro/1000,2) wait_time,
     round(a.time_since_last_wait_micro/1000,2) time_since_last_wait
FROM  v$session a
WHERE a.sid in (&__SID);


저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

1. LAST_CALL_ET 및 SQL_EXEC_START 칼럼 개요


V$SESSION 뷰의 LAST_CALL_ET (Last Call Elapsed Time) 칼럼은 이름에서도 알 수 있듯이 마지막 콜을 수행한 후, 현재시점까지의 경과 시간을 제공합니다. 따라서 세션 상태가 'ACTIVE' 라면 LAST_CALL_ET 칼럼에서 제공하는 수치는 최근에 수행한 SQL의 수행 시간이며, 세션 상태가 'INACTIVE'라면 IDLE 상태가 지속된 시간을 의미합니다. 따라서 현재 세션이 수행하는 SQL의 응답시간을 확인할 때나 INACTIVE 상태가 지속된 시간을 확인할 때 LAST_CALL_ET 칼럼은 매우 유용합니다.


하지만 LAST_CALL_ET 칼럼은 한가지 문제점이 있습니다. 해당 칼럼 값은 'MAIN CURSOR' 기준으로 작동되므로 프로시저 내에서 수행되는 개별 SQL의 수행 시간을 파악하는 것이 불가능합니다. 즉, 프로시저 (MAIN CURSOR) 내의 개별 SQL (CHILID CURSOR)의 수행시간을 확인할 수 없다는 단점이 있었습니다.


오라클은 이러한 한계점을 보완하기 위해 11g 부터 SQL_EXEC_START 칼럼을 제공합니다. SQL_EXEC_START 칼럼은 'MAIN CURSOR' 기준이 아닌, 매 SQL 수행 시작 시간을 제공하므로 프로시저 내에서 수행되는 개별 SQL의 수행 시간을 확인할 수 있습니다. 그림-1을 보면서 파악해보도록 하겠습니다.



2. 간단한 예제 수행 결과 비교


그림-1. LAST_CALL_ET 칼럼 및 SQL_EXEC_START 칼럼 비교



표-1. 비교표

 구분

 LAST_CALL_ET

 (SYSDATE-SQL_EXEC_START)*86400

 프로시저인 경우

 Procedure 수행 시작부터 현재까지의 경과 시간을 제공

 Procedure 내의 개별 쿼리에 대한 경과 시간을 제공

 단순 SQL인 경우

 SQL 수행 시작부터 현재까지의 경과 시간을 제공 

 좌동  

 INACTIVE 상태인 경우

 IDLE 상태가 지속된 시간을 제공

 NULL


3. 테스트 방법


3-1. 프로시저 생성

create or replace procedure proc_call_time_test
is
v_cnt1 number;
v_cnt2 number;
begin
    for i in 1..1000 loop
           for j in 1..1000 loop
              select count(*) into v_cnt1 from t1;
                  select count(*) into v_cnt2 from t2;
           end loop;
        end loop;
end;
/


3-2. 모니터링 쿼리 작성

set serveroutput on
set verify off
define __SID=&1;

begin
print_table('SELECT a.sid ,
       b.value exec_cnt ,
       a.last_call_et ,
       ( sysdate- a.sql_exec_start ) *86400 sql_exec_time ,
       SUBSTR( d.sql_text , 1 , 100 ) sql_text,
       d.program_id ,
       d.program_line#
FROM   v$session a ,
       v$sesstat b ,
       v$statname c ,
       v$sql d
WHERE  a.sid=&__SID
AND    a.sid=b.sid
AND    b.statistic#=c.statistic#
AND    c.name=''execute count''
AND    a.sql_id=d.sql_id
AND    a.sql_child_number=d.child_number');
end;
/


3-3. 모니터링 결과 확인

SCOTT@OOW1:1> @mon_1_sess_ela 214

SID                           : 214
EXEC_CNT                      : 429
LAST_CALL_ET                  : 37
SQL_EXEC_TIME                 : 4 ------------> 해당 SQL의 수행 시간은 4초임을 알 수 있음
SQL_TEXT                      : SELECT COUNT(*) FROM T1
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 8
-----------------

PL/SQL procedure successfully completed.

SCOTT@OOW1:1> @mon_1_sess_ela 214
SID                           : 214
EXEC_CNT                      : 430
LAST_CALL_ET                  : 38
SQL_EXEC_TIME                 : 1  -------------> 새로운 SQL 수행 시점에 값이 재 설정됨
SQL_TEXT                      : SELECT COUNT(*) FROM T2
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 9
-----------------

PL/SQL procedure successfully completed.

SCOTT@OOW1:1> @mon_1_sess_ela 214
SID                           : 214
EXEC_CNT                      : 431
LAST_CALL_ET                  : 39
SQL_EXEC_TIME                 : 1  ------------> 새로운 SQL 수행 시점에 값이 재 설정됨
SQL_TEXT                      : SELECT COUNT(*) FROM T1
PROGRAM_ID                    : 95252
PROGRAM_LINE#                 : 8




저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

이번 시간에는 시스템 레벨의 모니터링에 유용한 3개의 뷰를 이용해서 작성한 모니터링 스크립트를 소개합니다. (꼬박 하루동안 이것만  :))  3개의 뷰는 V$OSSTAT, V$SYS_TIME_MODELV$SYSTEM_EVENT 이며 뷰들의 용도는 다음과 같습니다.

  • V$OSSTAT : OS CPU, Run-Queue, Memory, Swap 등의 정보를 제공하기 위해 사용합니다. 
  • V$SYS_TIME_MODEL 
    1. CPU(%)를 DB CPU(%)과 NON DB CPU(%)로 구분해서 제공하기 위해 사용합니다. 또한 DB CPU(%)는 Foreground CPU(%) 와 Background CPU(%)로 구분합니다. (이를 위해 V$OSSTAT 뷰의 일부 데이터를 이용합니다)
    2. V$SYSTEM_EVENT 뷰와 조인해서 DB CPU, DB Elapsed Time, Wait Class, Wait Event 발생 현황을 트리 구조로 제공합니다.


1. 화면 출력 결과


스크립트 수행 결과는 크게 3부분으로 구분됩니다. (그림-1 참조)

  • OS Info 영역
  • DB CPU(%) 및 NON DB CPU(%) 영역
  • 응답시간 분석 트리 영역
그림-1. 수행 결과 예시 




2. OS Info 영역 설명


OS Info 영역은 V$OSSTAT 뷰의 정보를 이용합니다. 일반적으로 OS 정보를 모니터링할 때는 Top과 같은 시스템 유틸리티를 사용하는 것이 일반적이고 가장 편리한 방법입니다. 하지만 V$OSSTAT 뷰를 이용해서 OS 정보를 모니터링하는 것은 OS 유틸리티 대비 몇가지 장점을 제공합니다.

  1. 다른 뷰들과 조인해서 유용한 데이터를 추출하기가 용이합니다.
  2. 제품 개발 시에 OS API나 시스템 유틸리티 대용으로 사용할 수 있습니다.


2-1. 칼럼 설명


  칼럼 명

 설명  

 NUM_CPUS

 V$OSSTAT 뷰의 NUM_CPUS 칼럼 값

 RUN-QUEUE

 V$OSSTAT 뷰의 LOAD 칼럼 값

 TOTAL_CPU

 V$OSSTAT 뷰의 BUSY_TIME delta 값을 계산한 후 백분율(%) 데이터 제공

 USER_CPU

 V$OSSTAT 뷰의 USER_TIME delta 값을 계산한 후 백분율(%) 데이터 제공

 SYS_CPU

 V$OSSTAT 뷰의 SYS_TIME delta 값을 계산한 후 백분율(%) 데이터 제공

 IOWAIT_CPU

 V$OSSTAT 뷰의 IOWAIT_TIME delta 값을 계산한 후 백분율(%) 데이터 제공

 NICE_CPU

 V$OSSTAT 뷰의 NICE_TIME 값을 계산한 후 백분율(%) 데이터 제공

 TOTAL_MEM

 V$OSSTAT 뷰의 PHYSICAL_MEMORY_BYTES 칼럼 값을 Gb 단위로 제공

 FREE_MEM

 V$OSSTAT 뷰의 FREE_MEMORY_BYTES 칼럼 값을 Gb 단위로 제공

 MEM_USAGE

 (PHYSICAL_MEMORY_BYTES-FREE_MEMORY_BYTES)

 / PHYSICAL_MEMORY_BYTES*100 값 제공

 FREE_SWAP

 V$OSSTAT 뷰의 SWAP_FREE_BYTES 칼럼 값을 Mb 단위로 제공



2-2. 소스 설명
CPU(%)란 CPU가 사용한 시간을 이용해서 만든 비율(%) 지표입니다. 따라서 V$OSSTAT 뷰에서 제공하는 TIME 유형의 데이터들을 이용해서 사용률(%) 지표를 만들 수 있습니다. 이를 위해 2개의 SNAP (mon_sys_begin, mon_sys_end Global Temporary Table 이용) 데이터를 입력한 후, V$OSSTAT 뷰의 TIME 데이터들의 delta 값을 인터벌 및 NUM_CPUS로 나눕니다. 참고로 V$OSSTAT 뷰의 TIME 유형의 데이터는 1/100 (Centiseconds) 단위입니다.

SELECT
       num_cpus ,
       ROUND( load,1)                                          "RUN-QUEUE"     ,
       ROUND( busy_time_diff/interval/num_cpus , 1 )||'%'      "TOTAL_CPU"     ,
       ROUND( user_time_diff/interval/num_cpus , 1 )||'%'      "USER_CPU"      ,
       ROUND( sys_time_diff/interval/num_cpus , 1 )||'%'       "SYS_CPU"       ,
       ROUND( iowait_time_diff/interval/num_cpus , 1 )||'%'    "IOWAIT_CPU"    ,
       ROUND( nice_time_diff/interval/num_cpus , 1 )||'%'      "NICE_CPU"      ,
       ROUND( idle_time_diff/interval/num_cpus , 1 )||'%'      "IDLE_CPU"      ,
       ROUND( total_mem/1024/1024/1024 , 1 )||'(Gb)'           "TOTAL_MEM"     ,
       ROUND( free_mem/1024/1024/1024 , 1 )||'(Gb)'            "FREE_MEM"      ,
       ROUND(( total_mem- free_mem ) /total_mem*100 , 1 )||'%' "MEM_USAGE"     ,
       ROUND( free_swap/1024/1024/1024 , 1 )||'(Mb)'           "FREE_SWAP"     ,
       ROUND( interval,1)||'(Sec)'                             "INTERVAL"
FROM   (
        SELECT MAX( decode( b.name , 'NUM_CPUS' ,    b.value ) ) num_cpus ,
               MAX( decode( b.name , 'BUSY_TIME' ,   b.value - a.value ) ) busy_time_diff   ,
               MAX( decode( b.name , 'USER_TIME' ,   b.value - a.value ) ) user_time_diff   ,
               MAX( decode( b.name , 'SYS_TIME' ,    b.value - a.value ) ) sys_time_diff    ,
               MAX( decode( b.name , 'IOWAIT_TIME' , b.value - a.value ) ) iowait_time_diff ,
               MAX( decode( b.name , 'NICE_TIME' ,   b.value - a.value ) ) nice_time_diff   ,
               MAX( decode( b.name , 'IDLE_TIME' ,   b.value - a.value ) ) idle_time_diff   ,
               MAX( decode( b.name , 'LOAD' ,        b.value ) ) load ,
               MAX( decode( b.name , 'PHYSICAL_MEMORY_BYTES' , b.value ) ) total_mem ,
               MAX( decode( b.name , 'FREE_MEMORY_BYTES' ,     b.value ) ) free_mem  ,
               MAX( decode( b.name , 'SWAP_FREE_BYTES' ,       b.value ) ) free_swap ,
               MAX( TO_NUMBER( SUBSTR( TO_CHAR( b.log_time- a.log_time , 'SSFF' ) , 18 , 6 ) ) ) interval
        FROM   mon_sys_begin a ,
               mon_sys_end b
        WHERE  a.flag='[OSSTAT]'
        and    a.name=b.name
       );  




3. DB CPU(%) and NON DB CPU(%) 영역 설명


OS 레벨의 CPU(%)를 DB가 사용하는 CPU(%)와 NON DB가 사용하는 CPU(%)로 구분해서 제공합니다.


3-1. 칼럼 설명


  칼럼 명

 설명  

 TOTAL_CPU

 V$OSSTAT 뷰의 BUSY_TIME delta 값을 계산한 후 백분율(%) 데이터 제공

 DB_FG_CPU

 V$SYS_TIME_MODEL 뷰의 DB time delta 값을 계산한 후 백분율(%) 데이터 제공

 DB_BG_CPU

 V$SYS_TIME_MODEL 뷰의 background cpu time delta 값을 계산한 후 백분율(%)

 데이터 제공

 NON_DB_CPU

 TOTAL_CPU - (DB time + background cpu time) 값을 계산 한 후 백분율(%) 데이터 제공


 
3-2. 소스 설명
전체 CPU 사용률(%) 데이터는 V$OSSTAT 뷰를 이용하고, DB CPU 사용률(%) 데이터는 V$SYS_TIME_MODEL 뷰를 이용합니다. 참고로 V$SYS_TIME_MODEL 뷰의 단위는 1/1000000 (microseconds) 이므로 '10000'으로 더 나눠서 백분율을 구합니다. 

SELECT
       ROUND( busy_time_diff/interval/num_cpus , 1 ) ||'%'            "TOTAL_CPU" ,
       ROUND( db_fg_cpu_time_diff/interval/num_cpus/10000 , 1 ) ||'%' "DB_FG_CPU" ,
       ROUND( db_bg_cpu_time_diff/interval/num_cpus/10000 , 1 ) ||'%' "DB_BG_CPU" ,
       ROUND((( busy_time_diff*10000 ) - db_fg_cpu_time_diff- db_bg_cpu_time_diff )
                                 /interval/num_cpus/10000 , 1 ) ||'%' "NON_DB_CPU"
FROM   (
        SELECT MAX( decode( b.name , 'NUM_CPUS' ,  b.value ) ) num_cpus ,
               MAX( decode( b.name , 'BUSY_TIME' , b.value - a.value ) ) busy_time_diff ,
               MAX( decode( b.name , 'DB CPU' ,    b.value - a.value ) ) db_fg_cpu_time_diff ,
               MAX( decode( b.name , 'background cpu time' , b.value - a.value ) ) db_bg_cpu_time_diff ,
               MAX( TO_NUMBER( SUBSTR( TO_CHAR( b.log_time- a.log_time , 'SSFF' ) , 18 , 6 ) ) ) interval
        FROM   mon_sys_begin a ,
               mon_sys_end b
        WHERE  a.name IN ( 'NUM_CPUS' , 'BUSY_TIME' , 'DB CPU' , 'background cpu time')
        AND    a.name=b.name
       ) ;




4. 응답시간 분석 트리 영역 설명


시스템 레벨의 '전체 Elapsed Time'을 DB Time (Foreground 프로세스가 사용한 elapsed time)과 background elapsed time (Background 프로세스가 사용한 elapsed time)으로 구분하고, DB time을 DB CPU 및 WAIT CLASS, WAIT EVENT로 세분화해서 모니터링할 수 있다면, 현재 발생하는 성능 문제가 어디서 발생하는지 매우 직관적으로 파악할 수 있습니다. V$SYS_TIME_MODEL 뷰는 DB Time, Elapsed Time과 관련한 유용한 데이터를 제공하며 V$SYSTEM_EVENT 뷰는 대기 이벤트에 대한 자세한 정보를 제공하므로, 이 두개의 뷰를 이용해서 '응답시간 분석 트리'를 만들 수 있습니다. 


4-1. 칼럼 및 수행 결과 설명


 칼럼 명

 설명  

 NAME

 수행 결과를 계층 구조로 제공하며 비중도(%)를 표시합니다. 

 PCT_GRAPH

 10%당 1개의 '*'을 표시합니다.

 DIFF_TIME(Sec)

 2개의 스냅 구간 사이에 해당 지표가 사용한 시간을 표시합니다.


수행 결과를 분석할 때 몇 가지 유의해야할 사항이 있습니다.

  • TOTAL elapsed time = DB time + background elapsed time 이므로 두개의 비중도(%)를 합하면 100%가 됩니다.
  • DB time = DB CPU + WAIT TIME 입니다. 예제 데이터를 보면 DB time(90%)은 DB CPU (5%) + Concurrency Class (2%) + Configuration Class (1%) + Other Class (83%)와 유사한 것을 알 수 있습니다. 그리고 Other 대기 클래스 중에서 enq : SV - contention 대기 이벤트가 가장 문제인 것을 직관적으로 파악할 수 있습니다.
  • DB Time은 Foreground 프로세스가 수행한 elapsed time의 합이며 elapsed time 기준으로 세분화한 데이터들을 보면 지표 명 내에 'elapsed time'이 존재합니다. 예제의 데이터를 보면 DB time(90%)는 PL/SQL execution elapsed time(1%) + sql execute elapsed time(90%)과 유사한 것을 알 수 있습니다.


4-2. 소스 설명
비율(%) 계산을 위해서는 전체 응답시간을 알아야하므로 WITH 절을 이용해서 해당 값을 구해 둡니다. 그리고 두 개의 스냅 데이터를 이용해서 delta 값들을 계산하고, 트리 구성을 위해 자신의 'parent'를 설정합니다.

WITH v_total_ela AS (
                    SELECT SUM( b.value- a.value ) VALUE
                    FROM   mon_sys_begin a ,
                           mon_sys_end b
                    WHERE  a.name IN ( 'DB time' , 'background elapsed time' )
                    AND    a.name=b.name
     )
SELECT
     LPAD( ' ' , 2*( level- 1 ) )||name||' ('||ROUND( diff_ela/total_ela*100 , 0 )||'%)' "NAME",
     LPAD( ' ' , ROUND( diff_ela/total_ela*10,0), '*') "PCT_GRAPH",
     ROUND( diff_ela/1000000 , 3 ) "DIFF_TIME(Sec)"
FROM (
      SELECT b.name ,
      CASE
          WHEN b.name='DB time'                         THEN 'TOTAL elapsed time'
          WHEN b.name='background elapsed time'         THEN 'TOTAL elapsed time'
          WHEN b.name='background cpu time'             THEN 'background elapsed time'
          WHEN b.name LIKE 'RMAN cpu time%'             THEN 'background cpu time'
          WHEN b.name='DB CPU'                          THEN 'DB time'
          WHEN b.name='connection management call elapsed time'           THEN 'DB time'
          WHEN b.name='sequence load elapsed time'      THEN 'DB time'
          WHEN b.name='sql execute elapsed time'        THEN 'DB time'
          WHEN b.name='parse time elapsed'              THEN 'DB time'
          WHEN b.name='hard parse elapsed time'         THEN 'parse time elapsed'
          WHEN b.name='hard parse (sharing criteria) elapsed time'        THEN 'hard parse elapsed time'
          WHEN b.name='hard parse (bind mismatch) elapsed time'           THEN 'hard parse (sharing criteria) elapsed time'
          WHEN b.name='failed parse elapsed time'       THEN 'parse time elapsed'
          WHEN b.name='failed parse (out of shared memory) elapsed time'  THEN 'failed parse elapsed time'
          WHEN b.name='PL/SQL execution elapsed time'   THEN 'DB time'
          WHEN b.name='inbound PL/SQL rpc elapsed time' THEN 'DB time'
          WHEN b.name='PL/SQL compilation elapsed time' THEN 'DB time'
          WHEN b.name='Java execution elapsed time'     THEN 'DB time'
          WHEN b.name='repeated bind elapsed time'      THEN 'DB time'
      END parent ,
             b.value- a.value diff_ela ,
             c.value total_ela
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag='[TIME_MODEL]'
      AND    a.name=b.name
      AND    b.value >0
      UNION ALL
      SELECT '[WAIT] '||b.name,
             'DB time' ,
             b.value- a.value diff_ela,
             c.value
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag='[WAIT_CLASS]'
      AND    a.name=b.name
      AND    round((b.value-a.value)/1000000,1) > 0
      UNION ALL
      SELECT '[EVENT] '||b.name,
             '[WAIT] '||substr(b.flag, 14),
             b.value- a.value diff_ela,
             c.value
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag like '[WAIT_EVENT]%'
      AND    a.name=b.name
      AND    round((b.value-a.value)/1000000,1) > 0
      UNION ALL
      SELECT 'TOTAL elapsed time',
              NULL,
              value,
              value
      FROM    v_total_ela
     ) START WITH parent IS NULL
CONNECT BY PRIOR name=parent
AND  diff_ela > 0
AND  ROUND( diff_ela/total_ela*100 , 0 ) > 0;




5. 수행 방법 및 스크립트 소스



5.1 수행 방법

SQLPLUS> @mon_sys  

-- Global Temporary 테이블 생성 스크립트
drop table mon_sys_begin;

create global temporary table mon_sys_begin
(
  log_time   timestamp,
  flag       varchar2(30),
  name       varchar2(64),
  value      number
) on commit delete rows;;

drop table mon_sys_end;

create global temporary table mon_sys_end
(
  log_time   timestamp,
  flag       varchar2(30),
  name       varchar2(64),
  value      number
) on commit delete rows;;


5.2 모니터링 스크립트 소스 (mon_sys.sql)

!clear

set feedback off
set verify   off
set pages 1000

define __SLEEP_TIME=&1;

INSERT
INTO   mon_sys_begin
SELECT systimestamp ,
       '[OSSTAT]' ,
       stat_name ,
       value
FROM   v$osstat
UNION  ALL
SELECT systimestamp ,
       '[TIME_MODEL]' ,
       stat_name ,
       value
FROM   v$sys_time_model
UNION  ALL
SELECT systimestamp ,
       '[WAIT_CLASS]' ,
       wait_class ,
       SUM( time_waited_micro ) VALUE
FROM   v$system_event
WHERE  wait_class NOT IN ( 'Idle' )
GROUP BY wait_class
UNION ALL
SELECT systimestamp ,
       '[WAIT_EVENT]'||wait_class,
       event ,
       time_waited_micro  VALUE
FROM   v$system_event
WHERE  wait_class NOT IN ( 'Idle' );

exec sys.dbms_lock.sleep(&__SLEEP_TIME);

INSERT
INTO   mon_sys_end
SELECT systimestamp ,
       '[OSSTAT]' ,
       stat_name ,
       value
FROM   v$osstat
UNION  ALL
SELECT systimestamp ,
       '[TIME_MODEL]' ,
       stat_name ,
       value
FROM   v$sys_time_model
UNION  ALL
SELECT systimestamp ,
       '[WAIT_CLASS]' ,
       wait_class ,
       SUM( time_waited_micro ) VALUE
FROM   v$system_event
WHERE  wait_class NOT IN ( 'Idle' )
GROUP  BY wait_class
UNION ALL
SELECT systimestamp ,
       '[WAIT_EVENT] '||wait_class,
       event,
       time_waited_micro  VALUE
FROM   v$system_event
WHERE  wait_class NOT IN ( 'Idle' );

col num_cpus      for 999
col "RUN-QUEUE"   for 999.9
col "TOTAL_CPU"   for a9
col "USER_CPU"    for a8
col "SYS_CPU"     for a7
col "IOWAIT_CPU"  for a10
col "NICE_CPU"    for a8
col "IDLE_CPU"    for a8
col "TOTAL_MEM"   for a9
col "FREE_MEM"    for a8
col "MEM_USAGE"   for a9
col "FREE_SWAP"   for a9
col "INTERVAL"    for a8

TTITLE LEFT '[---------------------------------CPU ------------------------------------][------------MEMORY---------][--SWAP--]'

SELECT
       num_cpus ,
       ROUND( load,1)                                          "RUN-QUEUE"     ,
       ROUND( busy_time_diff/interval/num_cpus , 1 )||'%'      "TOTAL_CPU"     ,
       ROUND( user_time_diff/interval/num_cpus , 1 )||'%'      "USER_CPU"      ,
       ROUND( sys_time_diff/interval/num_cpus , 1 )||'%'       "SYS_CPU"       ,
       ROUND( iowait_time_diff/interval/num_cpus , 1 )||'%'    "IOWAIT_CPU"    ,
       ROUND( nice_time_diff/interval/num_cpus , 1 )||'%'      "NICE_CPU"      ,
       ROUND( idle_time_diff/interval/num_cpus , 1 )||'%'      "IDLE_CPU"      ,
       ROUND( total_mem/1024/1024/1024 , 1 )||'(Gb)'           "TOTAL_MEM"     ,
       ROUND( free_mem/1024/1024/1024 , 1 )||'(Gb)'            "FREE_MEM"      ,
       ROUND(( total_mem- free_mem ) /total_mem*100 , 1 )||'%' "MEM_USAGE"     ,
       ROUND( free_swap/1024/1024/1024 , 1 )||'(Mb)'           "FREE_SWAP"     ,
       ROUND( interval,1)||'(Sec)'                             "INTERVAL"
FROM   (
        SELECT MAX( decode( b.name , 'NUM_CPUS' ,    b.value ) ) num_cpus ,
               MAX( decode( b.name , 'BUSY_TIME' ,   b.value - a.value ) ) busy_time_diff   ,
               MAX( decode( b.name , 'USER_TIME' ,   b.value - a.value ) ) user_time_diff   ,
               MAX( decode( b.name , 'SYS_TIME' ,    b.value - a.value ) ) sys_time_diff    ,
               MAX( decode( b.name , 'IOWAIT_TIME' , b.value - a.value ) ) iowait_time_diff ,
               MAX( decode( b.name , 'NICE_TIME' ,   b.value - a.value ) ) nice_time_diff   ,
               MAX( decode( b.name , 'IDLE_TIME' ,   b.value - a.value ) ) idle_time_diff   ,
               MAX( decode( b.name , 'LOAD' ,        b.value ) ) load ,
               MAX( decode( b.name , 'PHYSICAL_MEMORY_BYTES' , b.value ) ) total_mem ,
               MAX( decode( b.name , 'FREE_MEMORY_BYTES' ,     b.value ) ) free_mem  ,
               MAX( decode( b.name , 'SWAP_FREE_BYTES' ,       b.value ) ) free_swap ,
               MAX( TO_NUMBER( SUBSTR( TO_CHAR( b.log_time- a.log_time , 'SSFF' ) , 18 , 6 ) ) ) interval
        FROM   mon_sys_begin a ,
               mon_sys_end b
        WHERE  a.flag='[OSSTAT]'
        and    a.name=b.name
       );

TTITLE OFF

col "TOTAL_CPU_TIME"  for a14
col "DB_FG_CPU_TIME"  for a14
col "DB_BG_CPU_TIME"  for a14
col "TOTAL_CPU"       for a9
col "DB_FG_CPU"       for a9
col "DB_BG_CPU"       for a9
col "NON_DB_CPU"      for a10


SELECT
       ROUND( busy_time_diff/interval/num_cpus , 1 ) ||'%'            "TOTAL_CPU" ,
       ROUND( db_fg_cpu_time_diff/interval/num_cpus/10000 , 1 ) ||'%' "DB_FG_CPU" ,
       ROUND( db_bg_cpu_time_diff/interval/num_cpus/10000 , 1 ) ||'%' "DB_BG_CPU" ,
       ROUND((( busy_time_diff*10000 ) - db_fg_cpu_time_diff- db_bg_cpu_time_diff )
                                 /interval/num_cpus/10000 , 1 ) ||'%' "NON_DB_CPU"
FROM   (
        SELECT MAX( decode( b.name , 'NUM_CPUS' ,  b.value ) ) num_cpus ,
               MAX( decode( b.name , 'BUSY_TIME' , b.value - a.value ) ) busy_time_diff ,
               MAX( decode( b.name , 'DB CPU' ,    b.value - a.value ) ) db_fg_cpu_time_diff ,
               MAX( decode( b.name , 'background cpu time' , b.value - a.value ) ) db_bg_cpu_time_diff ,
               MAX( TO_NUMBER( SUBSTR( TO_CHAR( b.log_time- a.log_time , 'SSFF' ) , 18 , 6 ) ) ) interval
        FROM   mon_sys_begin a ,
               mon_sys_end b
        WHERE  a.name IN ( 'NUM_CPUS' , 'BUSY_TIME' , 'DB CPU' , 'background cpu time')
        AND    a.name=b.name
       ) ;


col "NAME"           for a80
col "DIFF_TIME(Sec)" for 99999.99
col "PCT(%)"         for a15
col "PCT_GRAPH"      for a21



WITH v_total_ela AS (
                    SELECT SUM( b.value- a.value ) VALUE
                    FROM   mon_sys_begin a ,
                           mon_sys_end b
                    WHERE  a.name IN ( 'DB time' , 'background elapsed time' )
                    AND    a.name=b.name
     )
SELECT
     LPAD( ' ' , 2*( level- 1 ) )||name||' ('||ROUND( diff_ela/total_ela*100 , 0 )||'%)' "NAME",
     LPAD( ' ' , ROUND( diff_ela/total_ela*10,0), '*') "PCT_GRAPH",
     ROUND( diff_ela/1000000 , 3 ) "DIFF_TIME(Sec)"
FROM (
      SELECT b.name ,
      CASE
          WHEN b.name='DB time'                         THEN 'TOTAL elapsed time'
          WHEN b.name='background elapsed time'         THEN 'TOTAL elapsed time'
          WHEN b.name='background cpu time'             THEN 'background elapsed time'
          WHEN b.name LIKE 'RMAN cpu time%'             THEN 'background cpu time'
          WHEN b.name='DB CPU'                          THEN 'DB time'
          WHEN b.name='connection management call elapsed time'           THEN 'DB time'
          WHEN b.name='sequence load elapsed time'      THEN 'DB time'
          WHEN b.name='sql execute elapsed time'        THEN 'DB time'
          WHEN b.name='parse time elapsed'              THEN 'DB time'
          WHEN b.name='hard parse elapsed time'         THEN 'parse time elapsed'
          WHEN b.name='hard parse (sharing criteria) elapsed time'        THEN 'hard parse elapsed time'
          WHEN b.name='hard parse (bind mismatch) elapsed time'           THEN 'hard parse (sharing criteria) elapsed time'
          WHEN b.name='failed parse elapsed time'       THEN 'parse time elapsed'
          WHEN b.name='failed parse (out of shared memory) elapsed time'  THEN 'failed parse elapsed time'
          WHEN b.name='PL/SQL execution elapsed time'   THEN 'DB time'
          WHEN b.name='inbound PL/SQL rpc elapsed time' THEN 'DB time'
          WHEN b.name='PL/SQL compilation elapsed time' THEN 'DB time'
          WHEN b.name='Java execution elapsed time'     THEN 'DB time'
          WHEN b.name='repeated bind elapsed time'      THEN 'DB time'
      END parent ,
             b.value- a.value diff_ela ,
             c.value total_ela
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag='[TIME_MODEL]'
      AND    a.name=b.name
      AND    b.value >0
      UNION ALL
      SELECT '[WAIT] '||b.name,
             'DB time' ,
             b.value- a.value diff_ela,
             c.value
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag='[WAIT_CLASS]'
      AND    a.name=b.name
      AND    round((b.value-a.value)/1000000,1) > 0
      UNION ALL
      SELECT '[EVENT] '||b.name,
             '[WAIT] '||substr(b.flag, 14),
             b.value- a.value diff_ela,
             c.value
      FROM   mon_sys_begin a ,
             mon_sys_end b ,
             v_total_ela c
      WHERE  a.flag like '[WAIT_EVENT]%'
      AND    a.name=b.name
      AND    round((b.value-a.value)/1000000,1) > 0
      UNION ALL
      SELECT 'TOTAL elapsed time',
              NULL,
              value,
              value
      FROM    v_total_ela
     ) START WITH parent IS NULL
CONNECT BY PRIOR name=parent
AND  diff_ela > 0
AND  ROUND( diff_ela/total_ela*100 , 0 ) > 0;

commit;


5.3 수행 결과 예시

[---------------------------------CPU ------------------------------------][------------MEMORY---------][--SWAP--]
NUM_CPUS RUN-QUEUE TOTAL_CPU USER_CPU SYS_CPU IOWAIT_CPU NICE_CPU IDLE_CPU TOTAL_MEM FREE_MEM MEM_USAGE FREE_SWAP INTERVAL
-------- --------- --------- -------- ------- ---------- -------- -------- --------- -------- --------- --------- --------
       1       3.1 97.3%     5.6%     91.3%   0%         0%       .5%      2.3(Gb)   .1(Gb)   97.4%     2(Mb)     2.2(Sec)

TOTAL_CPU DB_FG_CPU DB_BG_CPU NON_DB_CPU
--------- --------- --------- ----------
97.3%     54.1%     17.1%     26%

NAME                                                                             PCT_GRATH              DIFF_TIME(Sec)
-------------------------------------------------------------------------------- --------------------- --------------
TOTAL elapsed time (100%)                                                        *********                      22.38
  DB time (90%)                                                                  ********                       20.21
    DB CPU (5%)                                                                                                  1.17
    PL/SQL execution elapsed time (1%)                                                                            .19
    [WAIT] Concurrency (2%)                                                                                       .47
      [EVENT] buffer busy waits (1%)                                                                              .14
      [EVENT] enq: TX - index contention (1%)                                                                     .33
    [WAIT] Configuration (1%)                                                                                     .23
      [EVENT] log file switch completion (1%)                                                                     .23
    [WAIT] Other (83%)                                                           *******                        18.64
      [EVENT] enq: SV -  contention (80%)                                        *******                        18.01
      [EVENT] latch: ges resource hash list (2%)                                                                  .35
    sql execute elapsed time (90%)                                               ********                       20.18
  background elapsed time (10%)                                                                                  2.17
    background cpu time (2%)                                                                                      .37


글을 마치며


다음 시간에는 V$SESS_TIME_MODEL 뷰를 이용한 세션 레벨 모니터링 스크립트를 작성할 예정입니다. 이러한 모니터링 스크립트는 작성 그 자체도 중요하겠지만 해당 뷰에서 제공하는 데이터의 성격을 명확하게 이해하는 것 또한 중요합니다. 따라서, 해당 스크립트의 내용을 잘 이해한 후 각자의 모니터링 환경에 적합하게 적절히 수정해서 사용하시면 좋을것 같습니다.

저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

운영 시스템을 모니터링할때 중요한 부분 중의 하나는 락 (enqueue) 또는 Library cache pin/lock등의 마지막 홀더 세션을 빠르게 추적함으로써 Root Cause를 정확히 파악하는 것입니다. 이를 위해 전통적으로 사용되었던 방법은 락 (enqueue)의 경우에는 V$LOCK 뷰를 이용하고, library cache pin과 library cache lock은 각각 X$KGLPNX$KGLLK fixed 테이블을 이용해서  홀더 세션을 추적하는 것이었습니다. 오라클은 11g 부터는 이와 더불어 V$WAIT_CHAINS 뷰를 제공합니다.



1. V$WAIT_CHAINS 뷰의 특징


V$WAIT_CHAINS 뷰는 이름에서도 알 수 있듯이 대기 체인들의 목록을 제공합니다. 해당 뷰의 몇 가지 특성은 다음과 같습니다.

  • RAC 환경에서 별도로 GV$WAIT_CHAINS 뷰를 제공하지 않습니다. 즉,  V$WAIT_CHAINS에 모든 인스턴스의 체인 목록을 저장합니다.
  • 이러한 이유로 인해, RAC 환경에서 해당 뷰를 조회하면 GV$를 조회하는것과 동일하게 각 노드의 PQ 슬레이스 프로세스가 쿼리를 수행합니다.
  • 현재 오픈된 대기 체인들의 관계를 아주 쉽게 파악할 수 있습니다. (장점)
  • 적시성이 떨어집니다 (단점) 환경마다 차이가 있겠지만, 제 테스트 환경에서는 대기 세션이 발생한지 10~15초 이후에 해당 뷰에 등록됩니다.
  • 이것을 통해 미루어 짐작할 수 있는 부분은 대기 세션이 직접 해당 뷰 (X$KSDHNG_CHAINS Fiexed 테이블)에 등록하는 방식이 아니라, 특정 백그라운드 프로세스가 주기적으로 대기 체인을 확인한 후에 해당 뷰에 등록하는 방식을 사용하는 것 같습니다. 참고로 V$SESSION 뷰의 BLOCKING_SESSION 칼럼도 이와 동일하게 동작합니다.
  • 이러한 적시성의 한계로 인해, 일부 환경에서는 해당 뷰를 사용하기 힘들 수도 있습니다. 다만, 이러한 delay는 환경마다 차이가 있을수 있으므로 각자 환경에서 테스트해보면 좋을것 같습니다.  
Note
'ORADEBUG -G ALL HANGANALYZE 10' 명령어를 사용해본 분들을 'CHAINS'란 단어가 익숙할것입니다. V$WAIT_CHAINS 뷰는 HANGANALYZE와 동일한 정보를 아주 빠르게 제공함과 동시에 트레이스 파일 대비 높은 가독성을 제공합니다.



2. V$WAIT_CHAINS 뷰를 이용한 스크립트


V$WAIT_CHAINS 뷰 자체로도 충분한 정보를 제공하고 있습니다만, 프로그램/모듈 및 SQL 정보를 확인하려면 V$SESSION V$SQL 뷰와 조인을 해야합니다. 아래의 쿼리는 SQL*Plus 환경에서 180 라인에 맞춰서 작성하기 위해 일부 칼럼을 제외하거나 (P2, P3 제외) 칼럼의 길이를 짧게 조정한것이므로, 그리드가 제공되는 툴을 사용하는 경우에는 적절히 편집해서 사용하시면 됩니다.

set linesize 180
set pages 100

col inst_id  for  999
col sid      for  a8
col serial#  for  999999
col wait_secs  heading 'WAIT|_SECS' for 999999
col object_id  heading 'OBJECT|_ID' for 999999
col spid     for a7
col sql_text for a21
col event    for a30
col prog_mod for a10
col p1       for a28

WITH v_wait_chains AS (
                      SELECT
                             instance ,
                             LPAD( ' ' , 2*( lv-1 ) ) ||sid sid,
                             sess_serial# ,
                             osid spid,
                             wait_event_text event,
                             p1_text,
                             p1,
                             p2_text,
                             p2,
                             p3_text,
                             p3,
                             in_wait_secs ,
                             row_wait_obj#
                      FROM   (
                              SELECT a.* ,
                                     LEVEL lv
                              FROM   v$wait_chains a
                              START WITH blocker_is_valid = 'FALSE'
							  CONNECT BY PRIOR sid          = blocker_sid
                              AND        PRIOR sess_serial# = blocker_sess_serial#
                              AND        PRIOR instance     = blocker_instance
							  
                             )
                      WHERE  num_waiters > 0
                      OR     blocker_sid IS NOT NULL
     )
SELECT /*+ leading(a b c) use_nl(b c) */
     a.instance inst_id ,
     a.sid ,
     a.sess_serial# serial# ,
     a.in_wait_secs wait_secs ,
     nvl(b.module, b.program) prog_mod,
     a.spid ,
     SUBSTR( c.sql_text , 1 , 20 ) sql_text ,
     a.row_wait_obj# object_id,
     a.event ,
     a.p1_text||'=>'||a.p1 p1
FROM v_wait_chains a ,
     gv$session    b ,
     gv$sql        c
WHERE a.instance    = b.inst_id
AND  a.sid          = b.sid
AND  a.sess_serial# = b.serial#
AND  b.inst_id      = c.inst_id
AND  nvl(b.sql_id, b.prev_sql_id) = c.sql_id;

INST_ID SID      SERIAL#   _SECS PROG_MOD   SPID    SQL_TEXT                  _ID EVENT                          P1
------- -------- ------- ------- ---------- ------- --------------------- ------- ------------------------------ ----------------------------
      2 40          1837     707 SQL*Plus   20707   BEGIN pin_test; END;       -1 PL/SQL lock timer              duration=>0
      2   82        1903     705 SQL*Plus   20671   alter procedure pin_    20366 library cache pin              handle address=>1815917400
      1     45     58257     676 SQL*Plus   24571   BEGIN pin_test; END;       -1 library cache lock             handle address=>1738926912
      2 42         46140   15058 SQL*Plus   18716   update lock_test set    94662 SQL*Net message from client    driver id=>1650815232
      1   57       16358   15049 SQL*Plus   18648   update lock_test set    94662 enq: TX - row lock contention  name|mode=>1415053318
      3     49     52493   15046 SQL*Plus   25700   update lock_test set    94662 enq: TX - row lock contention  name|mode=>1415053318
      1 73         31456   15139 SQL*Plus   18488   update lock_test set    94662 SQL*Net message from client    driver id=>1650815232
      2   64       42726   15134 SQL*Plus   18652   update lock_test set    94662 enq: TX - row lock contention  name|mode=>1415053318
      3     80     49316   15129 SQL*Plus   25613   update lock_test set    94662 enq: TX - row lock contention  name|mode=>1415053318



저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

RAC 환경에서 Right-hand 인덱스는 인서트가 집중되는 시점에 대량의 gc buffer busy acquire gc buffer busy release 대기이벤트가 발생할 수 있는 문제점을 내포하고 있습니다. 이는 Right-hand 인덱스의 특성 상 마지막 리프 블록에 입력이 집중되기 때문입니다.


일반적으로, Right-hand 인덱스의 문제를 해결하기 위해 제시되는 방법은 Reverse Index 및 Global HASH Index 파티션입니다. 그리고 일반적으로 제시되는 방법은 아니지만 (모델링 및 AP의 변경이 필요하므로 특수한 경우에만 적용 가능) LIST 파티션을 이용한 입력 노드의 완벽한 분리입니다.


이번 시간에는 부하 테스트를 통해 이들 간의 성능을 비교하고 고려사항을 정리함으로써 gc buffer busy 관련 대기이벤트에 대한 적절한 해결 방안을 선택하는데 도움이 되고자 합니다.



1. 테스트 케이스 설명 및 테스트 환경 설정


테스트 환경: Oracle 12.1.0.2 64bit 3-노드

  • Case#1: 튜닝 적용 전
  • Case#2: Reverse Index 적용
  • Case#3: Global Hash Index Partition 적용 (해시 파티션 개수 8개)
  • Case#4: LIST 파티션을 이용한 입력 노드의 분리
-----------------------------------------------------------
--Case#1 환경 설정 
-----------------------------------------------------------
drop table t1 purge;
create table t1 
 (c1 number,
  dummy char(100));
 
create unique index t1_uk on t1(c1); 

drop sequence t1_seq;
create sequence t1_seq cache 10000 order;

-----------------------------------------------------------
--Case#2 환경 설정 
-----------------------------------------------------------
drop table t1 purge;
create table t1 
 (c1 number,
  dummy char(100));
 
create unique index t1_uk on t1(c1) reverse; 

drop sequence t1_seq;
create sequence t1_seq cache 10000 order;

-----------------------------------------------------------
--Case#3 환경 설정 
-----------------------------------------------------------
drop table t1 purge;
create table t1 
 (c1 number,
  dummy char(100));
 
create unique index t1_uk on t1(c1) global partition by hash(c1) partitions 8;

drop sequence t1_seq;
create sequence t1_seq cache 10000 order;

-----------------------------------------------------------
--Case#4 환경 설정 
-----------------------------------------------------------
drop table t1 purge;

create table t1 
 (
  inst_id number,
  c1 number,
  dummy char(100))
 partition by list(inst_id)
 (
  partition t1_inst1 values(1),
  partition t1_inst2 values(2),
  partition t1_inst3 values(3)
 );
 
create unique index t1_uk on t1(inst_id, c1) local;

drop sequence t1_seq;
create sequence t1_seq cache 10000 order;

-----------------------------------------------------------
--프로시저 (Case#1~3에서 사용)
-----------------------------------------------------------
create or replace procedure insert_t1 (LoopCnt number)
 is
 begin
     for i in 1..LoopCnt loop
      insert into t1 values(t1_seq.nextval, 'dummy');
     end loop;
 end;
/

-----------------------------------------------------------
--프로시저 (Case#4에서 사용) 
-----------------------------------------------------------
create or replace procedure insert_t1 (LoopCnt number)
 is
 v_inst_id number;
 begin
     select userenv('INSTANCE') into v_inst_id from dual;
     for i in 1..LoopCnt loop
       insert into t1 values(v_inst_id, t1_seq.nextval, 'dummy') ;
     end loop;
 end;
/

상기 프로시저를 각 노드마다 10개의 세션 (총 30개 세션)으로 동시에 수행한 후에 결과를 분석합니다.



2. 결과 분석


3개의 권고안 모두 gc buffer busy 관련 대기이벤트에 대한 튜닝이 가능한 것으로 확인됩니다. (그림-1~2 및 결과-1 참조) 테스트 환경에 따라서 수치 상의 큰 차이가 있을 수 있으나, gc buffer busy acquire/release와 같이 경합과 관련된 대기이벤트에 대한 튜닝 방안은 경합 위치를 최대한 분산시키는 것이라는 것을 알 수 있습니다.


그림-1. 테스트 케이스 별 CPU 및 대기 클래스 별 대기 시간 비교


그림-2. 테스트 케이스 별 CPU 및 대기 클래스 별 대기 시간 비교 (Other 클래스 제외)


Note
테스트를 위해 order 속성의 시퀀스를 이용함에 따라 'enq: SV - contention' 대기이벤트의 대기시간이 전체 수행 시간의 80%를 차지합니다. 따라서 gc 관련 대기이벤트의 감소 효과를 보다 쉽게 확인하기 위해서 "그림-2"에서는 'enq: SV - contention' 대기이벤트가 속한 Other 클래스를 제외한 그래프를 비교합니다.


결과-1. 테스트 케이스별 CPU 사용 시간 및 대기이벤트 대기 시간 비교

-- 아래의 결과는 테스트 수행 전/후에 각각 V$SYSTEM_EVENT 수치를 저장한 후 Delta 값을 비교한 것입니다. 
FLAG       CLASS           NAME                                      1          2          3          4
---------- --------------- -------------------------------- ---------- ---------- ---------- ----------
[EVENT]    Other           enq: SV -  contention                 16869      14916      19951      13076      
[EVENT]    Cluster         gc buffer busy acquire                 1825         57         99          3
[EVENT]    Cluster         gc current block busy                   926         79        596          0
[EVENT]    Cluster         gc buffer busy release                  432         19         40
[EVENT]    Concurrency     buffer busy waits                       284         11         23          4
[EVENT]    Concurrency     enq: TX - index contention              216         26         20          1
[EVENT]    Concurrency     cursor: pin S wait on X                 131        153        204         73
[EVENT]    Cluster         gc cr grant 2-way                        70         22         70         18
[EVENT]    Cluster         gc cr block 2-way                        58         11         27          0
[EVENT]    Concurrency     row cache lock                           57         14         41         10
[EVENT]    Concurrency     library cache load lock                  38         23         25         27
[EVENT]    Cluster         gc current split                         34          1          2
[EVENT]    Cluster         gc current grant busy                    30          8         16          0
[EVENT]    Concurrency     library cache lock                       22         20         27         29
[EVENT]    Cluster         gc cr multi block request                13          3          7          2
[EVENT]    Concurrency     library cache pin                        11          1          3          0
[EVENT]    Cluster         gc current block lost                    11          4         13          0
[EVENT]    Cluster         gc current block 2-way                    9         60        122          0
[EVENT]    Concurrency     latch: cache buffers chains               8          0          0          0
[EVENT]    Cluster         gc current grant 2-way                    4          1         13          0
[EVENT]    Cluster         gc current block 3-way                    4         31         30          0


3. 결과 요약


테스트 케이스 별 개선 효과 및 적용 시 고려 사항을 정리하면 다음과 같습니다.


구분 

 수행 결과

 고려 사항

 Case #2

 (Reverse Index)

 우수

 Reverse 인덱스의 구조상 Index range scan을 수행할 수 없음.

 Case #3

 (Global Hash Index Partition)

 비교적 우수

 Index range scan 수행 시, 파티션 개수만큼의 partition iteration 수행 필요.

 Case #4

 (LIST 파티션을 이용한 입력 노드의 분리)

 가장 우수

 모델링 및 AP 수정 필요.

 Index range scan 수행 시, 노드 개수만큼의 partition iteration 수행 필요.




4. 글을 마치며


좋은 엔지니어가 되기 위해서는 정확한 도구로 정확히 문제를 파악하고, 해당 환경에 가장 적절한 튜닝 방법을 제시하는 능력이 필요합니다. 그러기 위해서는 다각적인 사고를 할 수 있는 사고의 유연성을 기르는 것도 필요할 것 같습니다.

저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

RAC 성능분석 시에 gc buffer busy acquire 대기이벤트와 gc buffer busy release 대기이벤트를 목격하는 경우가 있습니다. 오라클은 11g 부터 기존의 gc buffer busy 대기이벤트를 gc buffer busy acquiregc buffer busy release 대기이벤트로 세분화했습니다. 


gc buffer busy acquire 대기이벤트는 로컬 노드의 gc current request 대기이벤트와 관련이 있습니다. 로컬 노드에 gc current request 를 대기하는 세션이 획득하려는 버퍼를 대기할 때 gc buffer busy acquire 를 대기합니다. (예시-1 및 그림-1 참조)


gc buffer busy release 대기이벤트는 리모트 노드의 gc current request 대기이벤트와 관련이 있습니다. 리모트 노드에 gc current request 를 대기하는 세션이 획득하려는 버퍼를 대기할 때 gc buffer busy release 를 대기합니다. (예시-1 및 그림-1 참조)


예시-1. 3 노드 RAC 환경에서 gc buffer busy acquire 및 gc buffer busy release 대기이벤트 발생 예제

-- 1번 및 2번 노드에서 file#6 block#=1540에 대해서 'gc current request' 대기이벤트를 대기하는 세션이 존재
-- 이때, 1번과 2번 노드에는 'gc buffer busy acquire' 대기이벤트를 대기하는 세션이 발생
-- 이때, 3번 노드에는 'gc buffer busy release' 대기이벤트를 대기하는 세션이 발생 

INST_ID   SID STATUS   EVENT                                       P1         P2  WAIT_TIME SQL_TEXT
------- ----- -------- ----------------------------------- ---------- ---------- ---------- --------------------
      1    91 ACTIVE   gc current request                           6       1540          0 INSERT INTO T1 VALUE
          101 ACTIVE   gc buffer busy acquire                       6       1540          0 INSERT INTO T1 VALUE

      2    87 ACTIVE   gc current request                           6       1540          0 INSERT INTO T1 VALUE
	       76 ACTIVE   gc buffer busy acquire                       6       1540          0 INSERT INTO T1 VALUE
           
      3    93 ACTIVE   gc buffer busy release                       6       1540          0 INSERT INTO T1 VALUE


그림-1. 3 노드 RAC 환경에서 gc buffer busy acquire 및 gc buffer busy release 대기이벤트 발생 예제


저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License

지인으로부터 다음과 같은 질문을 받았습니다. "인덱스 블록에 대한 CR Read는 어떻게 이뤄지나요?" 상식적으로 생각하면 테이블 CR Read와 동일한 방식으로 수행될 것 같고, 사실 그러합니다. 그렇다면 어떤 방식으로 이 사실을 명확하게 증명할 수 있을까요? 어찌 보면 사실 그 자체보다 사실을 증명해 나가는 다양한 기법을 알고 있는 것이 엔지니어로서는 좋은 무기가 될 것입니다. 따라서 이번 포스팅에서는 몇 가지 유용한 기법을 통해서 인덱스 CR Read에 대해서 분석하는 내용을 다루려고 합니다. (RAC 연재를 마무리하고 다른 주제로 넘어가려고 했으나, 테스트한 내용을 간단히 정리하면 좋을 것 같아서 잠시 외도(?)를 하게 됬습니다 :))


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


답보기


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



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
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

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
CR blocks created                                                         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: ---DS--, 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: ---DS--, 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 유틸리티)들을 제공하고 있다는 사실에 새삼 놀라게 됩니다. 이런 다양한 기법 중에서 현재 처한 문제를 분석하기 위해서 적절한 기법을 선택한 것도 중요한 부분인 것 같습니다.

저작자 표시 비영리 변경 금지
신고
크리에이티브 커먼즈 라이선스
Creative Commons License


 

티스토리 툴바