My Books

My Slides

rss 아이콘 이미지

Search

'2016/08'에 해당되는 글 24건

  1. 2016.08.31 PostgreSQL의 pageinspect extension을 이용한 블록 덤프 방법
  2. 2016.08.31 PostgreSQL의 dblink extension을 이용한 autonomous 트랜잭션 구현 방법
  3. 2016.08.31 PostgreSQL에서 external (foreign) 테이블 생성 방법 및 이를 이용한 fulltime.sh 포팅 방안
  4. 2016.08.31 [PostgreSQL 9.6 New Feature] wait_event_type 및 wait_event 칼럼을 이용한 대기이벤트 모니터링
  5. 2016.08.27 오라클 리눅스 7에 PostgreSQL 9.4 및 9.6을 설치하는 가장 간단한 방법
  6. 2016.08.27 오라클 리눅스 7에 MySQL 5.7을 설치하는 간단한 방법
  7. 2016.08.27 MySQL, PostgreSQL 카테고리가 추가되었습니다.
  8. 2016.08.24 리눅스 perf 명령어를 이용한 오라클 Kernel Function 분석 방법
  9. 2016.08.23 V$SESSION 뷰의 WAIT_TIME_MICRO 및 TIME_SINCE_LAST_WAIT_MICRO 칼럼에 대한 명확한 이해 (1)
  10. 2016.08.22 V$SESSION 뷰의 LAST_CALL_ET 및 SQL_EXEC_START 칼럼에 대한 명확한 이해
  11. 2016.08.20 V$OSSTAT, V$SYS_TIME_MODEL 및 V$SYSTEM_EVENT 뷰를 이용한 시스템 레벨 모니터링 방안
  12. 2016.08.17 V$WAIT_CHAINS 뷰를 이용한 블로킹 세션과 대기 세션 모니터링 방법
  13. 2016.08.15 Right-hand 인덱스에서 발생하는 gc buffer busy acquire 및 gc buffer busy release 대기이벤트 감소 방안
  14. 2016.08.15 gc buffer busy acquire 대기이벤트와 gc buffer busy release 대기이벤트의 차이점
  15. 2016.08.12 [캐시 퓨전 #5] 커밋된 블록 UPDATE 시에 발생하는 gc cr/current block 2-way, 3-way 대기이벤트에 대한 이해
  16. 2016.08.12 [캐시 퓨전 #4] 변경된 블록 UPDATE 시에 발생하는 gc cr block busy, gc cr/current block 2-way, 3way 대기이벤트에 대한 이해
  17. 2016.08.12 [캐시 퓨전 #3] 커밋된 블록 SELECT 시에 발생하는 gc cr/current block 2-way, 3-way 대기이벤트 및 _fairness_threshold 파라미터에 대한 이해
  18. 2016.08.12 [캐시 퓨전 #2] 변경중인 블록 SELECT 시에 발생하는 gc cr block busy 대기이벤트 및 _db_block_max_cr_dba 파라미터에 대한 이해
  19. 2016.08.12 [캐시 퓨전 #1] SELECT 시에 발생하는 gc cr grant 2-way 대기이벤트에 대한 이해
  20. 2016.08.07 [20] GCS SHADOW 동작 원리 및 GCS SHADOW의 필요성에 대한 설명

PostgreSQL은 pageinspect 익스텐션을 이용한 블록 덤프 기능을 제공합니다. 오라클과 같이 다양하고 세세한 기능을 제공하지는 않지만, 간단한 테스트 시에는 좋은 도구로 활용할 수 있습니다. 사용 방법 및 예제는 다음과 같습니다.


1. PAGEINSPECT 익스텐션 설치 

create extension pageinspect;


2. 테스트 시나리오 수행

-- 테이블 생성 
test=# create table t3 (c1 integer);

-- 3건 입력 
test=# insert into t3 values(1);
test=# insert into t3 values(2);
test=# insert into t3 values(3);

-- 각각의 XID가 74,75,76 인것을 확인 
test=# select xmin, xmax, * from t3;
   xmin    | xmax | c1
-----------+------+----
        74 |    0 |  1
        75 |    0 |  2
        76 |    0 |  3

-- 2번 레코드 삭제  
test=#  delete from t3 where c1=2;

test=# select xmin, xmax, * from t3;
   xmin    | xmax | c1
-----------+------+----
        74 |    0 |  1
        76 |    0 |  3

-- 3번 레코드 변경 	
test=# update t3 set c1=4 where c1=3;

test=# select xmin, xmax, * from t3;
   xmin    | xmax | c1
-----------+------+----
        74 |    0 |  1
        78 |    0 |  4

이때, 실제 블록 내부에는 어떠한 변경 사항이 발생했는지 확인해보겠습니다.


3. GET_RAW_PAGE 함수를 이용한 블록 덤프

-- get_raw_page의 (1번쨰 아규먼트: 오브젝트 명) (2번쨰 아규먼트: 블록 번호)
-- delete와 update로 인해 삭제된 레코드 2건은 아직 블록 내에 존재하는 것을 알 수 있습니다.
-- delete의 XID는 77
-- update의 XID는 78 

test=# select t_ctid,
       case lp_flags
           when 0 then 'Unused'
           when 1 then 'Normal'
           when 2 then 'Redirect to ' || lp_off
           when 3 then 'Dead'
        end,
        t_xmin,
        t_xmax
from    heap_page_items(get_raw_page('t3',0));		

 t_ctid |  case  |  t_xmin   |  t_xmax
--------+--------+-----------+-----------
 (0,1)  | Normal | 74        |         0   
 (0,2)  | Normal | 75        |        77   --- delete 명령어로 delete된 레코드  
 (0,4)  | Normal | 76        |        78   --- update 명령어로 delete된 레코드
 (0,4)  | Normal | 78        |         0


4. VACUUM 수행 후의 변경 사항 확인

test=# vacuum t3;

-- VACUUM 수행 후, 삭제된 2건은 재활용 가능한 상태로 변경된 것을 알 수 있습니다. 

test=# select t_ctid,
       case lp_flags
           when 0 then 'Unused'
           when 1 then 'Normal'
           when 2 then 'Redirect to ' || lp_off
           when 3 then 'Dead'
        end,
        t_xmin,
        t_xmax
from    heap_page_items(get_raw_page('t3',0));
	
 t_ctid |     case      |  t_xmin   | t_xmax
--------+---------------+-----------+--------
 (0,1)  | Normal        |        74 |      0
        | Unused        |           |         
        | Redirect to 4 |           |         
 (0,4)  | Normal        |        78 |      0


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

PostgreSQL은 현재까지(버전 9.6) plpgsql내에서 autonomous 트랜잭션을 지원하지 않습니다. 하지만 dblink 익스텐션을 이용하면 autonomous 트랜잭션을 구현하는 것이 가능합니다. 제 경우에는 Vacuum 동작원리를 파악하기 위해 XID를 빠르게 증가시킬 필요가 있었습니다. 하지만 PostgreSQL은 LOOP 내에서의 COMMIT을 허용하지 않으므로 dblink 익스텐션을 이용해서 해당 기능을 구현했습니다. 사용 방법은 다음과 같습니다.


1. DBLINK 익스텐션 설치

test=# create extension dblink;


2. DBLINK를 이용해서 매건 커밋하는 프로시저 생성

-- 성능을 위해서 dblink_connect 및 dblink_disconnect는 프로시저 외부에서 수행하도록 변경 

CREATE OR REPLACE FUNCTION insert_t1(v1 integer) RETURNS VOID AS $$
BEGIN
           -- PERFORM dblink_connect('myconn','dbname=test port=5433 user=postgres password=oracle');
           PERFORM dblink('myconn','INSERT INTO t1 SELECT ' || '''' || v1 || '''');
           PERFORM dblink('myconn','COMMIT;');
           -- PERFORM dblink_disconnect('myconn'); 
END;
$$ LANGUAGE plpgsql;


3. 매건 커밋하는 프로시저를 호출하는 프로시저 생성

CREATE or replace FUNCTION loop_insert_t1(v_loop integer) RETURNS VOID AS $$
BEGIN
    
    FOR i in 1..v_loop LOOP
        PERFORM insert_t1(i);
    END LOOP;
END;
$$ LANGUAGE plpgsql;


4. DBLINK 연결 -> LOOP 수행 -> DBLINK 연결 해제


다음과 같은 방법을 이용하면 아주 빠르고 편리하게 XID를 증가시킬 수 있습니다. 테스트 시에 도움이 되길 바랍니다.

-- DBLINK 연결
test=# select dblink_connect('myconn','dbname=test port=5433 user=postgres password=oracle');

--프로시저 수행
test=# select loop_insert_t1(100000000);

--DBLINK 연결해제 
test=# select dblink_disconnect('myconn'); 


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

PostgreSQL은 file_fdw 익스텐션을 이용해서 external 테이블을 생성할 수 있습니다.


1. file_fdw 익스텐션을 이용한 external 테이블 생성 방법


-- file_fdw 익스텐션을 생성합니다.
test=#  create extension file_fdw;

-- 서버를 생성합니다.
test=# create server srv_file_fdw foreign data wrapper file_fdw;

-- foreign 테이블을 생성합니다.
test=#  create foreign table op_perf_report 
(
  overhead      numeric,
  command       varchar(100),
  shared_obj    varchar(100),
  symbol        varchar(100)  
)
server srv_file_fdw 
options ( 
    format 'csv',
	header 'true',
    delimiter ',',
    filename '/var/tmp/perf_report.txt');


2. external 테이블을 이용한 fulltime.sh 포팅


이전 포스팅에서 fulltime.sh (perf 명령어를 이용해서 오라클 Kernel function을 분석하는 쉘) 스크립트를 소개한바 있습니다. 해당 방법의 골자는 perf 명령어 수행결과 파일을 external 테이블로 지정한 후, 해당 테이블을 조회하는 것입니다. 따라서 fulltime.sh를 PostgreSQL용으로 포팅하기 위해서는 external 테이블을 이용해야 합니다. 단, PostgreSQL은 세션 레벨의 CPU Time 정보 (오라클의 v$sess_time_model)을 제공하지 않으므로 OS 레벨의 CPU 사용 정보만을 제공한다는 제약사항이 있습니다. 아래의 소스 중에서 눈 여겨 볼 것은 2가지 정도입니다.


1) foreign 테이블 생성을 위한 약간의 조작
foreign 테이블용으로 생성되는 파일 (/var/tmp/perf_report.txt)에는 주석(#) 및 공백 라인이 있을 경우에는 에러가 발생합니다. 따라서 다음과 같이 grep과 sed 명령어를 이용해서 해당 라인들을 제거합니다.

perf report -t, > z ; cat z | grep -v '#' | sed '/^\s*$/d' > /var/tmp/perf_report.txt 2>/dev/null

2) 패스워드 입력 없이 psql에 로그인 하는 방법

PGPASSWORD=oracle psql test -p 5433 -Upostgres <<EOF1


PostgreSQL용으로 포팅된 fulltime.sh 소스는 다음과 같습니다.


Source: PostgreSQL용 fulltime.sh

#!/bin/sh
#
# Name    : fulltime.sh
version=3e
# Purpose : To see PostgreSQL kernel function CPU details TOGETHER.
# Orig    : 17-Oct-2013
# Latest  : 31-Oct-2013
# Modify  : 31-Aug-2016 by Siyeon.Kim 
# Author  : Craig Shallahamer 
#           Frits Hoogland 
# Warrenty: There is absolutely no warrenty.
#           Use at your own and your organization's risk.
#           It's all on you, not me!

# Usage   : ./fulltime.sh
#           ./fulltime.sh PID INTERVAL CYCLES
#
# This has been developed on Linux.
# You break out with a cntrl-c

# Here is the general idea:
#
# Help user Identify the PID to profile
# Initial setup
# Loop
#   start PostgreSQL kernel cpu details
#   sleep x
#   stop PostgreSQL kernel cpu gathering
#   do some cool math and other neat stuff
#   display results
# End Loop

# Set the key variables
#
# use this for virtualised hosts:
#PERF_SAMPLE_METHOD='-e cpu-clock'
# use this for physical hosts:
PERF_SAMPLE_METHOD='-e cycles'

refresh_time=3
samples_remaining=999 # this is useful for longer single samples

workdir=$PWD
perf_file=perf_report.txt

clear

# if problems with perf
echo "If unable to execute perf, do as root:"
echo "   echo 0 > /proc/sys/kernel/perf_event_paranoid"

# perf sample method
echo ""
echo "The perf sample method is set to: $PERF_SAMPLE_METHOD"
echo "Use cpu-clock for virtualised hosts, cycles for physical hosts"

###
# ctrl_c routine
###
ctrl_c() {
        PGPASSWORD=oracle psql test -p 5433 -Upostgres <& /dev/null
        drop foreign table op_perf_report;
        drop table op_timing;
EOF0

        echo ""
        echo ""
        echo "Thanks for using FULLTIME v${version}!"
        echo ""
        echo "To see the latest Call Graph, press ENTER or to exit press CNTRL-C."
        echo ""
        echo "The Call Graph file is callgraph.txt"
        read x
        perf report -g -i callgraph.pdata > callgraph.txt 2>/dev/null
        echo ""
        more callgraph.txt
        exit
}

###
# help_find_pid routine
#
# Let's help the user identifiy the Oracle session of interest
#
###
help_find_pid() {
PGPASSWORD=oracle psql test -p 5433 -Upostgres </dev/null; then ctrl_c; fi

PGPASSWORD=oracle psql test -p 5433 -Upostgres <& /dev/null

drop foreign table op_perf_report;

create foreign table op_perf_report (
  overhead      numeric,
  command       varchar(100),
  shared_obj    varchar(100),
  symbol        varchar(100)
)
server srv_file_fdw
options (
    format 'csv',
    header 'true',
    delimiter ',',
    filename '/var/tmp/perf_report.txt'
);

EOF2

while [ $samples_remaining  -gt 0 ]
do
        echo "Gathering next $refresh_time second sample..."

        if ! ps -p $ospid >/dev/null; then ctrl_c; fi

        perf record -f $PERF_SAMPLE_METHOD -p $ospid sleep $refresh_time >& /dev/null &
        perf record -f $PERF_SAMPLE_METHOD -g -o callgraph.pdata -p $ospid sleep $refresh_time >& /dev/null   &
        wait

        if ! ps -p $ospid >/dev/null; then ctrl_c; fi

        perf report -t, > z ; cat z | grep -v '#' | sed '/^\s*$/d' > /var/tmp/perf_report.txt 2>/dev/null

        if ! ps -p $ospid >/dev/null; then ctrl_c; fi

        clear

        echo "Fulltime.sh v$version"

        PGPASSWORD=oracle psql test -p 5433 -Upostgres < 2.0;

EOF5
        echo ""
        echo "To see the Call Graph, press ENTER or to exit press CNTRL-C."
        samples_remaining=`echo "$samples_remaining-1" | bc`

        echo "Samples remaining: $samples_remaining"

done

# If NO command line options, then prompt for call graph, else just exit.
#
if [ "$#" -eq 0 ]; then
        ctrl_c
fi


3. fulltime.sh 사용 예제


-- 아규먼트 없이 fulltime.sh를 수행하면 현재 수행하는 모든 프로세스 목록이 출력됩니다. 
[root@pgserver ~]# ./fulltime.sh

  pid  |  query           
-------+------------------------------------------
 32572 | select loop_insert_t1(10000000);
 32598 | INSERT INTO t1 SELECT '3199470'
   427 | INSERT INTO t1 SELECT '3216064'
 32751 | select loop_insert_t1(100000000);
   521 | select loop_insert_t1(100000000);
   522 | INSERT INTO t1 SELECT '3067927'
   669 | select loop_insert_t1(100000000);
   670 | INSERT INTO t1 SELECT '3064539'
   773 | select loop_insert_t1(100000000);
   774 | INSERT INTO t1 SELECT '3072957'
   868 | select loop_insert_t1(100000000);
   870 | INSERT INTO t1 SELECT '3092238'
  1138 | select loop_insert_t1(100000000);
  1139 | INSERT INTO t1 SELECT '3013273'
  1248 | select loop_insert_t1(100000000);
  1249 | INSERT INTO t1 SELECT '3015102'
  1341 | select loop_insert_t1(100000000);
  1342 | INSERT INTO t1 SELECT '3002411'
  1433 | select loop_insert_t1(100000000);
  1435 | INSERT INTO t1 SELECT '2992595'
  
-- PID를 입력하면, 해당 프로세스의 기본 정보 및 Kernel function 사용 내역을 확인할 수 있습니다. 
Enter PID to profile : 32598

Fulltime.sh v3e
                          BASIC_INFO                            |                    QUERY
----------------------------------------------------------------+---------------------------------------------
 PID: 32598 USERNAME: postgres QUERY TIME(Sec): 00:00:00.000373 | CURRENT SQL: INSERT INTO t1 SELECT '101134'

                   item                    | overhead
-------------------------------------------+----------
 cpu : [k] _raw_spin_unlock_irqrestore     |    20.07
 cpu : [k] __do_softirq                    |     9.67
 cpu : [.] SearchCatCache                  |     2.60
(3 rows)

-- CTRL+C 이후에 엔터를 입력하면 Kernel Function Call Tree를 확인할 수 있습니다.
To see the Call Graph, press ENTER or to exit press CNTRL-C.
Samples remaining: 990
Gathering next 3 second sample...

# ========
# captured on: Tue Aug 30 12:43:14 2016
# hostname : pgserver
# os release : 3.8.13-35.3.1.el7uek.x86_64
# perf version : 3.8.13-35.3.1.el7uek.x86_64
# arch : x86_64
# nrcpus online : 2
# nrcpus avail : 2
# cpudesc : Intel(R) Core(TM) i7-6500U CPU @ 2.50GHz
# cpuid : GenuineIntel,6,78,3
# total memory : 3785700 kB
# cmdline : /usr/libexec/perf.3.8.13-35.3.1.el7uek.x86_64 record -f -e cycles -g -o callgraph.pdata -p 32572 sleep 3
# event : name = cpu-clock, type = 1, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_h
ost = 0, excl_guest = 1, precise_ip = 0, id = { 456 }
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: software = 1, tracepoint = 2, breakpoint = 5
# ========
#
# Samples: 80  of event 'cpu-clock'
# Event count (approx.): 80
#
# Overhead   Command      Shared Object                           Symbol
# ........  ........  .................  ...............................
#
    21.25%  postgres  [kernel.kallsyms]  [k] finish_task_switch
            |
            --- finish_task_switch
                __schedule
                schedule
                schedule_hrtimeout_range_clock
                schedule_hrtimeout_range
                poll_schedule_timeout
                do_sys_poll
                sys_poll
                system_call_fastpath
                __poll_nocancel

    18.75%  postgres  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
            |
            --- _raw_spin_unlock_irqrestore
               |
               |--86.67%-- __wake_up_sync_key
               |          |
               |          |--61.54%-- pipe_write
               |          |          do_aio_write
               |          |          do_sync_write
               |          |          vfs_write
               |          |          sys_write
               |          |          system_call_fastpath
               |          |          __GI___libc_write
               |          |          0x2065726568742020
               |          |
               |           --38.46%-- sock_def_readable
               |                     unix_stream_sendmsg
               |                     sock_sendmsg


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

PostgreSQL도 버전 9.6부터 pg_stat_activity 테이블의 wait_event_typewait_event 칼럼을 통해 대기이벤트를 모니터링할 수 있습니다. (세부 내용은 매뉴얼 참조) 현재는 4개의 wait_event_type과 100개 이내의 wait_event를 제공할 뿐이지만, 이전버전까지는 waiting 칼럼을 통해 락 대기 여부만을 판단할 수 있던 것에 비하면 획기적인 변화의 시작임은 분명합니다. 부하를 주고 모니터링을 해본 결과, 오라클과 같이 아주 세세한 부분까지 디버깅을 할 수는 없지만 심각한 문제에 대해서는 어느 정도 문제를 유추할 수 있는 수준의 데이터는 제공하는 것 같습니다. 아래는 동시에 10여개의 세션에서 동일 테이블에 INSERT를 수행하는 부하 테스트 시의 모니터링 결과입니다. 보시는 것과 같이 WALWriteLock 대기이벤트를 대기하는 세션이 다수이고, 이를 통해 해당 세션들은 WAL 버퍼가 디스크로 기록되기를 대기한다는 것을 알 수 있습니다.


Note
이전 버전까지 제공되던 waiting 칼럼은 9.6 버전에서는 제공되지 않습니다. 따라서 waiting='t' 조건을 이용해서 락 대기 세션을 모니터링했던 쿼리들은 wait_event_type='Lock'으로 조건을 변경해야 합니다. 


예시. wait_event_type 및 wait_event 칼럼을 이용한 대기이벤트 모니터링

test=# select pid, wait_event_type, wait_event, current_timestamp-xact_start as txn_time, query from pg_stat_activity;

  pid  | wait_event_type |  wait_event  |     txn_time     |     query
-------+-----------------+--------------+------------------+---------------------------------
 32572 |                 |              | 03:29:30.451393  | select loop_insert_t1(10000000);
 32598 | LWLockNamed     | WALWriteLock | 00:00:00.000653  | INSERT INTO t1 SELECT '3810212'
   427 | LWLockNamed     | WALWriteLock | 00:00:00.001069  | INSERT INTO t1 SELECT '3831263'
 32751 |                 |              | 03:29:17.380626  | select loop_insert_t1(100000000);
   521 |                 |              | 03:25:06.032286  | select loop_insert_t1(100000000);
   522 |                 |              |                  | INSERT INTO t1 SELECT '3683652'
   669 |                 |              | 03:25:04.224235  | select loop_insert_t1(100000000);
   670 | LWLockNamed     | WALWriteLock | 00:00:00.001333  | INSERT INTO t1 SELECT '3679654'
   773 |                 |              | 03:25:00.344482  | select loop_insert_t1(100000000);
   774 |                 |              | 00:00:00.001249  | INSERT INTO t1 SELECT '3689628'
   868 |                 |              | 03:25:45.836126  | select loop_insert_t1(100000000);
   870 | LWLockNamed     | WALWriteLock | 00:00:00.000672  | INSERT INTO t1 SELECT '3708035'
  1138 |                 |              | 03:22:13.689574  | select loop_insert_t1(100000000);
  1139 | LWLockNamed     | WALWriteLock | 00:00:00.000892  | INSERT INTO t1 SELECT '3628461'
  1248 |                 |              | 03:21:42.46344   | select loop_insert_t1(100000000);
  1249 | LWLockNamed     | WALWriteLock | -00:00:00.000289 | INSERT INTO t1 SELECT '3632619'
  1341 |                 |              | 03:21:12.328308  | select loop_insert_t1(100000000);
  1342 | LWLockNamed     | WALWriteLock | 00:00:00.002372  | INSERT INTO t1 SELECT '3619281'
  1433 |                 |              | 03:20:49.765249  | select loop_insert_t1(100000000);
  1435 | LWLockNamed     | WALWriteLock | 00:00:00.000924  | INSERT INTO t1 SELECT '3608915'


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

RUN 파일을 이용하면 아주 간단하게 PostgreSQL 9.4와 9.6을 설치할 수 있습니다.


1. RUN 파일을 다운로드합니다.
아래의 사이트에서 9.4 및 9.6 버전을 다운로드합니다.
http://www.enterprisedb.com/products-services-training/pgdownload


2. 한 서버에 2개의 버전을 설치하려면 9.4를 먼저 설치합니다.

[root@pgserver postgres]# ls -rlt
합계 134188
-rwxr-xr-x. 1 postgres postgres 99134297  8월 25 17:09 postgresql-9.6.0-beta4-linux-x64.run
-rwxr-xr-x. 1 postgres postgres 38271901  8월 25 17:58 postgresql-9.4.9-1-linux-x64.run

[root@pgserver postgres]# ./postgresql-9.4.9-1-linux-x64.run
----------------------------------------------------------------------------
Welcome to the PostgreSQL Setup Wizard.
-- 생략

-- postgres OS 유저가 없는 경우에는 자동으로 생성됩니다.. 
Please provide a password for the database superuser (postgres). A locked Unix
user account (postgres) will be created if not present.

-- postgres DB User의 비밀번호를 설정합니다. 
Password :
Retype password :

-- 리스너 포트를 설정합니다. 기본 설정 값은 5432입니다. 
Port [5432]:

-- 로케일을 설정합니다. 
Locale

[1] [Default locale]
[2] C
[3] POSIX
..
Please choose an option [1] : 2
..
Please wait while Setup installs PostgreSQL on your computer.

 Installing
 0% ______________ 50% ______________ 100%
 ########################################
----------------------------------------------------------------------------
Setup has finished installing PostgreSQL on your computer.

-- 설치가 완료되었습니다. 
-- ps 명령어로 프로세스를 확인하면 postgres 관련 프로세스 목록을 확인할 수 있습니다. 
[root@pgserver postgres]# ps -ef | grep postgres | grep -v root
postgres 15535 15530  0  8월25 ?      00:00:00 sshd: postgres@notty
postgres 15536 15535  0  8월25 ?      00:00:00 /usr/libexec/openssh/sftp-server
postgres 17567 17562  0  8월25 ?      00:00:00 sshd: postgres@notty
postgres 17569 17567  0  8월25 ?      00:00:00 /usr/libexec/openssh/sftp-server
postgres 21988     1  0 01:39 ?        00:00:00 /opt/PostgreSQL/9.4/bin/postgres -D /opt/PostgreSQL/9.4/data
postgres 21989 21988  0 01:39 ?        00:00:00 postgres: logger process
postgres 21991 21988  0 01:39 ?        00:00:00 postgres: checkpointer process
postgres 21992 21988  0 01:39 ?        00:00:00 postgres: writer process
postgres 21993 21988  0 01:39 ?        00:00:00 postgres: wal writer process
postgres 21994 21988  0 01:39 ?        00:00:00 postgres: autovacuum launcher process
postgres 21995 21988  0 01:39 ?        00:00:00 postgres: stats collector process


3. DB 종료, 시작 및 접속

[root@pgserver postgres]# su - postgres 
-- DB 종료
[postgres@pgserver ~]$ /opt/PostgreSQL/9.4/bin/pg_ctl -D /opt/PostgreSQL/9.4/data stop

-- DB 시작 
[postgres@pgserver ~]$ /opt/PostgreSQL/9.4/bin/pg_ctl -D /opt/PostgreSQL/9.4/data start

-- DB 접속 
[postgres@pgserver ~]$ /opt/PostgreSQL/9.4/bin/psql
Password:
psql.bin (9.4.9)
Type "help" for help.

postgres=# select current_user;
 current_user
--------------
 postgres
(1 row)

PostgreSQL 9.6도 동일한 방법으로 설치를 진행하면됩니다.

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

오라클 리눅스 7에 MySQL 5.7을 설치하는 간단한 방법

MySQL 2016.08.27 21:13 Posted by 시연아카데미

MySQL 5.7 설치를 시작으로 MySQL 세계로 다이빙해보도록 하겠습니다.



1. 오라클 리눅스 설치 시에 설치된 mariadb를 삭제합니다.

[root@localhost ~]# yum remove mariadb mariadb-server
[root@localhost ~]# rm -rf /var/lib/mysql 
[root@localhost ~]# rm /etc/my.cnf


2 아래의 사이트에서 YUM 리파지토리를 다운로드합니다.

2016년 8월 현재 가장 최신 버전은 mysql57-community-release-el7-8.noarch.rpm 입니다.


http://dev.mysql.com/downloads/repo/yum/



3. 다운받은 YUM 리파지토리를 설치합니다.

[root@localhost ~]# rpm -Uvh mysql57-community-release-el7-8.noarch.rpm
warning: mysql57-community-release-el7-8.noarch.rpm: Header V3 DSA/SHA1 Signature, key ID 5072e1f5: NOKEY
Preparing...                          ################################# [100%]
Updating / installing...
   1:mysql57-community-release-el7-8  ################################# [100%]


4. /etc/yum.repos.d/mysql-community.repo 파일을 확인합니다.

-- 아래와 같이 [mysql57-community] 섹션에 enabled=1로 되어있는 것을 확인합니다.
[mysql57-community]
name=MySQL 5.7 Community Server
baseurl=http://repo.mysql.com/yum/mysql-5.7-community/el/7/$basearch/
enabled=1
gpgcheck=1
gpgkey=file:///etc/pki/rpm-gpg/RPM-GPG-KEY-mysql


5. YUM으로 MySQL을 설치합니다.

[root@localhost ~]# yum install mysql-community-server
.. 생략
===========================================================================================================
 Package                            Arch          Version                   Repository                Size
===========================================================================================================
Installing:
 mysql-community-libs               x86_64        5.7.14-1.el7              mysql57-community        2.1 M
     replacing  mariadb-libs.x86_64 1:5.5.35-3.el7
 mysql-community-libs-compat        x86_64        5.7.14-1.el7              mysql57-community        2.0 M
     replacing  mariadb-libs.x86_64 1:5.5.35-3.el7
 mysql-community-server             x86_64        5.7.14-1.el7              mysql57-community        152 M
Installing for dependencies:
 mysql-community-client             x86_64        5.7.14-1.el7              mysql57-community         24 M
 mysql-community-common             x86_64        5.7.14-1.el7              mysql57-community        271 k
Updating for dependencies:
 perl-DBD-MySQL                     x86_64        4.023-5.0.1.el7           ol7_latest               140 k
 postfix                            x86_64        2:2.10.1-6.0.1.el7        ol7_latest               2.4 M
 qt                                 x86_64        1:4.8.5-12.el7_2          ol7_latest               4.5 M
 qt-mysql                           x86_64        1:4.8.5-12.el7_2          ol7_latest                31 k
 qt-x11                             x86_64        1:4.8.5-12.el7_2          ol7_latest                13 M

.. 생략 
Complete!


6. MySQL 서비스를 시작합니다.

[root@localhost ~]# service mysqld start


7. root 유저의 비밀번호를 변경합니다.

-- 현재 비밀번호를 확인합니다. 확인 결과 현재 임시 비밀번호는 'LhBgWgt?Y5ry' 인것을 알 수 있습니다.
[root@localhost ~]# grep 'temporary password' /var/log/mysqld.log
2016-08-27T01:57:51.283386Z 1 [Note] A temporary password is generated for root@localhost: LhBgWgt?Y5ry

-- 임시 비밀번호로 접속합니다.
[root@localhost ~]# mysql -uroot -pLhBgWgt?Y5ry

-- 새로운 비밀번호를 설정합니다. 
-- 비밀번호 정책에 따라 비밀번호는 대소문자, 숫자, 특수문자가 각각 1개 이상 있어야하고 최소 8자리 이상이어야 합니다. 

mysql> alter user 'root'@'localhost' identified by 'Mynewpass4!';
Query OK, 0 rows affected (0.00 sec)

설치가 완료되었습니다.


참고사이트
http://dev.mysql.com/doc/mysql-yum-repo-quick-guide/en/

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

MySQL, PostgreSQL 카테고리가 추가되었습니다.

NOTICE 2016.08.27 21:07 Posted by 시연아카데미

MySQL 및 PostgreSQL 카테고리를 추가했습니다. 블로그를 처음 개설했을 때의 생각은 오라클 분야의 연구를 최대한 고도화한 후에 다른 DBMS로 범위를 확장하는 것이었습니다만, 세상이 너무 빠르게 변하고 있고 더 이상 오라클만으로는 밥벌이하기가 쉽지 않다는 위기 의식이 점차 현실화되고 있습니다. 속도의 문제가 있겠지만 클라우드 세상으로 변모할 것이고, 이미 현실화되고 있는 탈 오라클 움직임은 오픈 소스 DBMS들의 활약으로 인해 점차 속도를 더할 것 같습니다. 이런 변화 속에서 살아남기 위해서는 오라클 이외의 새로운 무기를 가지고 있어야합니다. 이런 맥락에서 새롭게 연구를 시작한 DBMS는 MySQL과 PostgreSQL입니다. 오라클과 더불어 새로운 DBMS 역시 최선을 다해서 컨텐츠를 준비하려고 합니다. 그럼 많은 관심 부탁드리겠습니다.

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

일반적으로 오라클 성능 분석 방법론은 대기 시간의 분석에 초점이 맞춰져 있습니다. 즉, 응답시간을 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

1. 테스트 개요


2번 노드에서 레코드 1건 (마스터 노드: 3번)을 변경한 후 커밋을 수행합니다. 그런 후에 해당 블록 내의 각기 다른 레코드를 1번 및 3번 노드에서 변경합니다. 이를 통해, 커밋된 블록을 변경할 때 발생하는 gc cr block 2-way, gc cr block 3-way, gc current block 2-way, gc current block 3-way 대기이벤트의 동작원리를 파악하도록 합니다.



2. 2번 노드에서 1건 UPDATE 및 COMMIT 수행


2번 노드에서 1건을 변경하면 해당 블록에 대한 XCUR 버퍼 및 CR 버퍼가 캐시에 적재됩니다. (그림-1 참조) 이때 발생하는 변경 사항은 아래의 테스트 결과 중간중간에 주석으로 설명해 두었습니다. (테스트 수행 전에 버퍼 캐시를 flush합니다)


그림-1. 2번 노드에서 1건 UPDATE 및 COMMIT 수행 후의 변경 내용


-- 해당 블록은 로컬 및 리모트 캐시에 존재하지 않으므로 3번 노드의 LMS로부터 블록 액세스 권한을 부여 받습니다.
-- 이로 인해 'gc cr grant 2-way' 대기이벤트가 1회 발생합니다. 
  
-- 그런 후에, 싱글 블록 IO를 이용해서 해당 블록(File#=6, Block#=228)을 메모리로 적재합니다. 
-- 이때 'db file sequential read' 대기이벤트가 1회 발생합니다.
  
-- 해당 블록을 적재한 후에는 해당 블록을 변경하기 위한 CURRENT 권한을 부여 받아야합니다.
-- 이로 인해 'gc current grant 2-way' 대기이벤트가 1회 발생합니다.
  
-- 또한, 변경 작업을 위한 언두 블록을 할당 받기 위해 'db file sequential read' 대기이벤트가 2회 발생합니다.
-- 블록 덤프를 수행해보면 각각 언두 헤더 블록과 언두 블록임을 알 수 있습니다. 

-- 마지막으로 커밋 수행에 따른 'log file sync' 대기이벤트가 1회 발생합니다.

SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_update1 

WAIT #140225505518032: nam='gc cr grant 2-way' ela= 1694 p1=6 p2=228 p3=1 obj#=93973 tim=310683117658
WAIT #140225505518032: nam='db file sequential read' ela= 1004 file#=6 block#=228 blocks=1 obj#=93973 tim=310683118769
WAIT #140225505518032: nam='gc current grant 2-way' ela= 1585 p1=6 p2=228 p3=33619969 obj#=93973 tim=310683120612
WAIT #140225505518032: nam='db file sequential read' ela= 4967 file#=5 block#=208 blocks=1 obj#=0 tim=310683125736
WAIT #140225505518032: nam='db file sequential read' ela= 4138 file#=5 block#=3097 blocks=1 obj#=0 tim=310683130557

WAIT #140225502776168: nam='log file sync' ela= 3259 buffer#=3054 sync scn=12152221 p3=0 obj#=0 tim=310702054641

SYS@OOW2:2> alter system dump datafile 5 block 208;
frmt: 0x02 chkval: 0xbae3 type: 0x26=KTU SMU HEADER BLOCK

SYS@OOW2:2> alter system dump datafile 5 block 3097;
frmt: 0x02 chkval: 0xfdae type: 0x02=KTU UNDO BLOCK

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요)

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [EVENT]  db file sequential read            3
                        gc cr grant 2-way                  1
                        gc current grant 2-way             1						
               [STAT]   physical reads                     3
                        session logical reads              3

-- 2번 노드에 XCUR 버퍼 1개와 CR 버퍼 1개가 적재되었습니다.
-- 그리고 2번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되고 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다.

SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD4D06B0      1 CR     00                        0 0000000073540000
     00007F79DD4D0830      1 XCUR   00000000753FD2B0          2 0000000073A8E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000753FD338      1 KJUSEREX  GRANTED    00000000753FD2B0      1 XCUR
OOW3 00000000696D69C0      1 KJUSEREX  GRANTED



3. 1번 노드에서 동일 블록 내의 다른 레코드 UPDATE 및 COMMIT 수행


1번 노드에서 동을 블록 내의 다른 레코드를 변경하면 2번 노드의 XCUR 버퍼는 PI 버퍼로 변경되고 1번 노드에 XCUR 버퍼가 적재됩니다. (그림-2 참조)


그림-2. 1번 노드에서 동일 블록 내의 다른 레코드 UPDATE 및 COMMIT 수행후의 변경 내용


-- 2번 노드로부터 CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송 받습니다. 해당 블록의 마스터 노드는 3번이므로 
-- 'gc cr block 3-way'와 'gc current block 3-way' 대기이벤트가 1회씩 발생합니다.

-- 그리고, 트랜잭션 수행을 위한 언두 헤더 블록과 언두 블록을 메모리로 적재하는 과정에서
-- 'db file sequential read' 대기이벤트가 2회 발생합니다.

-- 마지막으로 커밋 수행에 따른 'log file sync' 대기이벤트가 1회 발생합니다. 
  
SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_update2 

WAIT #139902827416192: nam='gc cr block 3-way' ela= 2424 p1=6 p2=228 p3=1 obj#=93973 tim=337578449818
WAIT #139902827416192: nam='gc current block 3-way' ela= 2505 p1=6 p2=228 p3=33554433 obj#=93973 tim=337578453388
WAIT #139902827416192: nam='db file sequential read' ela= 1202 file#=4 block#=192 blocks=1 obj#=0 tim=337578455469
WAIT #139902827416192: nam='db file sequential read' ela= 1351 file#=4 block#=1474 blocks=1 obj#=0 tim=337578457287

WAIT #139902827440960: nam='log file sync' ela= 2514 buffer#=6901 sync scn=12156733 p3=0 obj#=0 tim=337578468566


-- 2번 노드의 LMS가 CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송한 것을 알 수 있습니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  db file sequential read            2
                        gc cr block 3-way                  1
                        gc current block 3-way             1						
               [STAT]   gc cr blocks received              1
                        gc current blocks received         1
                        physical reads                     2
                        session logical reads              5						
      2 [LMS]  [STAT]   gc cr blocks served                1
                        gc current blocks served           1
                        session logical reads              1

-- 2번 노드의 버퍼 상태가 XCUR에서 PI로 변경되었습니다.
-- 1번 노드에 XCUR 및 CR 버퍼가 1개씩 적재되었습니다.
-- 1번 노드의 GRD에 GCS 클라이언트가 1개 생성되었고, 3번 노드의 GRD에 GCS SHADOW가 1개 생성되었습니다.
	  
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072042788      1 CR     00                        0 00000000751CC000
     00007F8072042908      1 XCUR   0000000073BE8BA8          1 0000000074910000

OOW2 00007F79DD4D06B0      1 CR     00                        0 0000000073540000
     00007F79DD4D0830      1 PI     00000000753FD2B0          2 0000000073A8E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 0000000073BE8C30      0 KJUSEREX  GRANTED    0000000073BE8BA8      1 XCUR
OOW2 00000000753FD338      1 KJUSERNL  GRANTED    00000000753FD2B0      1 PI
OOW3 00000000696D69C0      1 KJUSERNL  GRANTED
OOW3 0000000069728E78      0 KJUSEREX  GRANTED



4. 3번 노드에서 동일 블록 내의 다른 레코드 UPDATE 및 COMMIT 수행


3번 노드에서 동일 블록 내의 다른 레코드를 변경하면 1번 노드의 XCUR 버퍼는 PI 버퍼로 변경되고 3번 노드에 XCUR 버퍼가 적재됩니다. (그림-3 참조)


그림-3. 3번 노드에서 동일 블록 내의 다른 레코드 UPDATE 및 COMMIT 수행후의 변경 내용


-- 1번 노드로부터 CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송 받습니다. 해당 블록의 마스터 노드는 3번이므로 
-- 'gc cr block 2-way'와 'gc current block 2-way' 대기이벤트가 1회씩 발생합니다.

-- 그리고, 트랜잭션 수행을 위한 언두 헤더 블록과 언두 블록을 메모리로 적재하는 과정에서
-- 'db file sequential read' 대기이벤트가 2회 발생합니다.

-- 마지막으로 커밋 수행에 따른 'log file sync' 대기이벤트가 1회 발생합니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_update3

WAIT #140357041043368: nam='gc cr block 2-way' ela= 2111 p1=6 p2=228 p3=1 obj#=93973 tim=311326241579
WAIT #140357041043368: nam='gc current block 2-way' ela= 2687 p1=6 p2=228 p3=33554433 obj#=93973 tim=311326245126
WAIT #140357041043368: nam='db file sequential read' ela= 2116 file#=2 block#=160 blocks=1 obj#=0 tim=311326247918
WAIT #140357041043368: nam='db file sequential read' ela= 4200 file#=2 block#=2335 blocks=1 obj#=0 tim=311326252599

WAIT #140357041184600: nam='log file sync' ela= 3590 buffer#=5594 sync scn=12156920 p3=0 obj#=0 tim=311326263131

-- 1번 노드의 LMS가 CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송한 것을 알 수 있습니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [LMS]  [STAT]   gc cr blocks served                1
                        gc current blocks served           1
                        session logical reads              1						
      3 [FG]   [EVENT]  db file sequential read            2
                        gc cr block 2-way                  1
                        gc current block 2-way             1						
               [STAT]   gc cr blocks received              1
                        gc current blocks received         1
                        physical reads                     2
                        session logical reads              5

-- 1번 노드의 버퍼 상태가 XCUR에서 PI로 변경되었습니다.
-- 3번 노드에 XCUR 및 CR 버퍼가 1개씩 적재되었습니다.
-- 3번 노드의 GRD에 GCS 클라이언트가 1개 생성되었습니다.
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F80728C39A0      1 CR     00                        0 00000000751CC000
     00007F80728C3B20      1 PI     0000000073BE8BA8          1 0000000074910000

OOW2 00007F79DD4D06B0      1 CR     00                        0 0000000073540000
     00007F79DD4D0830      1 PI     00000000753FD2B0          2 0000000073A8E000

OOW3 00007FBB2D2152B8      1 CR     00                        0 0000000074962000
     00007FBB2D215438      1 XCUR   00000000757E6AD8          1 00000000745BE000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 0000000073BE8C30      0 KJUSERNL  GRANTED    0000000073BE8BA8      1 PI
OOW2 00000000753FD338      1 KJUSERNL  GRANTED    00000000753FD2B0      1 PI
OOW3 0000000069728E78      0 KJUSERNL  GRANTED
OOW3 00000000696D69C0      1 KJUSERNL  GRANTED
OOW3 00000000757E6B60      2 KJUSEREX  GRANTED    00000000757E6AD8      1 XCUR


이전: [캐시 퓨전 #4] 변경된 블록 UPDATE 시에 발생하는 gc cr block busy, gc cr/current block 2-way, 3way 대기이벤트에 대한 이해


연재를 마무리하며


5개의 연재를 통해서 캐시 퓨전의 기본 원리에 대해서 살펴보았습니다. 다음 시간에는 경합에 의해 발생하는 buffer busy와 관련된 사항에 대해서 설명할 예정입니다.

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

1. 테스트 개요


2번 노드에서 레코드 1건 (마스터 노드: 3번)을 변경합니다. 그런 후에 해당 블록 내의 각기 다른 레코드를 1번 노드 및 3번 노드에서 변경합니다. 이를 통해, 변경 중인 블록을 변경할 때 발생하는 gc cr block busy, gc cr block 2-way, gc cr block 3-way, gc current block 2-way, gc current block 3-way 대기이벤트의 동작원리를 파악하도록 합니다.



2. 2번 노드에서 1건 UPDATE


2번 노드에서 1건을 변경하면 해당 블록에 대한 XCUR 버퍼 및 CR 버퍼가 캐시에 적재됩니다. (그림-1 참조) 이때 발생하는 변경 사항은 아래의 테스트 결과 중간중간에 주석으로 설명해 두었습니다. (테스트 수행 전에 버퍼 캐시를 flush합니다)


그림-1. 2번 노드에서 1건 변경 후의 버퍼 캐시 변경 내용


-- 해당 블록은 로컬 및 리모트 캐시에 존재하지 않으므로 3번 노드의 LMS로부터 블록 액세스 권한을 부여 받습니다.
-- 이로 인해 'gc cr grant 2-way' 대기이벤트가 1회 발생합니다. 
 
-- 그런 후에, 싱글 블록 IO를 이용해서 해당 블록(File#=6, Block#=228)을 메모리로 적재합니다. 
-- 이때 'db file sequential read' 대기이벤트가 1회 발생합니다.
 
-- 해당 블록을 적재한 후에는 해당 블록을 변경하기 위한 CURRENT 권한을 부여 받아야합니다.
-- 이로 인해 'gc current grant 2-way' 대기이벤트가 1회 발생합니다.
 
-- 또한, 변경 작업을 위한 언두 블록을 할당 받기 위해 'db file sequential read' 대기이벤트가 2회 발생합니다.
-- 블록 덤프를 수행해보면 각각 언두 헤더 블록과 언두 블록임을 알 수 있습니다. 

SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_update1 

WAIT #140225505525552: nam='gc cr grant 2-way' ela= 1818 p1=6 p2=228 p3=1 obj#=93973 tim=394675630649
WAIT #140225505525552: nam='db file sequential read' ela= 2100 file#=6 block#=228 blocks=1 obj#=93973 tim=394675632854
WAIT #140225505525552: nam='gc current grant 2-way' ela= 3294 p1=6 p2=228 p3=33619969 obj#=93973 tim=394675636305
WAIT #140225505525552: nam='db file sequential read' ela= 3964 file#=5 block#=240 blocks=1 obj#=0 tim=394675640394
WAIT #140225505525552: nam='db file sequential read' ela= 1170 file#=5 block#=245 blocks=1 obj#=0 tim=394675641954

SYS@OOW2:2> alter system dump datafile 5 block 240;
frmt: 0x02 chkval: 0xbae3 type: 0x26=KTU SMU HEADER BLOCK

SYS@OOW2:2> alter system dump datafile 5 block 245;
frmt: 0x02 chkval: 0xfdae type: 0x02=KTU UNDO BLOCK

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요)

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [EVENT]  db file sequential read            3
                        gc cr grant 2-way                  1
                        gc current grant 2-way             1 						
               [STAT]   physical reads                     3
                        session logical reads              4

-- 2번 노드에 XCUR 버퍼 1개와 CR 버퍼 1개가 적재되었습니다.
-- 그리고 2번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되고 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다. 
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD4C9118      1 CR     00                        0 0000000074726000
     00007F79DD4C9298      1 XCUR   00000000753FD2B0          2 0000000074AE8000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000753FD338      1 KJUSEREX  GRANTED    00000000753FD2B0      1 XCUR
OOW3 00000000696DCCA8      1 KJUSEREX  GRANTED



3. 1번 노드에서 동일 블록 내의 다른 레코드 업데이트


1번 노드에서 동을 블록 내의 다른 레코드를 변경하면 2번 노드의 XCUR 버퍼는 PI 버퍼로 변경되고 1번 노드에 XCUR 버퍼가 적재됩니다. (그림-2 참조)


그림-2. 1번 노드에서 1건 변경 후의 버퍼 캐시 변경 내용


-- 해당 블록은 현재 변경 전 (COMMIT 전이므로 'busy'상태)입니다.
-- 따라서 'gc cr block busy' 대기이벤트가 1회 발생합니다. 

-- 해당 블록에 대한 변경 작업을 수행해야하므로 CURRENT 버퍼를 전송 받아야합니다.
-- 해당 블록의 마스터 노드는 3번 노드이고 현재 2번 노드에 존재하므로
-- 'gc cuurent block 3-way' 대기이벤트가 1회 발생합니다. 

-- 또한, 변경 작업을 위한 언두 블록을 할당 받기 위해 'db file sequential read' 대기이벤트가 2회 발생합니다.

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_update2 

WAIT #139902824629120: nam='gc cr block busy' ela= 10832 p1=6 p2=228 p3=1 obj#=93973 tim=334535308571
WAIT #139902824629120: nam='gc current block 3-way' ela= 4535 p1=6 p2=228 p3=33554433 obj#=93973 tim=334535313580
WAIT #139902824629120: nam='db file sequential read' ela= 3131 file#=4 block#=176 blocks=1 obj#=0 tim=334535317648
WAIT #139902824629120: nam='db file sequential read' ela= 2645 file#=4 block#=1738 blocks=1 obj#=0 tim=334535320442

WAIT #139902827416192: nam='gc cr block busy' ela= 5942 p1=6 p2=228 p3=1 obj#=93973 tim=421043266066
WAIT #139902827416192: nam='gc current block 3-way' ela= 3107 p1=6 p2=228 p3=33554433 obj#=93973 tim=421043269474
WAIT #140357041043368: nam='db file sequential read' ela= 3131 file#=4 block#=240 blocks=1 obj#=0 tim=421043270380
WAIT #139902827416192: nam='db file sequential read' ela= 3960 file#=4 block#=697 blocks=1 obj#=0 tim=421043274340

-- 1번 노드의 Foreground 프로세스는 CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송 받았음을 알 수 있습니다. 
-- 2번 노드의 LMS는 CR 버퍼를 1개 생성했고, XCUR 버퍼를 PI 버퍼로 변경하기 위해 
-- 'gc cr blocks flushed'를 1회 수행했습니다. 
-- 또한, CR 버퍼와 CURRENT 버퍼를 각각 1개씩 전송한 것을 알 수 있습니다.  

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  db file sequential read            2
                        gc cr block busy                   1
                        gc current block 3-way             1
               [STAT]   gc cr blocks received              1
                        gc current blocks received         1
                        physical reads                     2
                        session logical reads              4
      2 [LMS]  [STAT]   CR blocks created                  1
                        gc cr blocks flushed               1
                        gc cr blocks served                1
                        gc current blocks served           1
                        session logical reads              3

-- 2번 노드의 버퍼 상태가 XCUR에서 PI로 변경되었고, CR 버퍼가 1개 적재되었습니다.
-- 1번 노드에 XCUR 및 CR 버퍼가 1개씩 적재되었습니다.
-- 1번 노드의 GRD에 GCS 클라이언트가 1개 생성되었고, 3번 노드의 GRD에 GCS SHADOW가 1개 생성되었습니다.
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F80728C2FD0      1 CR     00                        0 000000007518A000
     00007F80728C3150      1 XCUR   00000000757E5958          1 00000000742A6000

OOW2 00007F79DD4FCB10      1 CR     00                        0 00000000749A0000
     00007F79DD4FCC90      1 PI     00000000753FD2B0          2 00000000745C0000
     00007F79DD4FCE10      1 CR     00                        0 000000007451A000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 00000000757E59E0      0 KJUSEREX  GRANTED    00000000757E5958      1 XCUR
OOW2 00000000753FD338      1 KJUSERNL  GRANTED    00000000753FD2B0      1 PI
OOW3 00000000696F1F18      0 KJUSEREX  GRANTED
OOW3 00000000696E4610      1 KJUSERNL  GRANTED


4. 3번 노드에서 동일 블록 내의 다른 레코드 업데이트


3번 노드에서 동일 블록 내의 다른 레코드를 변경하면 1번 노드의 XCUR 버퍼는 PI 버퍼로 변경되고 3번 노드에 XCUR 버퍼가 적재됩니다. (그림-3 참조) 이점은 2번 노드에서의 변경과 동일합니다. 하지만 한번 PI 버퍼가 생성된 이후에는 gc cr buffer busy 대기가 아닌 gc cr block 2-way 대기이벤트가 발생합니다. 이것은 이전 시점에 2번 노드의 LMS가 수행한 gc cr blocks flushed의 영향으로 파악됩니다. 그리고 1번, 2번 노드에서 수행한 트랜잭션과 관련된 언두 헤더 블록 및 언두 블록을 전송 받기 위해서 gc cr block 2-way 대기이벤트가 총 4회 발생했습니다.


그림-3. 3번 노드에서 1건 변경 후의 버퍼 캐시 변경 내용


-- 해당 블록 (p1=6 p2=228)에 대한 CR 버퍼와 CURRENT 버퍼를 전송 받는 과정에서 -- 'gc cr block 2-way'와 'gc current block 2-way' 대기이벤트가 각각 1회 발생합니다. -- 1번 노드에서 수행한 트랜잭션과 관련된 언두 헤더 블록 (p1=4 p2=240) -- 및 언두 블록 (p1=4 p2=697)에 대한 CR 버퍼를 전송 받는 과정에서 -- 'gc cr block 2-way' 대기이벤트가 2회 발생합니다. -- 2번 노드에서 수행한 트랜잭션과 관련된 언두 헤더 블록 (p1=5 p2=240) -- 및 언두 블록 (p1=5 p2=235)에 대한 CR 버퍼를 전송받는 과정에서 -- 'gc cr block 2-way' 대기이벤트가 2회 발생합니다. -- 해당 트랜잭션 수행을 위한 언두 헤더 블록과 언두 블록을 할당 받는 과정에서 -- 'db file sequential read' 대기이벤트가 2회 발생합니다. SCOTT@OOW1:1> @set_trace_on 10046 8 SCOTT@OOW1:1> @one_row_update3 WAIT #140357041043368: nam='gc cr block 2-way' ela= 2455 p1=6 p2=228 p3=1 obj#=93973 tim=394694643881 WAIT #140357041043368: nam='gc cr block 2-way' ela= 811 p1=4 p2=240 p3=31 obj#=0 tim=394694645290 WAIT #140357041043368: nam='gc cr block 2-way' ela= 1073 p1=5 p2=240 p3=51 obj#=0 tim=394694647769 WAIT #140357041043368: nam='gc cr block 2-way' ela= 3229 p1=4 p2=697 p3=32 obj#=0 tim=394694651686 WAIT #140357041043368: nam='gc cr block 2-way' ela= 1424 p1=5 p2=245 p3=52 obj#=0 tim=394694654291 WAIT #140357041043368: nam='gc current block 2-way' ela= 1088 p1=6 p2=228 p3=33554433 obj#=93973 tim=394694655965 WAIT #140357041043368: nam='db file sequential read' ela= 6037 file#=2 block#=128 blocks=1 obj#=0 tim=394694662551 WAIT #140357041043368: nam='db file sequential read' ela= 1904 file#=2 block#=2540 blocks=1 obj#=0 tim=394694665150 -- 1번 노드의 LMS가 3개의 CR 버퍼와 1개의 CURRENT 버퍼를 전송했습니다. -- 2번 노드의 LMS가 2개의 CR 버퍼를 전송했습니다. SYS@OOW1:1> @init_temp_sesstat 91 65 43 SYS@OOW1:1> @get_temp_sesstat 91 65 43 INST_ID SERVER FLAG NAME VALUE ------- ------ -------- ------------------------------ ----- 1 [LMS] [STAT] gc cr blocks served 3 gc current blocks served 1 session logical reads 3 2 [LMS] [STAT] gc cr blocks served 2 session logical reads 2 3 [FG] [EVENT] db file sequential read 2 gc cr block 2-way 5 gc current block 2-way 1 [STAT] gc cr blocks received 5 gc current blocks received 1 physical reads 2 session logical reads 10 -- 1번 노드의 버퍼 상태가 XCUR에서 PI로 변경되었습니다. -- 3번 노드에 XCUR 및 CR 버퍼가 1개씩 적재되었습니다. -- 3번 노드의 GRD에 GCS 클라이언트가 1개 생성되었습니다. SYS@OOW1:1> @fnd_gcs_detail2 6 228 X$BH X$BH X$BH X$BH INST ADDR CLASS STATE LE_ADDR TCH BA ---- ---------------- ------ ------ ---------------- ---------- ---------------- OOW1 00007F80724285B0 1 CR 00 0 000000007518A000 00007F8072428730 1 PI 00000000757E5958 1 00000000742A6000 OOW2 00007F79DD4D15F0 1 CR 00 0 00000000749A0000 00007F79DD4D1770 1 PI 00000000753FD2B0 2 00000000745C0000 00007F79DD4D18F0 1 CR 00 0 000000007451A000 OOW3 00007FBB2D4168B0 1 CR 00 0 00000000752A6000 00007FBB2D416A30 1 XCUR 00000000757E6AD8 1 000000007494E000 X$KJBL X$KJBL X$KJBL X$KJBL X$BH X$BH X$BH INST LOCKP OWNER GRANT LOCKST LE_ADDR CLASS STATE ---- ---------------- ------ --------- ---------- ---------------- ------ ------ OOW1 00000000757E59E0 0 KJUSERNL GRANTED 00000000757E5958 1 PI OOW2 00000000753FD338 1 KJUSERNL GRANTED 00000000753FD2B0 1 PI OOW3 00000000696E4610 1 KJUSERNL GRANTED OOW3 00000000696F1F18 0 KJUSERNL GRANTED OOW3 00000000757E6B60 2 KJUSEREX GRANTED 00000000757E6AD8 1 XCUR


이전: [캐시 퓨전 #3] 커밋된 블록 SELECT 시에 발생하는 gc cr/current block 2-way, 3-way 대기이벤트 및 _fairness_threshold 파라미터에 대한 이해
다음: [캐시 퓨전 #5] 커밋된 블록 UPDATE 시에 발생하는 gc cr/current block 2-way, 3-way 대기이벤트에 대한 이해

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

1. 테스트 개요


2번 노드에서 레코드 1건 (마스터 노드: 3번)을 변경한 후에 커밋을 수행합니다. 그런 후에 동일 레코드를 1번  및 3번 노드에서 반복적으로 조회합니다. 이를 통해, 커밋된 블록을 조회할 떄 발생하는 gc cr block 2-way, gc cr block 3-way, gc current block 2-way, gc current block 3-way 대기이벤트 및 _fairness_threshold 파라미터의 동작원리를 파악하도록 합니다.



2. 2번 노드에서 1건 UPDATE 및 COMMIT 수행


2번 노드에서 1건을 변경하면 해당 블록에 대한 XCUR 버퍼 및 CR 버퍼가 캐시에 적재됩니다. (그림-1 참조) 이때 발생하는 변경 사항은 아래의 테스트 결과 중간중간에 주석으로 설명해 두었습니다. (테스트 수행 전에 버퍼 캐시를 flush합니다)


그림-1. 2번 노드에서 1건 UPDATE 및 COMMIT 수행 후의 변경 내용


-- 해당 블록은 로컬 및 리모트 캐시에 존재하지 않으므로 3번 노드의 LMS로부터 블록 액세스 권한을 부여 받습니다.
-- 이로 인해 'gc cr grant 2-way' 대기이벤트가 1회 발생합니다. 
 
-- 그런 후에, 싱글 블록 IO를 이용해서 해당 블록(File#=6, Block#=228)을 메모리로 적재합니다. 
-- 이때 'db file sequential read' 대기이벤트가 1회 발생합니다.
 
-- 해당 블록을 적재한 후에는 해당 블록을 변경하기 위한 CURRENT 권하는 부여 받아야합니다.
-- 이로 인해 'gc current grant 2-way' 대기이벤트가 1회 발생합니다.
 
-- 또한, 변경 작업을 위한 언두 블록을 할당 받기 위해 'db file sequential read' 대기이벤트가 2회 발생합니다.
-- 블록 덤프를 수행해보면 각각 언두 헤더 블록과 언두 블록임을 알 수 있습니다. 

-- 마지막으로 커밋 수행에 따른 'log file sync' 대기이벤트가 1회 발생합니다. 

SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_update 
SCOTT@OOW2:2> commit; 

WAIT #140225502726824: nam='gc cr grant 2-way' ela= 2572 p1=6 p2=228 p3=1 obj#=93823 tim=291817361860
WAIT #140225502726824: nam='db file sequential read' ela= 5763 file#=6 block#=228 blocks=1 obj#=93823 tim=291817368044
WAIT #140225502726824: nam='gc current grant 2-way' ela= 4572 p1=6 p2=228 p3=33619969 obj#=93823 tim=291817374295
WAIT #140225502726824: nam='db file sequential read' ela= 1795 file#=5 block#=160 blocks=1 obj#=0 tim=291817376480
WAIT #140225502726824: nam='db file sequential read' ela= 2058 file#=5 block#=8099 blocks=1 obj#=0 tim=291817379029
WAIT #140225505518032: nam='log file sync' ela= 2549 buffer#=631 sync scn=12103377 p3=0 obj#=0 tim=291881847246

SYS@OOW2:2> alter system dump datafile 5 block 160;
frmt: 0x02 chkval: 0xbae3 type: 0x26=KTU SMU HEADER BLOCK

SYS@OOW2:2> alter system dump datafile 5 block 8099;
frmt: 0x02 chkval: 0xfdae type: 0x02=KTU UNDO BLOCK  '

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요)

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [EVENT]  db file sequential read            3
                        gc cr grant 2-way                  1
                        gc current grant 2-way             1						
               [STAT]   physical reads                     3
                        session logical reads              8

-- 2번 노드에 XCUR 버퍼 1개와 CR 버퍼 1개가 적재되었습니다.
-- 그리고 2번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되고 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다. 

SYS@OOW1:1> @fnd_gcs_detail2 6 228
 
                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD6859A8      1 CR     00                        0 0000000073474000
     00007F79DD685B28      1 XCUR   00000000737F7900          2 0000000074AFC000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000737F7988      1 KJUSEREX  GRANTED    00000000737F7900      1 XCUR
OOW3 0000000069716EA8      1 KJUSEREX  GRANTED


3. 1번 노드에서 해당 레코드 조회 (1회 수행)


1번 노드에서 동일한 레코드를 조회하면 1번 노드에 해당 블록에 대한 CR 버퍼가 버퍼 캐시에 적재됩니다. (그림-2 참조)


그림-2. 1번 노드에서 해당 레코드 1회 조회한 후의 버퍼 캐시 변경 내용


-- 해당 블록의 마스터 노드는 3번 노드이고 현재 2번 노드에 존재합니다.
-- 따라서 'gc cr block 3-way' 대기이벤트가 1회 발생합니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902907847544: nam='gc cr block 3-way' ela= 3504 p1=6 p2=228 p3=1 obj#=93823 tim=318327265441

-- 1번 노드의 Foreground 프로세스는 CR 버퍼를 1개 전송 받았음을 알 수 있습니다.
-- 2번 노드의 LMS는 CR 버퍼를 1번 노드로 전송한 것을 알 수 있습니다. 
-- 이때, 연재#2의 경우와 달리 LMS는 CR 버퍼를 생성하지 않습니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc cr block 3-way                  1	  
               [STAT]   gc cr blocks received              1
                        session logical reads              1						
      2 [LMS]  [STAT]   gc cr blocks served                1
                        session logical reads              1

-- 1번 노드에 CR 버퍼가 1개 적재되었습니다. 

SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072A9E478      1 CR     00                        1 00000000738D0000

OOW2 00007F79E2243540      1 CR     00                        0 000000007490C000
     00007F79E22436C0      1 XCUR   00000000737F7900          2 000000007396E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000737F7988      1 KJUSEREX  GRANTED    00000000737F7900      1 XCUR
OOW3 000000006971F698      1 KJUSEREX  GRANTED



4. 1번 노드에서 해당 레코드 조회 (2회 수행)


1번 노드에서 동일한 레코드를 한번 더 조회하면 1번 노드의 버퍼 캐시에는 CR 버퍼가 1개 적재됩니다. 그리고 2번 노드의 버퍼 상태가 XCUR에서 SCUR로 변경됩니다. (그림-3 참조) 2번 노드의 버퍼 상태가 SCUR로 변경되는 것은 _fairness_threshold 파라미터와 관련이 있습니다. 해당 파라미터의 설정 값은 버전에 따라 다르고 제 환경에서는 2입니다. 따라서 변경이 끝난 XCUR 버퍼를 2번 액세스하면 버퍼의 상태가 SCUR로 변경됩니다.


그림-3. 1번 노드에서 해당 레코드 2회 조회한 후의 버퍼 캐시 변경 내용


-- 1회 조회 시와 동일하게 'gc cr block 3-way' 대기이벤트가 1회 발생합니다.

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902907847544: nam='gc cr block 3-way' ela= 3470 p1=6 p2=228 p3=1 obj#=93823 tim=319239338492

-- 1회 조회 시와 동일합니다.

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc cr block 3-way                  1	  
               [STAT]   gc cr blocks received              1
                        session logical reads              1						
      2 [LMS]  [STAT]   gc cr blocks served                1
                        session logical reads              1

-- 1번 노드에 CR 버퍼 1개가 적재되었습니다.
-- 그리고 2번 노드의 버퍼 상태가 XCUR에 SCUR로 변경되었습니다. 
					
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072A485F8      1 CR     00                        1 00000000738D0000
     00007F8072A48778      1 CR     00                        1 000000007382C000

OOW2 00007F79E22436C0      1 CR     00                        0 000000007490C000
     00007F79E2243840      1 SCUR   00000000737F7900          2 000000007396E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000737F7988      1 KJUSERPR  GRANTED    00000000737F7900      1 SCUR
OOW3 000000006971F698      1 KJUSERPR  GRANTED



5. 1번 노드에서 해당 레코드 조회 (3회 수행)


1번 노드에서 동일한 레코드를 한번 더 조회하면 1번 노드의 버퍼 캐시에는 SCUR 버퍼가 1개 적재됩니다. (그림-4 참조)


그림-4. 1번 노드에서 해당 레코드 3회 조회한 후의 버퍼 캐시 변경 내용


-- SCUR 버퍼가 적재되므로 'gc cr block 3-way'가 아닌 'gc current block 3-way' 대기이벤트가 1회 발생합니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902907847544: nam='gc current block 3-way' ela= 3935 p1=6 p2=228 p3=1 obj#=93823 tim=319277179034

-- 1번 노드의 Foreground 프로세스는 CURRENT 버퍼를 1개 전송 받았음을 알 수 있습니다.
-- 2번 노드의 LMS는 CURRENT 버퍼를 1번 노드로 전송한 것을 알 수 있습니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc current block 3-way             1	  
               [STAT]   gc current blocks received         1
                        session logical reads              1						
      2 [LMS]  [STAT]   gc current blocks served           1

-- 1번 노드에 SCUR 버퍼 1개가 적재되었습니다.
-- 그리고 1번 노드의 GRD에 GCS 클라이언트가 1개 생성되고, 
-- 마스터 노드인 3번 노드의 GRD에 GCS SHADOW가 1개 생성되었습니다.

SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F807277ED78      1 CR     00                        1 00000000738D0000
     00007F807277EEF8      1 CR     00                        1 000000007382C000
     00007F807277F078      1 SCUR   00000000743ECD48          1 0000000073C74000

OOW2 00007F79E22436C0      1 CR     00                        0 000000007490C000
     00007F79E2243840      1 SCUR   00000000737F7900          2 000000007396E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 00000000743ECDD0      0 KJUSERPR  GRANTED    00000000743ECD48      1 SCUR
OOW2 00000000737F7988      1 KJUSERPR  GRANTED    00000000737F7900      1 SCUR
OOW3 0000000069722410      0 KJUSERPR  GRANTED
OOW3 000000006971F698      1 KJUSERPR  GRANTED



6. 1번 노드에서 해당 레코드 조회 (4회 수행)


1번 노드에도 SCUR 버퍼가 존재하므로, 해당 레코드를 조회하면 로컬 캐시에서 SCUR 버퍼를 읽습니다. 따라서 클러스터 및 IO 관련 대기이벤트 및 GRD 내의 변경은 발생하지 않습니다. 로컬 캐시에서 원하는 블록을 읽었으므로 메모리 IO가 1회 증가하고 해당 버퍼의 TCH가 2로 증가하는 정도의 변경만 발생합니다.


-- 클러스터 및 IO 관련 대기이벤트는 발생하지 않습니다.

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

-- 해당 버퍼에 대한 메모리 IO가 1회 발생합니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [STAT]   session logical reads              1

-- SCUR 버퍼에 대한 액세스로 인해 TCH가 2로 증가합니다.
	  
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F807277ED78      1 CR     00                        1 00000000738D0000
     00007F807277EEF8      1 CR     00                        1 000000007382C000
     00007F807277F078      1 SCUR   00000000743ECD48          2 0000000073C74000

OOW2 00007F79E22436C0      1 CR     00                        0 000000007490C000
     00007F79E2243840      1 SCUR   00000000737F7900          2 000000007396E000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 00000000743ECDD0      0 KJUSERPR  GRANTED    00000000743ECD48      1 SCUR
OOW2 00000000737F7988      1 KJUSERPR  GRANTED    00000000737F7900      1 SCUR
OOW3 0000000069722410      0 KJUSERPR  GRANTED
OOW3 000000006971F698      1 KJUSERPR  GRANTED



7. 3번 노드에서 해당 레코드 1회 조회


3번 노드에서 동일한 레코드를 조회하면 해당 블록에 대한 SCUR 버퍼가 버퍼 캐시에 적재됩니다. (그림-5 참조)


그림-5. 3번 노드에서 1건 조회 후의 버퍼 캐시 변경 내용


-- 3번 노드가 마스터 노드이고 CUURENT 블록을 전송 받으므로 
-- 'gc current block 2-way' 대기이벤트가 1회 발생합니다.

SCOTT@OOW3:3> @set_trace_on 10046 8
SCOTT@OOW3:3> @one_row_select 

WAIT #140357041936560: nam='gc current block 2-way' ela= 3478 p1=6 p2=228 p3=1 obj#=93973 tim=384133917366

-- 2번 노드의 LMS는 CURRENT 버퍼를 3번 노드로 전송한 것을 알 수 있습니다. 
-- 3번 노드의 Foreground 프로세스는 CURRENT 버퍼를 1개 전송 받았음을 알 수 있습니다.

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [LMS]  [STAT]   gc current blocks served           1
      3 [FG]   [EVENT]  gc current block 2-way             1
               [STAT]   gc current blocks received         1
                        session logical reads              1

-- 3번 노드에 SCUR 버퍼 1개가 적재되었습니다.
-- 그리고 3번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되었습니다.

SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072A48030      1 CR     00                        1 0000000074090000
     00007F8072A481B0      1 CR     00                        1 0000000074AEE000
     00007F8072A48330      1 SCUR   0000000074BE0868          2 0000000074752000

OOW2 00007F79DD4C9BE0      1 CR     00                        0 0000000073D54000
     00007F79DD4C9D60      1 SCUR   00000000737F7900          2 0000000072E8E000

OOW3 00007FBB31F8A7D8      1 SCUR   00000000743E5B88          1 0000000073E70000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 0000000074BE08F0      0 KJUSERPR  GRANTED    0000000074BE0868      1 SCUR
OOW2 00000000737F7988      1 KJUSERPR  GRANTED    00000000737F7900      1 SCUR
OOW3 00000000696D0390      0 KJUSERPR  GRANTED
OOW3 000000006972A570      1 KJUSERPR  GRANTED
OOW3 00000000743E5C10      2 KJUSERPR  GRANTED    00000000743E5B88      1 SCUR



7. 3번 노드에서 해당 레코드 조회 2회 조회


3번 노드에도 SCUR 버퍼가 존재하므로, 해당 레코드를 조회하면 로컬 캐시에서 SCUR 버퍼를 읽습니다. 따라서 클러스터 및 IO 관련 대기이벤트 및 GRD 내의 변경은 발생하지 않습니다. 로컬 캐시에서 원하는 블록을 읽었으므로 메모리 IO가 1회 증가하고 해당 버퍼의 TCH가 2로 증가하는 정도의 변경만 발생합니다.


-- 클러스터 및 IO 관련 대기이벤트는 발생하지 않습니다.

SCOTT@OOW3:3> @set_trace_on 10046 8
SCOTT@OOW3:3> @one_row_select 

-- 해당 버퍼에 대한 메모리 IO가 1회 발생합니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      3 [FG]   [STAT]   session logical reads              1

-- SCUR 버퍼에 대한 액세스로 인해 TCH가 2로 증가합니다.
	  
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F807277E4E8      1 CR     00                        1 0000000074090000
     00007F807277E668      1 CR     00                        1 0000000074AEE000
     00007F807277E7E8      1 SCUR   0000000074BE0868          2 0000000074752000

OOW2 00007F79DD4C9BE0      1 CR     00                        0 0000000073D54000
     00007F79DD4C9D60      1 SCUR   00000000737F7900          2 0000000072E8E000

OOW3 00007FBB31F8AAD8      1 SCUR   00000000743E5B88          2 0000000073E70000


     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 0000000074BE08F0      0 KJUSERPR  GRANTED    0000000074BE0868      1 SCUR
OOW2 00000000737F7988      1 KJUSERPR  GRANTED    00000000737F7900      1 SCUR
OOW3 00000000696D0390      0 KJUSERPR  GRANTED
OOW3 000000006972A570      1 KJUSERPR  GRANTED
OOW3 00000000743E5C10      2 KJUSERPR  GRANTED    00000000743E5B88      1 SCUR


 

이전: [캐시 퓨전 #2] 변경중인 블록 SELECT 시에 발생하는 gc cr block busy 대기이벤트 및 _db_block_max_cr_dba 파라미터에 대한 이해

다음: [캐시 퓨전 #4] 변경된 블록 UPDATE 시에 발생하는 gc cr block busy, gc cr/current block 2-way, 3way 대기이벤트에 대한 이해

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

1. 테스트 개요


2번 노드에서 레코드 1건 (마스터 노드: 3번)을 변경한 후에 1번 및 3번 노드에서 동일 레코드를 각각 7번 조회합니다. 이를 통해 변경 중인 블록을 조회할 때 발생하는 대기이벤트와 성능 지표를 살펴보고 버퍼 캐시 및 GRD의 변경 내용을 확인합니다. 그리고 _db_block_max_cr_dba 파라미터의 동작원리 또한 파악하도록 합니다.



2. 2번 노드에서 1건 UPDATE


2번 노드에서 1건을 변경하면 해당 블록에 대한 XCUR 버퍼 및 CR 버퍼가 캐시에 적재됩니다. (그림-1 참조) 이때 발생하는 변경 사항은 아래의 테스트 결과 중간중간에 주석으로 설명해 두었습니다. (테스트 수행 전에 버퍼 캐시를 flush합니다)


그림-1. 2번 노드에서 1건 변경 후의 버퍼 캐시 변경 내용


-- 해당 블록은 로컬 및 리모트 캐시에 존재하지 않으므로 3번 노드의 LMS로부터 블록 액세스 권한을 부여 받습니다.
-- 이로 인해 'gc cr grant 2-way' 대기이벤트가 1회 발생합니다. 

-- 그런 후에, 싱글 블록 IO를 이용해서 해당 블록(File#=6, Block#=228)을 메모리로 적재합니다. 
-- 이때 'db file sequential read' 대기이벤트가 1회 발생합니다.

-- 해당 블록을 적재한 후에는 해당 블록을 변경하기 위한 CURRENT 권한을 부여 받아야합니다.
-- 이로 인해 'gc current grant 2-way' 대기이벤트가 1회 발생합니다.

-- 또한, 변경 작업을 위한 언두 블록을 할당 받기 위해 'db file sequential read' 대기이벤트가 2회 발생합니다.
-- 블록 덤프를 수행해보면 각각 언두 헤더 블록과 언두 블록임을 알 수 있습니다. 
 
SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_update 

WAIT #140225505518032: nam='gc cr grant 2-way' ela= 1913 p1=6 p2=228 p3=1 obj#=93823 tim=294714258816
WAIT #140225505518032: nam='db file sequential read' ela= 1918 file#=6 block#=228 blocks=1 obj#=93823 tim=294714261240
WAIT #140225505518032: nam='gc current grant 2-way' ela= 2213 p1=6 p2=228 p3=33619969 obj#=93823 tim=294714263898
WAIT #140225505518032: nam='db file sequential read' ela= 2029 file#=5 block#=144 blocks=1 obj#=0 tim=294714268613
WAIT #140225505518032: nam='db file sequential read' ela= 1150 file#=5 block#=1796 blocks=1 obj#=0 tim=294714270377
 
SYS@OOW2:2> alter system dump datafile 5 block 144;
frmt: 0x02 chkval: 0xbae3 type: 0x26=KTU SMU HEADER BLOCK 

SYS@OOW2:2> alter system dump datafile 5 block 1796;
frmt: 0x02 chkval: 0xfdae type: 0x02=KTU UNDO BLOCK 

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요)

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [EVENT]  db file sequential read            3
                        gc cr grant 2-way                  1
                        gc current grant 2-way             1						
               [STAT]   physical reads                     3
                        session logical reads              4

-- 2번 노드에 XCUR 버퍼 1개와 CR 버퍼 1개가 적재되었습니다.
-- 그리고 2번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되고 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다. 
 						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD4C4F08      1 CR     00                        0 00000000734C2000
     00007F79DD4C5088      1 XCUR   00000000733E2EB0          2 000000007513A000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSEREX  GRANTED    00000000733E2EB0      1 XCUR
OOW3 00000000696D70C8      1 KJUSEREX  GRANTED



3. 1번 노드에서 해당 레코드 조회 (1회 수행)


1번 노드에서 동일한 레코드를 조회하면 1번 노드 및 2번 노드에 해당 블록에 대한 CR 버퍼가 버퍼 캐시에 적재됩니다. (그림-2 참조)


그림-2. 1번 노드에서 1건 조회 후의 버퍼 캐시 변경 내용


-- 해당 블록은 현재 변경 전 (COMMIT 전이므로 'busy'상태)입니다.
-- 따라서 'gc cr block busy' 대기이벤트가 1회 발생합니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902907847544: nam='gc cr block busy' ela= 18363 p1=6 p2=228 p3=1 obj#=93823 tim=311836140232

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

-- 1번 노드의 Foreground 프로세스는 CR 버퍼를 1개 전송 받았음을 알 수 있습니다.
-- 2번 노드의 LMS는 CR 버퍼를 1개 생성한 후에 1번 노드로 해당 버퍼를 전송한 것을 알 수 있습니다. 

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc cr block busy                   1
               [STAT]   gc cr blocks received              1
                        session logical reads              1
      2 [LMS]  [STAT]   CR blocks created                  1
                        gc cr blocks flushed               1
                        gc cr blocks served                1
                        session logical reads              3

-- 1번 노드와 2번 노드에 CR 버퍼가 각각 1개씩 더 적재되었습니다. 
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072037AC8      1 CR     00                        1 0000000074298000

OOW2 00007F79DD69C000      1 CR     00                        0 00000000734C2000
     00007F79DD69C180      1 XCUR   00000000733E2EB0          2 000000007513A000
     00007F79DD69C300      1 CR     00                        0 000000007545E000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSEREX  GRANTED    00000000733E2EB0      1 XCUR
OOW3 00000000696D70C8      1 KJUSEREX  GRANTED



4. 1번 노드에서 해당 레코드 조회 (6회 수행)


해당 레코드를 6회 반복해서 조회하면 1, 2번 모두 6개의 CR 버퍼가 적재됩니다. (그림-3 참조) 즉, 'busy'한 블록을 반복적으로 조회하면 조회할 때마다 CR 버퍼가 적재되고, 최대 값은 _db_block_max_cr_dba 파라미터에 의해 결정됩니다. 해당 파라미터의 기본 설정 값은 6이므로 최대 6개의 CR 버퍼가 적재된 것을 알 수 있습니다.


그림-3. 1번 노드에서 6번 조회 후의 버퍼 캐시 변경 내용



-- 해당 블록은 현재 변경 전 (COMMIT 전이므로 'busy'상태)입니다.
-- 따라서 'gc cr block busy' 대기이벤트가 1회 발생합니다. 
 
SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902907847544: nam='gc cr block busy' ela= 4052 p1=6 p2=228 p3=1 obj#=93823 tim=311885751211

-- 이전과 동일하게 2번 노드의 LMS는 CR 버퍼를 1개 생성한 후 1번 노드로 전송한 것을 알 수 있습니다.

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc cr block busy                   1
               [STAT]   gc cr blocks received              1
                        session logical reads              1
      2 [LMS]  [STAT]   CR blocks created                  1
                        gc cr blocks flushed               1
                        gc cr blocks served                1
                        session logical reads              3

-- 1,2번 노드 각각 6개의 CR 버퍼가 적재되었습니다. 
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F80720374A8      1 CR     00                        1 0000000073D70000
     00007F8072037648      1 CR     00                        1 0000000074034000
     00007F80720377C8      1 CR     00                        1 0000000074274000
     00007F8072037948      1 CR     00                        1 0000000074CD0000
     00007F8072037AC8      1 CR     00                        1 00000000739E8000
     00007F807236C5A0      1 CR     00                        1 0000000074298000

OOW2 00007F79DD69BA00      1 XCUR   00000000733E2EB0          2 000000007513A000
     00007F79DD69BB80      1 CR     00                        0 000000007545E000
     00007F79DD69BD00      1 CR     00                        0 0000000075772000
     00007F79DD69BE80      1 CR     00                        0 0000000072EB4000
     00007F79DD69C000      1 CR     00                        0 0000000075038000
     00007F79DD69C180      1 CR     00                        0 00000000734C2000
     00007F79DD69C300      1 CR     00                        0 0000000073194000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSEREX  GRANTED    00000000733E2EB0      1 XCUR
OOW3 00000000696D70C8      1 KJUSEREX  GRANTED



5. 1번 노드에서 해당 레코드 조회 (7회 수행)


그렇다면, 해당 레코드를 7번쨰 조회할 경우에는 어떤 변화가 발생하는지 확인해보겠습니다.

-- 여전히, 'gc cr block busy' 대기이벤트가 발생합니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select

WAIT #139902907847544: nam='gc cr block busy' ela= 7971 p1=6 p2=228 p3=1 obj#=93823 tim=311953030887

-- 여전히, 2번 노드의 LMS는 CR 버퍼를 1개 생성한 후 1번 노드로 전송합니다. 
-- 이를 통해, _db_block_max_cr_dba 파라미터는 CR 버퍼의 생성과 관련된 것이 아니라
-- CR 버퍼의 적재 개수와 관련된 것임을 알 수 있습니다.

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  gc cr block busy                   1
               [STAT]   gc cr blocks received              1
                        session logical reads              1
      2 [LMS]  [STAT]   CR blocks created                  1
                        gc cr blocks flushed               1
                        gc cr blocks served                1
                        session logical reads              3

-- 버퍼 캐시내의 큰 변화는 없습니다. 즉, 여전히 CR 버퍼의 개수는 6개입니다.
-- 다만, 새로운 CR 버퍼가 1개 적재되었고 기존의 CR 버퍼 1개는 aged out 되었음을 알 수 있습니다. 			
			
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F80728A21E8      1 CR     00                        1 0000000074034000
     00007F8072A48158      1 CR     00                        1 0000000074274000
     00007F8072A482F8      1 CR     00                        1 0000000074CD0000
     00007F8072A48478      1 CR     00                        1 00000000739E8000
     00007F8072A485F8      1 CR     00                        1 0000000074298000
     00007F8072A48778      1 CR     00                        1 0000000073D70000

OOW2 00007F79DD4C4788      1 XCUR   00000000733E2EB0          2 000000007513A000
     00007F79DD4C4908      1 CR     00                        0 0000000072EB4000
     00007F79DD4C4A88      1 CR     00                        0 0000000075038000
     00007F79DD4C4C08      1 CR     00                        0 00000000734C2000
     00007F79DD4C4D88      1 CR     00                        0 0000000073194000
     00007F79DD4C4F08      1 CR     00                        0 000000007545E000
     00007F79DD4C5088      1 CR     00                        0 0000000075772000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSEREX  GRANTED    00000000733E2EB0      1 XCUR
OOW3 00000000696D70C8      1 KJUSEREX  GRANTED

3번 노드에서 동일한 테스트를 수행한 결과, GCS SHADOW가 생성되지 않다는 점을 제외하면 1번 노드의 테스트 결과와 동일합니다. 따라서 설명은 생략합니다. 


이전: [캐시 퓨전 #1] SELECT 시에 발생하는 gc cr grant 2-way 대기이벤트에 대한 이해
다음: [캐시 퓨전 #3] 커밋된 블록 SELECT 시에 발생하는 gc cr/current block 2-way, 3-way 대기이벤트 및 _fairness_threshold 파라미터에 대한 이해



 

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

이번 시간에 살펴볼 내용은 캐시 퓨전 시에 발생하는 클러스터 관련 대기이벤트들 및 이와 연관된 성능 지표들의 변경사항, 그리고 버퍼 캐시 내의 버퍼 상태 및 GRD의 변경 사항들입니다. 테스트를 위해 10046 트레이스, V$SESSTAT, X$BH, X$KJBL Fixed 테이블을 이용했습니다. 연재 순서는 다음과 같습니다.


[캐시 퓨전 #1] SELECT 시에 발생하는 gc cr grant 2-way 대기이벤트에 대한 이해


테스트 환경 : Oracle 12.1.0.2 (64bits) 3 노드 RAC


1. 테스트 개요


2번 노드에서 레코드 1건 (마스터노드: 3번)을 조회한 후에 1번 및 3번 노드에서 동일 레코드를 각각 조회합니다. 테스트의 편의성을 위해 인덱스를 생성하지 않고 해당 레코드의 ROWID를 이용해서 조회하며, 조회 시에 발생하는 대기이벤트와 성능지표를 살펴보고 버퍼 캐시 및 GRD의 변경 내용을 확인합니다.



2. 초기 환경 SETUP


-- 테스트 테이블 생성 및 데이터 입력

SCOTT@OOW1:1> drop table t1 purge;
SCOTT@OOW1:1> create table t1 (c1 number, c2 number);
SCOTT@OOW1:1> insert into t1 select level, level from dual connect by level<=10000;
SCOTT@OOW1:1> commit;
SCOTT@OOW1:1> exec dbms_stats.gather_table_stats(user,'T1');

--C1=1에 대한 블록 마스터 노드가 OOW3 (KJBRMASTER=2)임을 확인

SCOTT@OOW1:1> @fnd_blk_master T1 1

        C1     OBJ_NO    FILE_NO     BLK_NO
---------- ---------- ---------- ----------
         1      93823          6        228

       X$BH X$KJBR                                                       X$KJBR
INST  CLASS NAME                           KJBLNAME2       KJBRGRANT     MASTER
---- ------ ------------------------------ --------------- --------- ----------
OOW3      1 [0xe4][0x6],[BL][ext 0x0,0x0]  228,6,BL        KJUSEREX           2

-- 모든 노드에서 buffer cache flush 수행 

SYS@OOW1:1> alter system flush buffer_cache;
SYS@OOW2:2> alter system flush buffer_cache;
SYS@OOW3:3> alter system flush buffer_cache;



3. 2번 노드에서 1건 조회


2번 노드에서 1건을 조회하면 해당 블록에 대한 SCUR 버퍼가 버퍼 캐시에 적재됩니다. (그림-1 참조) 이때 발생하는 변경 사항은 아래의 테스트 결과 중간중간에 주석으로 설명해 두었습니다.


그림-1. 2번 노드에서 1건 조회 후의 버퍼 캐시 변경 내용


-- 해당 블록은 로컬 및 리모트 버퍼 캐시에 존재하지 않으므로 3번 노드의 LMS로부터 블록 액세스 권한을 부여 받습니다. 
-- 이로 인해 'gc cr grant 2-way' 대기이벤트가 1회 발생합니다. 
-- 그런 후에, 싱글 블록 IO를 이용해서 해당 블록(File#=6, Block#=228)을 메모리로 적재합니다. 
-- 이때 'db file sequential read' 대기이벤트가 1회 발생합니다.
 
SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_select 

WAIT #140225505500112: nam='gc cr grant 2-way' ela= 1991 p1=6 p2=228 p3=1 obj#=93696 tim=282496042645
WAIT #140225505500112: nam='db file sequential read' ela= 4141 file#=6 block#=228 blocks=1 obj#=93696 tim=282496046954

-- 10046 트레이스에서 확인한 것과 동일한 대기이벤트 정보를 확인할 수 있습니다. 
-- 더불어 DISK IO 1회, 메모리 IO 1회가 발생한 것을 알 수 있습니다.

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [EVENT]  db file sequential read            1
                        gc cr grant 2-way                  1
               [STAT]   physical reads                     1
                        session logical reads              1

-- 2번 노드에 SCUR 버퍼가 1개 적재되었습니다. 
-- 그리고 2번 노드의 GRD에 GCS 클라이언트 (락 엘리먼트 존재)가 1개 생성되고 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다. 
				
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD4F7A60      1 SCUR   00000000733E2EB0          1 00000000738EC000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSERPR  GRANTED    00000000733E2EB0      1 SCUR
OOW3 00000000696EB438      1 KJUSERPR  GRANTED



4. 2번 노드에서 1번 더 조회


2번 노드에서 동일한 레코드를 1번 더 조회할 경우에는 로컬 캐시에서 해당 블록을 읽게 됩니다. 따라서 클러스터 및 IO 관련 대기이벤트 및 GRD 내의 변경은 발생하지 않습니다. 로컬 캐시에서 원하는 블록을 읽었으므로 메모리 IO가 1회 증가하고 해당 버퍼의 TCH가 2로 증가하는 정도의 변경만 발생합니다.


-- 클러스터 및 IO 관련 대기이벤트는 발생하지 않습니다.

SCOTT@OOW2:2> @set_trace_on 10046 8
SCOTT@OOW2:2> @one_row_select 

-- 해당 버퍼에 대한 메모리 IO가 1회 발생합니다. 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      2 [FG]   [STAT]   session logical reads              1

-- 해당 버퍼에 대한 액세스로 인해 TCH가 2로 증가합니다.
	  
SYS@OOW1:1> @fnd_gcs_detail 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW2 00007F79DD4FAC58      1 SCUR   00000000733E2EB0          2 0000000073922000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW2 00000000733E2F38      1 KJUSERPR  GRANTED    00000000733E2EB0      1 SCUR
OOW3 00000000696D44B8      1 KJUSERPR  GRANTED

5. 1번 노드에서 조회


1번 노드에서 동일한 레코드를 조회하면 해당 블록에 대한 SCUR 버퍼가 버퍼 캐시에 적재됩니다. (그림-2 참조) 캐시 퓨전을 설명한 문서들을 보면 이러한 경우에는 해당 블록은 캐시 퓨전을 통해서 리모트 캐시(2번 노드)에서 전송 받고, 이로 인해 'gc current block 2/3 way' 대기이벤트가 발생하는 것으로 되어있습니다만, 테스트 결과는 조금 다릅니다. 이러한 차이는 테스트 환경 (버전 또는 buffer cache flush 여부 등)의 차이라고 보여집니다.


그림-2. 1번 노드에서 1건 조회 후의 버퍼 캐시 변경 내용


-- 2번 노드와 동일한 결과를 나타냅니다. 

SCOTT@OOW1:1> @set_trace_on 10046 8
SCOTT@OOW1:1> @one_row_select 

WAIT #139902827437888: nam='gc cr grant 2-way' ela= 4187 p1=6 p2=228 p3=1 obj#=93696 tim=309078519225
WAIT #139902827437888: nam='db file sequential read' ela= 6589 file#=6 block#=228 blocks=1 obj#=93696 tim=309078528563

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요) 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      1 [FG]   [EVENT]  db file sequential read            1
                        gc cr grant 2-way                  1
               [STAT]   physical reads                     1
                        session logical reads              1

-- 1번 노드에 SCUR 버퍼가 1개 적재되었습니다. 
-- 그리고 2번 노드의 GRD에 GCS 클라이언트가 1개 생성되고, 
-- 마스터 노드인 3번 노드에 GCS SHADOW가 1개 생성되었습니다.
 						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F80726712D0      1 SCUR   00000000747F19D8          1 00000000750EE000
OOW2 00007F79E2242F58      1 SCUR   00000000733E2EB0          0 0000000074940000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 00000000747F1A60      0 KJUSERPR  GRANTED    00000000747F19D8      1 SCUR
OOW2 00000000733E2F38      1 KJUSERPR  GRANTED    00000000733E2EB0      1 SCUR
OOW3 00000000697216F0      1 KJUSERPR  GRANTED
OOW3 00000000696CDD20      0 KJUSERPR  GRANTED


6. 3번 노드에서 조회


3번 노드에서 동일한 레코드를 조회하면 해당 블록에 대한 SCUR 버퍼가 버퍼 캐시에 적재됩니다. (그림-3 참조)


그림-3. 3번 노드에서 1건 조회 후의 버퍼 캐시 변경 내용


-- 3번 노드가 마스터 노드이므로 GRANT 수행 없이 싱글 블록 IO를 이용해서 버퍼에 적재합니다.
-- 따라서 'gc cr grant 2-way' 대기 없이 'db file sequential' 대기이벤트만 1회 발생합니다.

SCOTT@OOW3:3> @set_trace_on 10046 8
SCOTT@OOW3:3> @one_row_select 

WAIT #140357040867896: nam='db file sequential read' ela= 4382 file#=6 block#=228 blocks=1 obj#=93696 tim=282758433936

-- V$SESSTAT 뷰의 변경 사항 (참고만 하세요) 

SYS@OOW1:1> @init_temp_sesstat 91 65 43
SYS@OOW1:1> @get_temp_sesstat  91 65 43

INST_ID SERVER FLAG     NAME                           VALUE
------- ------ -------- ------------------------------ -----
      3 [FG]   [EVENT]  db file sequential read            1
               [STAT]   physical reads                     1
                        session logical reads              1						

-- 3번 노드에 SCUR 버퍼가 1개 적재되었습니다. 
-- 3번 노드가 마스터 노드이므로 GCS SHADOW는 생성되지 않고 GCS 클라이언트만 1개 생성되었습니다. 
						
SYS@OOW1:1> @fnd_gcs_detail2 6 228

                        X$BH X$BH   X$BH                   X$BH
INST ADDR              CLASS STATE  LE_ADDR                 TCH BA
---- ---------------- ------ ------ ---------------- ---------- ----------------
OOW1 00007F8072671870      1 SCUR   00000000747F19D8          1 0000000075744000
OOW2 00007F79DD4C9298      1 SCUR   00000000733E2EB0          1 0000000073418000
OOW3 00007FBB31F831B0      1 SCUR   00000000757DC498          1 0000000072E32000

     X$KJBL           X$KJBL X$KJBL    X$KJBL     X$BH               X$BH X$BH
INST LOCKP             OWNER GRANT     LOCKST     LE_ADDR           CLASS STATE
---- ---------------- ------ --------- ---------- ---------------- ------ ------
OOW1 00000000747F1A60      0 KJUSERPR  GRANTED    00000000747F19D8      1 SCUR
OOW2 00000000733E2F38      1 KJUSERPR  GRANTED    00000000733E2EB0      1 SCUR
OOW3 0000000069715DC8      1 KJUSERPR  GRANTED
OOW3 00000000697273C0      0 KJUSERPR  GRANTED
OOW3 00000000757DC520      2 KJUSERPR  GRANTED    00000000757DC498      1 SCUR


다음: [캐시 퓨전 #2] 변경중인 블록 SELECT 시에 발생하는 gc cr block busy 대기이벤트 및 _db_block_max_cr_dba 파라미터에 대한 이해

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

GCS (Glocal Cache Service)와 관련된 인터널 문서를 읽다보면 GCS SHADOW란 용어를 접하게 됩니다. 하지만 GCS SHADOW의 명확한 동작원리에 대해서 언급한 문서를 찾기가 힘듭니다. 그나마 Juian Dyke의 2008년도 PDF 문서에 다음과 같은 정의와 구성도를 확인할 수 있습니다.


"GCS Shadow describes blocks held by other instances, but mastered locally" [Julian Dyke]


그림-1. GCS 메모리 구성도 (참조문헌: Julian Dyke PDF)


즉, GCS SHADOW란 마스터에 속한 블록을 다른 노드에서 사용할때 이를 표현하는 구조체입니다. (설명이 조금 어렵죠?) 그리고 "그림-1"에서 보여지는 것처럼 GCS SHADOW는 락 엘리먼트를 가지고 있지 않습니다. 그런데 이 설명과 그림만으로는 GCS SHADOW를 정확히 이해하기는 어렵습니다. (적어도 저의 경우는 그랬습니다) 그렇다면 GCS SHADOW는 어떻게 동작하고 어떤 목적으로 사용될까요? 이를 분석하기 위해 테스트를 진행한 결과를 다음과 같이 정리합니다.



1. GCS SHADOW의 동작 원리 및 목적


1-1. GCS SHADOW의 동작 원리

  1. 마스터 노드에서 해당 블록을 액세스할 경우에는 GCS CLIENT가 1개 생성되고 GCS SHADOW는 생성되지 않습니다.
  2. 리모트 노드에서 해당 블록을 액세스할 경우에는 리모트 노드에 GCS CLIENT가 1개 생성되고, 마스터 노드에는 이와 관련된 GCS SHADOW가 1개 생성됩니다. 여러 개의 리모트 노드에서 해당 블록을 액세스한다면 리모트 노드 개수만큼의 GCS SHADOW가 마스터 노드에 생성됩니다.
Note
설명의 편의성을 위해 GCS CLIENT와 GCS SHADOW로 나누었으나, 오라클 내부적으로는 모두 GCS SHADOW로 관리됩니다. GCS CLIENT는 락 엘리먼트가 있는 GCS 구조체 (X$KJBL내에 생성됨)이고 GCS SHADOW는 락 엘리먼트가 없는 GCS 구조체라고 이해하시면 좋습니다. 개인적인 생각이지만 오라클은 용어 및 약어 선정을 아주 잘하는 회사인것 같습니다. GCS SHADOW란 용어도 알고 보면 아주 적절한 용어라고 보입니다. 즉, 그림자와 같이 형체(X$KJBL 구조체)는 동일하지만 알맹이(락 엘리먼트)는 없는 것을 잘 표현하고 있습니다.


그런데 여기서 의문점이 하나 생기게됩니다. "오라클은 이러한 중복 관리를 부하를 감수하면서도 GCS SHADOW를 사용할까?"라는 것이죠. 예를 들어, 마스터 노드의 블록들을 리모트 노드에서 대량으로 액세스하게 되면, 마스터 노드에는 블록 개수만큼의 GCS SHADOW 구조체를 shared pool의 gcs shadow 영역에 생성해야하는 부하가 발생하게 됩니다. 이와 같은 오퍼레이션은 CPU 및 shared pool 사용 측면에서 모두 부하를 유발하게 됩니다. 그렇다면 왜 필요한걸까요?


1-2. GCS SHADOW의 목적
테스트를 통해 추론된 결론은 "GCS SHADOW의 목적은 마스터 노드에 속한 블록들의 사용 노드를 확인하기 위한 것"입니다. 그림-2~그림-4를 보시면 쉽게 이해될것 같습니다.


그림-2. 초기 상태


그림-3. RAC3 노드에서 UPDATE 수행  


그림-4. RAC2번 노드에서 SELECT 수행

Note
해당 블록의 마스터 노드는 OOW1이므로 OOW1의 GCS 리소스 구조체를 접근한 후, 해당 구조에 아래 딸린 GCS CLIENT/SHADOW 구조체를 확인합니다. 확인 결과, GCS SHADOW의 정보를 통해 해당 블록은 현재 3번 노드에 있다는 사실을 알 수 있습니다. 이와 같이 GCS SHADOW는 마스터 블록의 사용 노드를 확인하기 위한 용도로 사용된다고 할 수 있습니다. 


이러한 결론을 이끌어냈던 테스트 방법에 대해서 자세히 살펴보도록 하겠습니다.



2. GCS SHADOW의 동작원리 분석을 위한 테스트 내역


2-1. 테스트 데이터 생성

SCOTT @ OOW1 > drop table t1 purge;
SCOTT @ OOW1 > create table t1 (c1 number, dummy char(10));
SCOTT @ OOW1 > insert into t1 select level, level from dual connect by level<=10000;
SCOTT @ OOW1 > commit;
SCOTT @ OOW1 > create index t1_idx01 on t1(c1) nologging;
SCOTT @ OOW1 > exec dbms_stats.gather_table_stats(user,'T1');


2-2. 초기 상태 확인

-- 레코드 1건 조회

SCOTT @ OOW1 > select /*+ index(t1 t1_idx01) */
       count(*),
       max(dbms_rowid.rowid_relative_fno(rowid)) file_no,
       max(dbms_rowid.rowid_block_number(rowid)) blk_no
from   t1
where  c1=1
and    dummy <> '9999';

-- 해당 레코드가 속한 블록의 마스터 노드 확인 (마스터 노드가 0번 즉, OOW1번 노드임을 확인)

SCOTT @ OOW1 > @fnd_blk_master T1 1

        C1     OBJ_NO    FILE_NO     BLK_NO
---------- ---------- ---------- ----------
         1      93240          8        134

INST      CLASS KJBRNAME                       KJBLNAME2       KJBRGRANT KJBRMASTER
---- ---------- ------------------------------ --------------- --------- ----------
OOW1          1 [0x86][0x8],[BL][ext 0x0,0x0]  134,8,BL        KJUSEREX           0


2-3. OOW3 노드에서 UPDATE 수행 후의 변경 사항 확인

-- 테스트의 편의성을 위해 모든 노드에서 alter system flush buffer cache 수행 후 3번 노드에서 update 수행

SCOTT @ OOW3 > update  t1 set c1=-1 where c1=1;

-- 결과 확인
 
SCOTT @ OOW1 > @fnd_gcs_detail 8 134

                            X$BH X$BH       X$BH                   X$BH
INST ADDR                  CLASS STATE      LE_ADDR                 TCH
---- ---------------- ---------- ---------- ---------------- ----------
OOW3 00007F37A4573068          1 XCUR       0000000072FF5948          1

     X$KJBR               X$KJBR X$KJBR
INST RESP                 MASTER NAME
---- ---------------- ---------- ------------------------------
OOW1 000000006946A358          0 [0x86][0x8],[BL][ext 0x0,0x0]

     X$KJBL               X$KJBL X$KJBL    X$KJBL     X$BH                   X$BH X$BH
INST LOCKP                 OWNER GRANT     LOCKST     LE_ADDR               CLASS STATE
---- ---------------- ---------- --------- ---------- ---------------- ---------- ----------
OOW1 0000000069722CF8          2 KJUSEREX  GRANTED
OOW3 0000000072FF59D0          2 KJUSEREX  GRANTED    0000000072FF5948          1 XCUR


결과분석
1. 3번 노드에 XCUR 버퍼 1개 할당
2. 해당 블록의 마스터 노드는 0번 (즉, OOW1)임을 재확인
3. 3번 노드에 GCS CLIENT 1개 생성. 그리고 1번 노드에 GCS SHADOW 1개 생성됨


2-4. OOW2 노드에서 SELECT 수행 후의 변경 사항 확인

-- 2번 노드에서 SELECT 수행 

SCOTT @ OOW2 > select * from t1 where c1=2;

-- 결과 확인
 
SCOTT @ OOW1 > @fnd_gcs_detail 8 134

                            X$BH X$BH       X$BH                   X$BH
INST ADDR                  CLASS STATE      LE_ADDR                 TCH
---- ---------------- ---------- ---------- ---------------- ----------
OOW2 00007F6A25D42AD8          1 CR         00                        1

OOW3 00007F37A4572EE8          1 XCUR       0000000072FF5948          1
     00007F37A4573068          1 CR         00                        0

     X$KJBR               X$KJBR X$KJBR
INST RESP                 MASTER NAME
---- ---------------- ---------- ------------------------------
OOW1 000000006946A358          0 [0x86][0x8],[BL][ext 0x0,0x0]

     X$KJBL               X$KJBL X$KJBL    X$KJBL     X$BH                   X$BH X$BH
INST LOCKP                 OWNER GRANT     LOCKST     LE_ADDR               CLASS STATE
---- ---------------- ---------- --------- ---------- ---------------- ---------- ----------
OOW1 0000000069722CF8          2 KJUSEREX  GRANTED
OOW3 0000000072FF59D0          2 KJUSEREX  GRANTED    0000000072FF5948          1 XCUR


결과분석
1. 3번 노드의 XCUR 버퍼를 1개 복사해서 새로운 XCUR 버퍼 할당. 기존 XCUR 버퍼는 CR 버퍼로 락 다운그레이드됨 (ADDR로 확인)
2. 2번 노드에 CR 버퍼 복사 (3번 노드의 CR 버퍼를 전송받음)
3. CR 버퍼에 대해서는 락 엘리먼트 및 GCS CLIENT 및 SHADOW를 생성하지 않는 것을 확인


스크립트


이 글에 사용된 스크립트는 다음과 같습니다.

fnd_blk_master 
fnd_gcs_detail


글을 마치며


설명을 단순화하기 위해서 테스트의 예제를 UPDATE로 했지만, SELECT 및 UPDATE등 다양한 테스트를 한 후 fnd_gcs_detail 스크립트를 이용해서 결과를 분석해보시면 RAC 내부 동작원리를 좀 더 파악할 수 있으리라 생각됩니다. 그리고 이번 포스팅을 끝으로 3개월 동안 진행한 "RAC 동작원리에 대한 연재"를 마무리하려고 합니다. GCS, GES 및 RAC 관련 파라미터에 대한 설명은 연재 내에서 다루기보다는 "성능 분석"이라는 새로운 주제 내에서 다룰 예정입니다. 지금까지는 다소 지루한 개론 부분이었다면 앞으로는 실용적인 측면을 가미한 내용으로 찾아뵙도록 하겠습니다.  


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


 

티스토리 툴바