ORACLE SEQUENCE PERFORMANCE TEST v1.0
ORACLE SEQUENCE PERFORMANCE TEST v1.0
|
13.05.03 |
v1.0 |
|
|
|
|
|
|
|
|
|
1. SEQUENCE
시퀀스 성능은 CACHE, ORDER 옵션에 좌지우지 된다.
이와 관련해 얻는 결론은 상당히 단순한 것으로 문서 말미에서 확인할 수 있다.
2. PRACTICE (ENV)
테스트를 위해 다음과 같은 환경을 사용하였다.
l RAC
l Sequence 를 단순 select
l 각 세션은 trace
다음과 같은 내용을 테스트한다.
A. NOCACHE + NOORDER (SINGLE SESSION)
B. NOCACHE + NOORDER (TWO SESSIONS, NODE1)
C. NOCACHE + NOORDER (TWO SESSIONS, NODE1 and NODE2)
D. CACHE + NOORDER (SINGLE SESSION)
E. CACHE + NOORDER (TWO SESSIONS, NODE1)
F. CACHE + NOORDER (TWO SESSIONS, NODE1 and NODE2)
G. NOCACHE + ORDER (SINGLE SESSION)
H. NOCACHE + ORDER (TWO SESSIONS, NODE1)
I. NOCACHE + ORDER (TWO SESSIONS, NODE1 and NODE2)
J. CACHE + ORDER (SINGLE SESSION, NODE1)
K. CACHE + ORDER (TWO SESSION, NODE1)
L. CACHE + ORDER (TWO SESSION, NODE1 and NODE2)
l Create USER 및 Create Sequence
|
CREATE USER SEQ_TEST IDENTIFIED BY SEQ_TEST DEFAULT TABLESPACE USERS TEMPORARY TABLESPACE TEMP;
GRANT CONNECT, ALTER SESSION TO SEQ_TEST;
CREATE SEQUENCE SEQ_TEST.NN_SEQ NOCACHE NOORDER; CREATE SEQUENCE SEQ_TEST.CN_SEQ CACHE 100 NOORDER; CREATE SEQUENCE SEQ_TEST.NO_SEQ NOCACHE ORDER; CREATE SEQUENCE SEQ_TEST.CO_SEQ CACHE 100 ORDER; |
l PL/SQL
|
#!/bin/bash
rm –f /oracle/log/*LHW*
sqlplus SEQ_TEST/SEQ_TEST << EOF
alter session set tracefile_identifier=lhw_a;
alter session set events '10046 trace name context forever,level 12';
declare tmp int; begin for i in 1..50000 loop select NN_SEQ.NEXTVAL into tmp from dual; end loop; end; /
alter session set events '10046 trace name context off';
EOF
tkprof /oracle/log/*LHW*.trc lhw_a sys=no
|
위와 같은 방법으로 A ~ L 케이스에 대해 스크립트를 사전 준비하였다.
3. PRACTICE
A ~ L 예시에 대해 모두 동일하게 5만번 호출하였다. 더불어 괄호안의 내용은 다음을 의미한다.
l SINGLE SESSION : NODE1 에서 하나의 세션을 수행
l TWO SESSIONS, NODE1 : NODE1 에서 두 개의 세션을 수행
l TWO SESSIONS, NODE1 and NODE2 : NODE1,2 에서 각기 수행
A. NOCACHE + NOORDER (SINGLE SESSION)
|
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.14 0.71 0 0 0 0 Fetch 50000 39.19 16.41 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 39.33 17.12 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NN_SEQ (cr=2 pr=4 pw=0 time=34997 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49274 0.01 4.97 latch: row cache objects 1 0.00 0.00 |
B. NOCACHE + NOORDER (TWO SESSIONS, NODE1)
|
#1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.12 0.72 0 0 0 0 Fetch 50000 35.46 45.82 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 35.58 46.54 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NN_SEQ (cr=2 pr=5 pw=0 time=33186 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=4 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49980 0.16 35.54 latch: row cache objects 8 0.00 0.00 latch: ges resource hash list 1 0.00 0.00
#2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.13 0.66 0 0 0 0 Fetch 50000 37.05 46.79 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 37.18 47.45 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NN_SEQ (cr=2 pr=2 pw=0 time=3999 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 50000 0.07 37.29 latch: row cache objects 6 0.00 0.00 library cache: mutex X 2 0.00 0.00 |
C. NOCACHE + NOORDER (TWO SESSIONS, NODE1 and NODE2)
|
# NODE1
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.19 0.90 0 0 0 0 Fetch 50000 26.59 206.80 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 26.78 207.71 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NN_SEQ (cr=2 pr=0 pw=0 time=2735 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49978 0.12 186.54 latch: row cache objects 4 0.00 0.00
# NODE2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.19 1.03 0 0 0 0 Fetch 50000 22.28 195.06 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 22.47 196.10 0 0 50000 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NN_SEQ (cr=5 pr=1 pw=0 time=15423 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49801 0.05 169.87 latch: row cache objects 10 0.00 0.00 |
D. CACHE + NOORDER (SINGLE SESSION)
|
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.46 0.53 0 0 0 0 Fetch 50000 3.01 1.54 0 0 500 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 3.47 2.07 0 0 500 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CN_SEQ (cr=2 pr=0 pw=0 time=1984 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 500 0.00 0.08 |
E. CACHE + NOORDER (TWO SESSIONS, NODE1)
|
# session1
SELECT CN_SEQ.NEXTVAL FROM DUAL
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.25 0.55 0 0 0 0 Fetch 50000 3.55 2.81 0 0 494 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 3.80 3.36 0 0 494 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CN_SEQ (cr=2 pr=4 pw=0 time=22244 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 424 0.00 0.04 enq: SQ - contention 458 0.01 1.04 library cache: mutex X 738 0.01 0.11 cursor: pin S 2 0.00 0.00 latch: ges resource hash list 1 0.00 0.00 latch free 1 0.00 0.00
# session2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.23 0.52 0 0 0 0 Fetch 50000 3.25 2.86 0 0 506 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 3.48 3.39 0 0 506 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CN_SEQ (cr=0 pr=0 pw=0 time=122 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 506 0.00 0.05 enq: SQ - contention 436 0.03 1.14 library cache: mutex X 1034 0.01 0.10 latch free 4 0.00 0.00 latch: ges resource hash list 2 0.00 0.00 cursor: pin S 2 0.00 0.00
|
F. CACHE + NOORDER (TWO SESSIONS, NODE1 and NODE2)
|
# NODE1
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.28 0.52 0 0 0 0 Fetch 50000 2.62 2.04 0 0 500 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 2.90 2.57 0 0 500 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CN_SEQ (cr=2 pr=1 pw=0 time=4852 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=4 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 500 0.10 0.52 KJC: Wait for msg sends to complete 19 0.00 0.00
# NODE 2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.33 0.54 0 0 0 0 Fetch 50000 2.75 2.14 0 0 500 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 3.08 2.69 0 0 500 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CN_SEQ (cr=5 pr=1 pw=0 time=3721 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=4 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 500 0.10 0.64 |
G. NOCACHE + ORDER (SINGLE SESSION)
|
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.04 0.73 0 0 0 0 Fetch 50000 38.70 15.13 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 38.74 15.87 0 0 50000 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NO_SEQ (cr=2 pr=1 pw=0 time=3757 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 47473 0.00 3.80 KJC: Wait for msg sends to complete 8 0.00 0.00 latch: row cache objects 3 0.00 0.00 |
H. NOCACHE + ORDER (TWO SESSIONS, NODE1)
|
# session1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.15 0.63 0 0 0 0 Fetch 50000 37.87 41.08 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 38.02 41.72 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NO_SEQ (cr=2 pr=0 pw=0 time=2261 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49909 0.03 31.88 latch: row cache objects 3 0.00 0.00
#session2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.11 0.73 0 0 0 0 Fetch 50000 36.71 38.99 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 36.82 39.73 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NO_SEQ (cr=2 pr=0 pw=0 time=2794 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49977 0.03 28.66 latch free 1 0.00 0.00 latch: row cache objects 5 0.00 0.00 |
I. NOCACHE + ORDER (TWO SESSIONS, NODE1 and NODE2)
|
# NODE1
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.17 0.90 0 0 0 0 Fetch 50000 21.88 165.59 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 22.05 166.49 0 0 50000 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NO_SEQ (cr=2 pr=4 pw=0 time=4035 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49996 0.06 145.02 KJC: Wait for msg sends to complete 244 0.00 0.00 latch: row cache objects 2 0.00 0.00
# NODE2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.20 1.02 0 0 0 0 Fetch 50000 26.34 203.50 0 0 50000 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 26.54 204.53 0 0 50000 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE NO_SEQ (cr=5 pr=1 pw=0 time=5781 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 49975 0.06 178.54 latch: row cache objects 9 0.00 0.00 latch: messages 1 0.00 0.00 |
J. CACHE + ORDER (SINGLE SESSION, NODE1)
|
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.40 0.53 0 0 0 0 Fetch 50000 3.23 2.17 0 0 500 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 3.63 2.70 0 0 500 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CO_SEQ (cr=2 pr=0 pw=0 time=2075 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 501 0.01 0.10 |
K. CACHE + ORDER (TWO SESSION, NODE1)
|
#session1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.20 0.53 0 0 0 0 Fetch 50000 4.30 2.76 0 0 525 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 4.50 3.30 0 0 525 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CO_SEQ (cr=2 pr=0 pw=0 time=2284 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 431 0.00 0.03 library cache: mutex X 729 0.01 0.04 DFS lock handle 799 0.02 0.46 latch: ges resource hash list 3 0.00 0.00 latch free 1 0.00 0.00 cursor: pin S 3 0.00 0.00
#session2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.20 0.53 0 0 0 0 Fetch 50000 4.30 2.76 0 0 525 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 4.50 3.30 0 0 525 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CO_SEQ (cr=2 pr=0 pw=0 time=2284 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 431 0.00 0.03 library cache: mutex X 729 0.01 0.04 DFS lock handle 799 0.02 0.46 latch: ges resource hash list 3 0.00 0.00 latch free 1 0.00 0.00 cursor: pin S 3 0.00 0.00 |
L. CACHE + ORDER (TWO SESSION, NODE1 and NODE2)
|
# node1
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.11 0.58 0 0 0 0 Fetch 50000 8.16 15.03 0 0 483 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 8.27 15.62 0 0 483 50000
Misses in library cache during parse: 0 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CO_SEQ (cr=2 pr=0 pw=0 time=2718 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ row cache lock 366 0.00 0.11 DFS lock handle 33771 0.02 10.88 KJC: Wait for msg sends to complete 210 0.00 0.00 latch: ges resource hash list 13 0.00 0.00
#node 2
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 50000 0.14 0.60 0 0 0 0 Fetch 50000 7.50 15.22 0 0 517 50000 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 100001 7.64 15.82 0 0 517 50000
Misses in library cache during parse: 1 Optimizer mode: FIRST_ROWS Parsing user id: 263 (recursive depth: 1) Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SEQUENCE CO_SEQ (cr=0 pr=0 pw=0 time=525 us) 1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ DFS lock handle 33772 0.02 10.78 KJC: Wait for msg sends to complete 588 0.00 0.00 row cache lock 517 0.00 0.17 latch: ges resource hash list 9 0.00 0.00 |
4. Summary
l Elapsed Time
Row cache lock 을 대기하는 시간 (Total Waited = sec)
|
|
NOORDER |
ORDER |
||||
|
Session |
1 |
2 (NODE1) |
2(NODE1,2) |
1 |
2 (NODE1) |
2(NODE1,2) |
|
NOCACHE |
4.97 |
37.29 |
186.54 |
3.80 |
31.88 |
178.54 |
|
CACHE |
0.08 |
0.05 |
0.64 |
0.10 |
0.03 |
0.17 |
Row cache lock 을 대기하는 시간을 보면 다음과 같은 사실을 알 수 있다.
- NOCACHE 가 CACHE 경우보다 수행타임이 더 길다.
- 한 노드에서 두 세션이 일으키는 경합보다 두 노드에서 각각의 한 세션이 일으키는 경합이 더 크다
한 노드에서 한 세션 vs 두 세션 이 일으키는 경합의 경우는 값이 역전되기도 하여 위 표만 보고 비교하기 어렵다.
사실 다른 이벤트 대기시간까지 고려한다면 한 세션보다 두 세션이 일으키는 경합이 확실히 더 크다.
(ex : CACHE + NOORDER 에서 한 노드에서 두 세션을 수행한 경우 SQ contention 경합으로 수행타임이 길어진다.)
Row cache lock 을 대기한 회수
|
|
NOORDER |
ORDER |
||||
|
Session |
1 |
2 (NODE1) |
2(NODE1,2) |
1 |
2 (NODE1) |
2(NODE1,2) |
|
NOCACHE |
49274 |
50000 |
49978 |
47443 |
49909 |
49996 |
|
CACHE |
500 |
506 |
500 |
501 |
431 |
517 |
Row cache lock 을 대기한 회수를 보면 이 값이 cache size 와 연관이 크다는 걸 알 수 있다.
CACHE 옵션의 경우 SIZE 를 100 을 주었다. ROW cache lock 을 대기한다는 것은 시퀀스의 딕셔너리 정보 (캐시를 소진하고 HW 를 상향) 를
수정하기 위함으로 이를 500 번 했다는 것은 시퀀스를 50,000 소진했다는 이야기다.
50,000 은 FOR LOOP 에 사용한 반복 값이다.
l Wait Event 특이사항 (row cache lock 제외)
- CACHE + NOORDER
위 환경에서 한 노드에서 두 개의 세션을 동시에 수행했을 때 관측결과이다.
Enq : SQ contention 이 458회 1.04초 관측되었다. 두번째로 큰 대기시간이 0.11 인 걸 생각하면 비율상 매우 큰 값이다.
|
|
NOORDER |
ORDER |
||||
|
Session |
1 |
2 (NODE1) |
2(NODE1,2) |
1 |
2 (NODE1) |
2(NODE1,2) |
|
NOCACHE |
|
|
|
|
|
|
|
CACHE |
|
SQ contention |
|
|
DFS lock handle |
DFS lock handle |
SQ contention 은 CACHE 를 사용하는 시퀀스에서 나타나는 대기이벤트다.
SEQUENCE.NEXTVAL 을 호출하는경우 SQ LOCK 을 획득한다.
때문에 동시에 많은 세션이 특정 시퀀스의 NEXTVAL 을 호출하게 되면 SQ LOCK 에 대한 경합이 발생하고,
이로인해 enq : SQ - contention 을 대기하게 된다.
하나의 세션으로 테스트 하는 경우 SQ Lock 에 대해 경합할 대상이 없기 때문에 SQ – contention 이 발생하지 않는다.
NOORDER + CACHE 의 각각의 노드에 대해 테스트 한 경우에도 각 노드를 생각해 볼 때 각 노드의 캐싱되어 있는
시퀀스 값을 사용하는 주체는 한 세션밖에 없다. 때문에 경합이 발생하지 않는다.
이는 CACHE + ORDER 환경에서 각 노드 각 세션에 대해 수행한 경우도 동일한 상황이다.
위 내용에 앞서 CACHE + ORDER 환경에서는 SQ lock 이 아닌 SV lock 을 사용한다고 한다. (Ref.A 참고)
- CACHE + ORDER
위 환경에서는 DFS lock handle event 가 도드라져 보였다.
DFS lock handle 은 CACHE + ORDER 환경에서 나타나는 enq : SQ – contention 격의 이벤트이다.
CACHE + ORDER 환경에서는 SV lock 을 사용하고, 이에대한 경합이 나타나는 경우 DFS lock handle 이 나타난다 한다. (Ref.A 참고)
Enq : SQ – contention 이 CACHE + NOORDER 환경에서 나타나는 SEQUENCE.NEXTVAL 을 위한 SQ lock 경합인데 반해
DFS lock handle 은 CACHE + ORDER 환경에서 SEQUENCE.NEXTVAL 을 위한 SV lock 경합이다.
분산환경에서 nextval 을 순차적으로 (order) 가져가기 위한 대기이벤트인 것이다.
이에 대한 테스트 결과는 아래와 같다.
l 두 세션을 한 노드에서 수행 한 경우 : DFS lock handle 458회 0.46초 (NODE1 결과값)
l 두 세션을 각각의 노드에서 수행 한 경우 : DFS lock handle 33771회 / 10.88 초 (NODE1 결과값)
위 결과를 보면 한 노드에서 두 세션을 이용해 경합을 일으킨 경우 DFS lock handle 이 발생했다는 것이다.
상황상 enq : SQ – contention 이 발생해야 하나 타겟이 된 시퀀스가 cache + order 이기 때문에 SV lock 과 연관 된 DFS lock handle 로 나타났다.
위 결과를 보면 order 를 사용하지 않은 경우 node1 의 총 대기시간이 0.52 에 반해, order 를 사용한 경우 무려 10.99 나 대기하게 된다.
그 이유는 다음과 같다.
cache + noorder 의 대기시간 = 각 노드의 nextval 경합시간
cache + order 의 대기시간 = 각 노드의 nextval 경합시간 + 전 노드간의 nextval 경합시간
5. CONCLUSIONS
NOCACHE 보다 CACHE 가 성능상 훨씬 유리하다.
ORDER 보다는 NOORDER 가 성능상 훨씬 유리하다.
추가로 값의 순서를 지키며 중간에 누락없이 쓰기위해 NOCACHE (+ORDER) 를 사용하는 경우가 있을 수 있는데,
이는 트랜잭션이 실패하기만 해도 값이 누락되는 취약한 구조이다.
6. REFERENCES
A. DFS lock handle : http://wiki.ex-em.com/index.php/DFS_lock_handle