본문 바로가기

카테고리 없음

ORACLE SEQUENCE PERFORMANCE TEST v1.0

 ORACLE SEQUENCE PERFORMANCE TEST v1.0

 

Date

Ver

Etc.

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