태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

'LOB'에 해당되는 글 5건

  1. 2009.09.24 Parallel Query와 direct path read, 그리고 LOB (1)
  2. 2009.08.21 CLOB Concatentaion 줄이기 (2)
  3. 2008.09.19 Oracle이 거짓말을 할 때 - Elapsed Time과 Wait Time의 역전 (2)
  4. 2008.08.13 LOB 데이터와 Cache 속성 - 두번째 이야기 (1)
  5. 2008.05.15 LOB 데이터와 Cache 속성 (3)

Parallel Query와 direct path read, 그리고 LOB

오라클 2009.09.24 16:20
Parallel하게 Table을 읽으면 direct path I/O를 사용합니다. 이것이 일반적인 진실입니다.

하지만, 테이블의 크기가 _small_table_threshold 파라미터 값보다 클 때만 그렇습니다.

NAME                           VALUE                IS_DEFAUL SES_MODIFI
------------------------------ -------------------- --------- ----------
SYS_MODIFI
----------
DESCRIPTION
--------------------------------------------------------------------------------
_small_table_threshold         1027                 TRUE      true
deferred
threshold level of table size for direct reads
즉, 이 시스템에서는 테이블의 크기가 1027 블록보다 클 때만 direct path I/O를 사용합니다. 하지만 테이블의 크기가 그보다 작을 때는 conventional path I/O를 사용합니다. _small_table_threshold 파라미터의 기본값은 Buffer Cache 크기의 5% 정도입니다. 즉 Buffer Cache의 5%보다 큰 테이블에 대해서만 Parallel Query에서 direct path I/O를 사용합니다.

Direct path I/O와 관련해서 또 하나의 숨겨진 사실이 있습니다. Out-Of-Row로 저장된 LOB 데이터를 Parallel Query로 읽고자 합니다. 이 LOB 데이터는 Slave Process가 읽을까요, Coordinator Process가 읽을까요? 놀랍게도 정답은 Coordinator Process가 읽는다는 것입니다.

이런 복합적인 사실들을 명확하게 이해하지 못하면 Parallel Query에 대한 10046 트레이스 분석시 치명적인 실수를 하게 됩니다. 아래의 간단한 테스트 결과를 볼까요.

1. _small_table_threshold 파라미터 값이 1027입니다.

UKJA@ukja1021> col value new_value stt
UKJA@ukja1021> @para small_table_threshold
UKJA@ukja1021> set echo off
old   9: and i.ksppinm like '%&1%'
new   9: and i.ksppinm like '%small_table_threshold%'

NAME                           VALUE                IS_DEFAUL SES_MODIFI
------------------------------ -------------------- --------- ----------
SYS_MODIFI
----------
DESCRIPTION
--------------------------------------------------------------------------------
_small_table_threshold         1027                 TRUE      true
deferred
threshold level of table size for direct reads
2. 테이블의 크기가 1027보다 조금 작게끔 생성합니다.
UKJA@ukja1021> create table t1(c1 int, c2 char(2000), c3 char(2000), c4 char(1000), c5 clob)
  2  lob(c5) store as (nocache nologging disable storage in row)
  3  ;

Table created.

Elapsed: 00:00:00.15
UKJA@ukja1021> 
UKJA@ukja1021> insert into t1
  2  select level, 'x', 'x', 'x', rpad('x',4000)
  3  from dual
  4  connect by level <= &stt - 100
  5  ;
old   4: connect by level <= &stt - 100
new   4: connect by level <= 1027 - 100

927 rows created.

Elapsed: 00:00:09.20
UKJA@ukja1021> @gather t1
UKJA@ukja1021> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
UKJA@ukja1021> select table_name, blocks
  2  from user_tables
  3  where table_name = 'T1';

TABLE_NAME               BLOCKS
-------------------- ----------
T1                          938
3. 이 테이블에 대해 Parallel Query를 수행합니다. Coordinator Process에서는 Physical I/O가 전혀 발생하지 않습니다.
UKJA@ukja1021> alter system flush buffer_cache;

UKJA@ukja1021> select /*+ parallel(t1 2) small */ * from t1;

select /*+ parallel(t1 2) small */ * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.45          1          2          0           0
Fetch      928      0.12       0.27          0          0          0         927
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      930      0.12       0.72          1          2          0         927

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
    927  PX COORDINATOR  (cr=2 pr=1 pw=0 time=518856 us)
      0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
      0    PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0     TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         1        0.01          0.01
  PX Deq: Parse Reply                             3        0.43          0.43
  SQL*Net message to client                     929        0.00          0.00
  SQL*Net message from client                   929        0.00          0.13
  PX Deq: Execute Reply                         271        0.01          0.07
  SQL*Net more data to client                     2        0.00          0.00
  PX qref latch                                  13        0.00          0.00
  PX Deq: Signal ACK                              3        0.09          0.10
  enq: PS - contention                            2        0.00          0.00
********************************************************************************
4. Physical I/O는 Slave Process에서 발생합니다. 하지만 direct path I/O가 아닌 conventional path I/O(db file scattered read 대기이벤트)가 사용된 것을 알 수 있습니다.
select /*+ parallel(t1 2) small */ * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.07      27.00        481        507          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.07      27.00        481        507          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
    470    PX BLOCK ITERATOR (cr=507 pr=481 pw=0 time=17523 us)
    470     TABLE ACCESS FULL T1 (cr=507 pr=481 pw=0 time=166734 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          15        0.12          0.14
  db file scattered read                         39        0.02          0.19
  PX Deq Credit: send blkd                      845        0.19         26.32
  PX qref latch                                  10        0.00          0.00
  PX Deq Credit: need buffer                      6        0.11          0.24
********************************************************************************
5. 테이블에 데이터를 더 추가해서 _small_table_threshold 값을 살짝 넘게 만듭니다.
UKJA@ukja1021> insert into t1
  2  select level, 'x', 'x', 'x', rpad('x',4000)
  3  from dual
  4  connect by level <= 200
  5  ;

200 rows created.

Elapsed: 00:00:01.23
UKJA@ukja1021> @gather t1
UKJA@ukja1021> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.57
UKJA@ukja1021> select table_name, blocks
  2  from user_tables
  3  where table_name = 'T1';

TABLE_NAME               BLOCKS
-------------------- ----------
T1                         1130
6. 다음과 같이 Parallel Query를 수행합니다. 여전히 Coordinator Process에서는 Physical I/O가 관찰되지 않습니다.
select /*+ parallel(t1 2) big */ * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.13          1          2          0           0
Fetch     1128      0.09       0.25          0          0          0        1127
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1130      0.09       0.38          1          2          0        1127

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
   1127  PX COORDINATOR  (cr=2 pr=1 pw=0 time=222619 us)
      0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
      0    PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0     TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         1        0.00          0.00
  PX Deq: Join ACK                                2        0.00          0.00
  PX Deq: Parse Reply                             2        0.12          0.12
  SQL*Net message to client                    1129        0.00          0.00
  SQL*Net message from client                  1129        0.00          0.15
  PX Deq: Execute Reply                         311        0.01          0.02
  SQL*Net more data to client                     2        0.00          0.00
  PX qref latch                                  12        0.00          0.00
  PX Deq: Signal ACK                              3        0.10          0.10
  enq: PS - contention                            2        0.00          0.00
7. 이번에도 Slave Process에서 Physical I/O가 이루어집니다. 단, conventional path I/O가 아닌 direct path I/O(direct path read 대기이벤트)가 이루어진 것을 알 수 있습니다.
select /*+ parallel(t1 2) big */ * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.07      28.93        572        585          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.07      28.93        572        585          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
    569    PX BLOCK ITERATOR (cr=585 pr=572 pw=0 time=447086 us)
    569     TABLE ACCESS FULL T1 (cr=585 pr=572 pw=0 time=327324 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          15        0.04          0.32
  direct path read                               51        0.01          0.05
  PX Deq Credit: need buffer                      7        0.02          0.07
  PX Deq Credit: send blkd                     1025        0.08         28.38
  PX qref latch                                  27        0.00          0.00
8. 여기서 한가지 더 의문이 있습니다. 테이블을 정의할 때 Out-Of-Row로 LOB을 생성했습니다. 이 LOB에 대한 Physical I/O는 어디로 갔을까요? LOB을 실제로 Fetch하는 것은 Slave Process가 아닌 Coordinator Process입니다. 더불어서 LOB에 대한 Fetch는 #0번의 Internal Cursor를 사용하기 때문에 Coordinator Process가 수행한 Query에 대한 TKPROF 결과에는 보고되지 않습니다. 이 문제는 여기에서 보고한 바 있죠.

따라서 LOB에 대한 direct path I/O에서 발생하는 direct path read 대기이벤트는 Coordinator Process가 남긴 트레이스 파일에 대한 TKPROF 리포트의 요약정보에서만 관찰됩니다.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      6      0.00       0.58          2          4          0           0
Fetch     2056      0.21       0.52          0          0          0        2054
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2066      0.21       1.11          2          4          0        2054

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    6168        0.00          0.02
  SQL*Net message from client                  6168        0.14         49.16
  db file sequential read                        20        0.02          0.17
  PX Deq: Parse Reply                             5        0.43          0.55
  PX Deq: Execute Reply                         582        0.01          0.10
  SQL*Net more data to client                     4        0.00          0.00
  direct path read                             8216        0.04          4.43
  PX qref latch                                  25        0.00          0.00
  PX Deq: Signal ACK                              6        0.10          0.20
  enq: PS - contention                            4        0.00          0.00
  PX Deq: Join ACK                                2        0.00          0.00
그 이유는 Coordinator Process에 대한 트레이스 파일 원본을 보면 알 수 있습니다. direct path read가 WAIT #0으로 보고되는 것에 유의해야 합니다.
WAIT #2: nam='PX Deq: Execute Reply' ela= 5 sleeptime/senderid=200 passes=1 p3=0
WAIT #2: nam='PX Deq: Execute Reply' ela= 6 sleeptime/senderid=200 passes=2 p3=0
WAIT #2: nam='PX Deq: Execute Reply' ela= 206 sleeptime/senderid=200 passes=3 p3
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
FETCH #2:c=0,e=501,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=511204438360          
WAIT #2: nam='SQL*Net message from client' ela= 245 driver id=1413697536 #bytes=
WAIT #0: nam='direct path read' ela= 5019 file number=9 first dba=23243 block cn
WAIT #0: nam='direct path read' ela= 443 file number=9 first dba=23243 block cnt
WAIT #0: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3
*** 2009-09-24 15:42:07.328                                                     
WAIT #0: nam='SQL*Net message from client' ela= 14753 driver id=1413697536 #byte
WAIT #0: nam='direct path read' ela= 253 file number=9 first dba=23243 block cnt
WAIT #0: nam='direct path read' ela= 188 file number=9 first dba=23243 block cnt
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
WAIT #0: nam='SQL*Net message from client' ela= 609 driver id=1413697536 #bytes=
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3
Parallel Query와 LOB이 같이 사용되면 문제가 상당히 복잡해진다는 것을 알 수 있죠. 대기이벤트를 분석할 때는 언제나 정신을 바짝 차려야 합니다.
저작자 표시
신고
Trackback 0 : Comment 1
  1. moncler españa 2013.01.05 20:20 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment


CLOB Concatentaion 줄이기

오라클 2009.08.21 14:02
한 고객사에서 PL/SQL 내에서 300KB가 넘는 SQL 문장을 동적으로 생성해야하는 요구 사항이 생겼습니다.

최초에 사용한 방법은 다음과 같았습니다.
(원래의 소스 코드를 매우 간단한 버전으로 수정했음을 알려 드립니다)

UKJA@ukja1021> create or replace function make_long_sql(p_idx in number)
  2  return clob
  3  is
  4  	     v_clob	     clob;
  5  begin
  6  	     v_clob := 'select ';
  7  	     for idx in 1 .. p_idx loop
  8  		     v_clob := v_clob||to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';
  9  	     end loop;
 10  	     v_clob := v_clob || '1 from dual';
 11  
 12  	     return v_clob;
 13  end;
 14  /

Function created.
아무런 특이 사항을 발견할 수 없습니다. CLOB 변수를 Concatenation을 통해서 합치는 매우 간단한 작업입니다. 즉, 개선 사항이 전혀 없어 보입니다. 그런데 이 함수를 수행해보면 무려 46초가 걸립니다.
UKJA@ukja1021> exec :c := make_long_sql(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:46.00
실제 고객사에서는 150KB 정도의 문자열을 동적으로 생성하는데 5분 이상이 걸렸습니다. 그래서 도움 요청이 왔죠.

제가 내린 처방은 다음과 같이 임시로 VARCHAR2 변수를 사용해서 CLOB에 대한 Concatenation 회수를 줄이는 것이었습니다.

UKJA@ukja1021> create or replace function make_long_sql2(p_idx in number)
  2  return clob
  3  is
  4  	     v_clob	     clob;
  5  	     v_varchar	     varchar2(1000);
  6  begin
  7  	     v_clob := 'select ';
  8  	     for idx in 1 .. p_idx loop
  9  		     v_varchar := to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';
 10  		     v_clob := v_clob||v_varchar;
 11  	     end loop;
 12  	     v_clob := v_clob || '1 from dual';
 13  
 14  	     return v_clob;
 15  end;
 16  /

Function created.
결과는 매우 극적입니다. 수행 시간이 42초에서 0.5초로 줄었습니다.
UKJA@ukja1021> exec :c := make_long_sql2(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.50
실제 고객사에서는 5분 작업이 5초 정도로 줄었습니다.

어디서 이런 큰 차이가 발생하는 것일까요? V$SESSTAT 뷰와 V$LATCH 뷰를 통해서 각각의 경우에 어떤 차이가 있는지를 보면 힌트를 얻을 수 있습니다.

NAME                                           VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
session logical reads                      17,376,991      133,035  -17,243,956
db block gets from cache                   15,764,933      102,971  -15,661,962
db block gets                              15,764,933      102,971  -15,661,962
consistent changes                          6,024,802       17,697   -6,007,105
db block changes                            6,024,814       17,710   -6,007,104
consistent gets from cache                  1,612,058       30,064   -1,581,994
consistent gets                             1,612,058       30,064   -1,581,994
free buffer requested                       1,432,143           49   -1,432,094
calls to get snapshot scn: kcmgss             480,030       40,019     -440,011
lob writes                                    120,008       10,004     -110,004
lob writes unaligned                          119,962       10,004     -109,958
lob reads                                      60,001       10,001      -50,000
...

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
cache buffers chains            -45091211          0          0   -1399062
object queue header operation    -2864253          0          0          0
cache buffers lru chain          -2864138          0          0          0
simulator hash latch              -164417          0          0          0
simulator lru latch               -112459          0          0     -51952
...
CLOB만 사용하는 경우(첫번째)와 VARCHAR2를 임시로 사용해서 Concatenation 회수를 줄인 경우(두번째)에 Logical Reads, LOB reads, LOB writes 등에서 큰 차이가 발생하고, 그만큼 latch 획득에서도 차이가 발생합니다. 이것이 성능 차이로 나타난 것입니다.

그 이유는 아래 글에서 잘 설명되어 있습니다.
http://jonathanlewis.wordpress.com/2009/07/09/concatenating-lobs/

LOB은 Concatenation에 취약한 특징을 지니고 있기 때문에 Concatenation의 회수 및 위치가 성능에 큰 영향을 미칠 수 있습니다. LOB를 사용할 때는 이점에 유의할 필요가 있겠습니다.

저작자 표시
신고
tags : LOB
Trackback 0 : Comments 2
  1. oveRock 2009.08.21 14:40 신고 Modify/Delete Reply

    흥미롭네요.... 저는 오라클이 워낙 젬병이라 잘은 모르겠지만....
    페인트공 알고리즘과 연관이 있는 게 아닐까요?

    • 욱짜 2009.08.21 15:06 신고 Modify/Delete

      본문의 링크에 설명이 잘 나와요.

      v_clob := v_clob || 'x' || 'y';

      이렇게 하면 'x'을 붙일 때 임시 Lob를 만들고, 'y'를 붙일 때 또 임시 Lob을 만들게 됩니다. 그만큼 불필요한 작업이 더 생기게 됩니다.

      러시아 페인트 공과는 조금 다른 문제입니다.

Write a comment


Oracle이 거짓말을 할 때 - Elapsed Time과 Wait Time의 역전

오라클 2008.09.19 17:53

이 글은 Test 결과 해석에 몇 가지 오류가 있습니다.
(생각지 못한 이상한 현상들이 더 발견되었네요 - 댓글 참조)
 
자세한 내용은 추후에 다시 논의하도록 하겠습니다.

---------------------------------------------------------------------------
OWI, 즉 Oracle Wait Interface는 Oracle 성능 문제를 분석하는 가장 강력한 Tool들 중 하나이다.

하지만 가끔 거짓말을 한다.
Sampling에서 오는 오류도 있고 Bug에 의한 오류도 있다.

가끔은 전혀 알 수 없은 오류를 내기도 한다.

아래에 간단한 예가 있다.

다음과 같이 LOB Type의 Column을 가진 Table을 생성한다.

drop table t1 purge;

create table t1(c1 clob)
  lob(c1) store as (cache enable storage in row);

첫번 째 Case는 순수 SQL을 통해 총 5000건의 LOB Data를 insert한다.
두번 째 Case는 PL/SQL을 통해 총 5000건의 LOB Data를 insert한다.

두번 째 Case가 성능이 더 우수한 것은 두말할 나위가 없다.
하지만 첫번 째 Case에서 우리는 놀라운 사실을 알 수 있다.

--------------------------------------------------------
-- case1: insert lob in normal sql

@ukja102
ed temp
/*
set heading off
set timing off
set feedback off
set verify off

spool lob.sql

select
  'insert into t1 values(rpad(''x'',4000,''x'')); ' || chr(13)||chr(10) ||
  'commit; '|| chr(13)||chr(10)
from dual
connect by level <= &1
;

set verify on
set heading on
set timing on
set feedback on


spool off
*/

@temp 5000

@trace_on 10046 8

@lob

@trace_off
@trace_file
@tkprof trc1.out

아래에 10046 Event, 즉 SQL*Trace에 대한 tkprof의 결과가 있다.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS                                
                                                                               
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10064      0.23       0.22          0          0          0           0
Execute  10065      2.40       2.38          9      10653      62832        5063
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20129      2.64       2.60          9      10653      62832        5063
                                                                               
Misses in library cache during parse: 1                                        
                                                                               
Elapsed times include waiting on following events:                             
  Event waited on                             Times   Max. Wait  Total Waited  
  ----------------------------------------   Waited  ----------  ------------  
  SQL*Net message to client                   10001        0.00          0.03  
  SQL*Net message from client                 10001        0.02          6.60  
  log file sync                                5053        0.04          3.09  
  db file sequential read                         9        0.03          0.09  
  log file switch completion                      2        0.10          0.18  

무언가 이상하지 않은가?
Query의 Elapsed Time은 2.6초인데 반해 Wait Time은 10초에 달한다. 논리적으로 불가능하다.
어딘가 이빨이 빠진 것이다.

반면에 PL/SQL을 통해 동일한 작업을 수행한 경우에는 이런 문제가 없다.

--------------------------------------------------------
-- case2: insert lob in pl/sql

@ukja102
@trace_on 10046 8

begin
  for idx in 1 .. 5000 loop
    insert into t1 values(rpad('x',4000,'x'));
    commit;
  end loop;
end;
/

@trace_off
@trace_file
@tkprof trc2.out

약간의 오류는 있지만 Wait Time이 Elapsed Time에 비해 턱없이 높은 오류는 없다.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS                                
                                                                              
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      0.48       0.51          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.48       0.51          0          0          0           1
                                                                              
Misses in library cache during parse: 1                                        
                                                                              
Elapsed times include waiting on following events:                             
  Event waited on                             Times   Max. Wait  Total Waited  
  ----------------------------------------   Waited  ----------  ------------  
  SQL*Net message to client                       2        0.00          0.00  
  SQL*Net message from client                     2        0.00          0.00  
  log file sync                                   1        0.59          0.59  
                                                                              
                                                                              
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS                                    
                                                                              
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       98      0.00       0.00          0          0          0           0
Execute  10096      1.23       5.02          3       5438      51748        5065
Fetch      182      0.00       0.00          0        243          0         151
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    10376      1.23       5.03          3       5681      51748        5216
                                                                              
Misses in library cache during parse: 1                                        
                                                                              
Elapsed times include waiting on following events:                             
  Event waited on                             Times   Max. Wait  Total Waited  
  ----------------------------------------   Waited  ----------  ------------  
  log buffer space                               10        0.37          2.08  
  db file sequential read                         3        0.20          0.32  
  free buffer waits                              38        0.01          0.37  
  latch: cache buffers lru chain                  1        0.00          0.00  
  log file switch completion                      3        0.50          0.84  

위의 Test 결과에서 한가지 추측할 수 있는 것은 LOB Data를 Handling하는 Operation에 대해 SQL*Trace가 정확한 측정을 하지 않다는 것이다. 즉 LOB Data를 Handling하는 과정에서 발생하는 Wait Time을 Elased Time에 포함시키지 않고 있는 것이다. 더 재미있는 것은 이런 오류가 PL/SQL에서는 나타나지 않으며 오로지 Pure SQL을 통해 실행될 때만 나타난다는 것이다. 아마 Cursor의 Execution과 Wait를 연결하는 고리에서 문제가 있을 것이다.

이것이 Designed Feature인지 Bug 중 하나인지는 알 수 없지만 매우 바람직하지 못한 일임에는 분명하다.

OWI는 매우 강력한 성능 측정 도구이지만 의외로 상당히 함정이 많다는 것을 사용할 때마다 느낀다. 이런 함정을 모른다면 자칫 매우 잘못된 결론을 내릴 수 있다.

모름지기 어떤 현상을 해석할 때는 조심 또 조심해야할 일이다.




신고
tags : LOB, OWI
Trackback 0 : Comments 2
  1. extremedb 2008.09.21 18:23 신고 Modify/Delete Reply

    설명하신것 중에 가장 많은 시간을 차지한 SQL*Net message from client 의 6.6 초는 는 DB 서버의 작업(PARSE/EXEC/FETCH)과는 상관없는 시간 입니다.
    즉 다시말해 2.6 초는 DB 서버의 작업 이며 6.6 초는 서버작업과는 상관없는 시간인 것입니다.
    아래의 스크립트를 보시면
    SQL> alter session set events '10046 trace name context forever, level 12';

    Session altered.

    SQL> !date
    Tue Apr 17 13:46:40 EDT 2007

    SQL> !date
    Tue Apr 17 13:47:02 EDT 2007 --> 약 22 초 경과

    SQL> select * from dual;

    이렇게 해서 TKPROF 보고서를 보시면
    SQL*Net message from client =
    22 초 + SQL 타이핑 시간과 거의 일치하는 것을 알수 있습니다.

  2. 욱짜 2008.09.21 22:29 신고 Modify/Delete Reply

    Trace File을 다시 보니 그 동안 무심하게 지나쳤던 몇가지를 발견하게 되네요. Trace File 맨뒤의 요약 정보와 개별 정보간의 합에서 몇가지 Mismatch가 발생하는 것 같습니다.
    이 현상을 좀 더 관찰해봐야겠습니다.

    가령 말씀하신 SQL*Net message from client의 Wait Time은 개별 SQL 정보에서는 Elapsed Time안에 포함되는 반면, 제일 뒤의 요약 정보에는 빠져 있습니다. SQL*Net message from client 뿐만 아니라 좀 더 Test를 해보니까 log file sync Wait Time도 그런 속성이 있네요. 이런 요소들 때문에 Trace File 맨 뒤의 요약 정보가 크게 틀린 것처럼 보였습니다.

    Raw Trace File을 좀 더 해석해보고 더 좋은 결론이 나면 다시 논의하도록 하겠습니다.

Write a comment


LOB 데이터와 Cache 속성 - 두번째 이야기

오라클 2008.08.13 11:34
2008/05/15 - [Advanced Oracle] - LOB 데이터와 Cache 속성에서 LOB과 CACHE 속성의 연관 관계에 대해서 간단한 Test 결과를 공유한 바 있다.

해당 글에 대해 다음과 같은 Comment가 달렸다.

in-line lob의 경우 buffer cache를 경유하며 이 때는 cache 옵션을 사용한 것 처럼 작동한다. 그러나 실제 nocache로 선언한 경우 nologging을 같이 선언 할 수 있는데 cache 옵션을 명시적으로 사용하면무조건 logging 이다. 그렇다면 위와 같이 in-line lob를 nocache로 선언하고 nologging으로 사용한다면 redo가 사용 될것인가?

nologging을 선언한 경우에는 Redo 생성이 최소화될 것이고, 그렇지 않은 경우에는 Redo가 생성될 것이다(Document에 의하면). 하지만 역시 Test를 해보지 않으면 정확한 결과를 공유하기 힘들겠다. 아래에 간단한 Test Case가 있다.

두 가지의 경우를 비교하고자 한다.
LOB Data의 크기가 4K 미만이면 별도의 Segment가 아닌 Table Segment의 Block에 저장된다. 반면 LOB Data의 크기가 4K 이상이면 별도의 LOB Segment에 저장될 것이다. 이 두가지 경우에 Redo 생성이 어떻게 다르게 나타나는지를 비교해 보자.

Case1: LOB Data의 크기가 4K 미만인 경우

@mysid
@mon_on &v_sid

drop table t1 purge;
create table t1(c1 clob)
  lob(c1) store as (nocache nologging) -- nologging
;
 

begin
  
  for idx in 1 .. 100000 loop
    insert into t1 values('0123456789'); -- < 4K
  end loop;
  
  commit;
  
end;
/

@mon_off

drop table t1 purge;
create table t1(c1 clob)
  lob(c1) store as (nocache logging) -- logging
;

begin
  
  for idx in 1 .. 100000 loop
    insert into t1 values('0123456789');  -- <4K
  end loop;
  
  commit;
  
end;
/

@mon_off2

@mon_show2
4K 미만의 LOB Data에 대한 nologging과 logging의 비교 결과는 다음과 같다.
NAME                                           VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
physical write total bytes                          0   10,641,408   10,641,408
session pga memory                            720,896    4,587,520    3,866,624
session pga memory max                        720,896    4,587,520    3,866,624
session uga memory                            458,248            0     -458,248
physical read total bytes                      32,768      458,752      425,984
session uga memory max                        458,248      261,964     -196,284
physical read bytes                            32,768      131,072       98,304
redo size                                  29,344,080   29,341,896       -2,184
...

STAT_NAME                                      VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
sql execute elapsed time                    5,255,255    5,970,572      715,317
DB time                                     5,370,640    6,049,237      678,597
DB CPU                                      4,471,217    4,407,326      -63,891
PL/SQL execution elapsed time                 335,458      325,010      -10,448
sequence load elapsed time                     44,833       39,366       -5,467
...
Redo Size에 아무런 차이가 없다. 즉, Logging 속성에 무관하게 거의 동일한 양의 Redo가 생성된다. 당연한 결과라고 할 수 있다. Data Block에 LOB이 저장되므로 Redo가 무조건 생성되는 것이다.

Case2: LOB Data의 크기가 4K 이상인 경우

@mysid
@mon_on &v_sid

drop table t1 purge;
create table t1(c1 clob)
  lob(c1) store as (nocache nologging)  -- nologging
;
 
declare
  v_value varchar2(10000);
begin
  for idx in 1 .. 10000 loop
    v_value := v_value || '0';   -- > 4K
  end loop;
  
  for idx in 1 .. 1000 loop
    insert into t1 values(v_value);
  end loop;
  
  commit;
  
end;
/

@mon_off

drop table t1 purge;
create table t1(c1 clob)
  lob(c1) store as (nocache logging)  -- logging
;

declare
  v_value varchar2(10000);
begin
  for idx in 1 .. 10000 loop
    v_value := v_value || '0';
  end loop;
  
  for idx in 1 .. 1000 loop
    insert into t1 values(v_value);  -- > 4K
  end loop;
  
  commit;
  
end;
/

@mon_off2

@mon_show2
4K 이상의 LOB Data에 대한 nologging과 logging의 비교 결과는 다음과 같다.
NAME                                           VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
redo size                                   1,169,916   25,720,496   24,550,580
session pga memory                            983,040            0     -983,040
session pga memory max                        983,040      262,144     -720,896
session uga memory                            458,248            0     -458,248
session uga memory max                        458,248      254,380     -203,868
physical read bytes                            81,920       32,768      -49,152
physical read total bytes                      81,920       32,768      -49,152
...

STAT_NAME                                      VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
DB time                                     3,790,992    8,103,137    4,312,145
sql execute elapsed time                    3,699,938    7,998,178    4,298,240
DB CPU                                        795,460    1,065,060      269,600
PL/SQL execution elapsed time                  10,288       11,340        1,052
parse time elapsed                             19,039       19,841          802
...
Nologging 속성이 부여된 경우에는 Redo가 생성되지 않는다. 하지만 logging 속성이 부여된 경우에는 Redo가 생성된다. 그만큼 수행 시간(DB Time)또한 크게 개선된다. 이것 역시 당연한 결과라고 할 수 있겠다.

LOB을 사용하는 경우 큰 크기의 Data가 대부분일것(더 정확하게 말하면 별도의 Segment에 저장)이므로 Case2가 우리가 실제로 많이 접하는 경우가 될 것이다.

신고
tags : LOB, nocache, nologging
Trackback 0 : Comment 1
  1. lee 2008.08.13 18:48 신고 Modify/Delete Reply

    정말 좋은 설명 감사합니다.

Write a comment


LOB 데이터와 Cache 속성

오라클 2008.05.15 10:03
얼마전 이런 취지의 문의를 받았다.

LOB 컬럼을 CACHE 속성으로 정의했다. 만일 Buffer Cache가 2G이고, LOB 데이터의 크기가 1.9G라고 하자. 이 경우 LOB 데이터를 읽으면 2G중 1.9G가 LOB 데이터로 꽉 차버리는가? 그렇다면 너무 비효율적인 것이 아닌가?


본인 스스로 이런 고민을 해본 적이 없기 때문에 다음과 같은 대답을 할 수 밖에 없었다.

충분히 의문을 가질 수 있다. Document에 의하면 CACHE 속성의 LOB 데이터는 Buffer Cache를 점유할 수 있으며, 다른 버퍼를 밀어낼 위험이 있다고 되어 있다. 하지만 정말 그렇게 무식하게(?) 동작할까?

그래서 간단한 테스트를 통해 검증을 해보았다.

결론은 CACHE 속성의 LOB 데이터는 크기에 무관하게 Buffer Cache를 점유한다는 것이다.

1. SGA의 크기 분포는 다음과 같다.
UKJA@ukja101> show sga

Total System Global Area  171966464 bytes
Fixed Size                   787988 bytes
Variable Size             145488364 bytes
Database Buffers           25165824 bytes  <-- 25M
Redo Buffers                 524288 bytes

2. 큰 크기(30M 이상)의 Btree Index를 경유하는 일반적인 Range Scan을 통해 Buffer Cache를 꽉 채운다.

OBJ_NAME                          OBJ_CNT
------------------------------ ----------
T2_N1                                3006

최대 수용 가능한 블록 수는 (Buffer Cache / Block Size) = 25M/8K = 3200(개)로, Buffer Cache가 거의 Btree Index로 꽉 찼음을 알 수 있다.

3. 큰 크기(100M 이상)의 LOB 데이터를 읽은 후 Buffer Cache를 조사해보면 이상한 이름의 객체로 Buffer Cache가 꽉찬 것을 알 수 있다.

create table t1(c1 int, c2 clob)
  lob(c2) store as (cache)
;
...
OBJ_NAME                          OBJ_CNT
------------------------------ ----------
SYS_LOB0000051135C00002$$            2579
PROCEDUREINFO$                         85
                                       44
MGMT_METRICS_RAW_PK                    25
MGMT_SYSTEM_PERF_LOG_IDX_01            16


dba_lobs 뷰를 통해 어떤 테이블의 LOB 데이터인지 확인해 보면, 우리가 정의한 t1 테이블이라는 것을 확인할 수 있다.

UKJA@ukja101> exec print_table('select * from dba_lobs where segment_name = ''&lob_seg''');
Enter value for lob_seg: SYS_LOB0000051135C00002$$
OWNER                         : UKJA
TABLE_NAME                    : T1
COLUMN_NAME                   : C2
SEGMENT_NAME                  : SYS_LOB0000051135C00002$$
TABLESPACE_NAME               : USERS
INDEX_NAME                    : SYS_IL0000051135C00002$$
CHUNK                         : 8192
PCTVERSION                    : 10
RETENTION                     : 900
FREEPOOLS                     :
CACHE                         : YES
LOGGING                       : YES
IN_ROW                        : YES
FORMAT                        : ENDIAN NEUTRAL
PARTITIONED                   : NO


큰 크기의 LOB은 기본적으로 Buffer Cache를 경유하지 않는 것이 합리적이다.

  • 우선 Buffer Cache내의 다른 중요한 블록들을 밀어 낸다
  • 큰 크기의 LOB를 공유할 필요가 있겠는가? 한번 읽고 버리는 것이 합리적이다.
  • 설사 공유할 필요가 있다고 해도 그 큰 크기를 어떻게 메모리에 보관하겠는가? Recycle Buffer Pool 같은 것을 쓴다고 해도 곧 밀려날 것이다.

한가지 재미있는 것은 Buffer Cache에 존재하지 않는 LOB 데이터를 읽어 들일 때는 db file sequential read 이벤트를 대기하는 것으로 관찰된다는 것이다.

EVENT                                       D_WAITS D_TIMEOUTS D_TIME_WAITED
---------------------------------------- ---------- ---------- -------------
SQL*Net message from client                       6          0          3062
db file sequential read                        2426          0           485
db file scattered read                           71          0             8
rdbms ipc reply                                   1          0             1
SQL*Net message to client                         6          0             0


db file sequential read 이벤트를 대기한다고 해서 항상 Btree Index 경유를 의미하지 않는다는 것에 주의할 필요가 있겠다.


(참조) 아래는 테스트에 사용한 스크립트다.

--------------------------------------------
-- Test for how lob is cached into memory
--------------------------------------------

spool result.txt
set echo on
-- version
select * from v$version;

-- show sga (buffer cache를 25M 정도로 지정)
show sga

drop table t1 purge;
drop table t2 purge;

create table t1(c1 int, c2 clob)
  lob(c2) store as (cache)
;

create table t2(c1 char(1000));

insert into t2
select level
from dual
connect by level <= 30000
;

create index t2_n1 on t2(c1)
;

insert into t1 values(1, '0123456789');

declare
  src_lob clob;
  tar_lob clob;
begin
  select c2 into tar_lob
  from t1
  where rownum = 1 for update
  ;
   
  for idx in 1 .. 20 loop
     select c2 into src_lob
      from t1
      where rownum = 1 for update;
     dbms_lob.append(tar_lob, src_lob);
  end loop;
 
  commit;

end;
/

select dbms_lob.getlength(c2) from t1
;


-- flush buffer cache with index
explain plan for
select /*+ index(t2) */ *
from t2
where c1 > ' '
;

@plan

alter system flush buffer_cache;

select /*+ index(t2) */ count(c1)
from t2
where c1 > ' '
;

col obj_name format a30

select
  (select object_name
    from all_objects
    where object_id = v.objd) as obj_name,
  v.obj_cnt
from (
  select objd,
       count(*) as obj_cnt
  from v$bh
  group by objd
  order by 2 desc
) v
where rownum <= 5
;


-- read lob
declare
  l_pos  pls_integer := 1;
  l_amount binary_integer := 32767;
  v_buffer varchar2(32767);
  l_clob_len pls_integer;
  src_lob clob;
begin
  select c2 into src_lob from t1 where rownum = 1;
 
  l_clob_len := dbms_lob.getlength(src_lob);
 
  while l_pos < l_clob_len loop
    dbms_lob.read(src_lob, l_amount, l_pos, v_buffer);
    l_pos := l_pos + l_amount;
  end loop;
end;
/


select
  (select object_name
    from all_objects
    where object_id = v.objd) as obj_name,
  v.obj_cnt
from (
  select objd,
       count(*) as obj_cnt
  from v$bh
  group by objd
  order by 2 desc
) v
where rownum <= 5
;

exec print_table('select * from dba_lobs where segment_name = ''&lob_seg''');
-- or
--set long 100000000    -- if you can wait
--select * from t1;

spool off
ed result.txt



신고
Trackback 0 : Comments 3
  1. oracler 2008.06.01 18:53 신고 Modify/Delete Reply

    선생님의 OWI 책 344 페이지에 보면..

    CACHE 옵션을 사용하여 LOB 컬럼을 생성하면
    버퍼캐시를 경유하게되므로 "일반 데이타와 동일한 메커니즘"을 따르게 된다.
    ..중략..
    만일 SGA 의 크기가 여유가 없거나 LOB 데이타의 크기가 크다면
    NOCACHE 를 사용하는것이 유리하다.
    LOB 데이타가 크지 않고, 자주 액세스되는 범위가 정해져 있다면
    CACHE 옵션을 사용함으로써 성능개선 효과를 얻을수 있다.

    라고 나와 있네요.
    CACHE 옵션 사용시 일반 데이타와 동일한 메커니즘을 따른다는 부분이 핵심입니다.

  2. lee 2008.08.12 19:19 신고 Modify/Delete Reply

    in-line lob의 경우 buffer cache를 경유하며 이 때는 cache 옵션을 사용한 것 처럼 작동한다.
    그러나 실제 nocache로 선언한 경우 nologging을 같이 선언 할 수 있는데 cache 옵션을 명시적으로 사용하면무조건 logging 이다.

    그렇다면 위와 같이 in-line lob를 nocache로 선언하고 nologging으로 사용한다면 redo가 사용 될것인가?

  3. 욱짜 2008.08.13 11:34 신고 Modify/Delete Reply

    http://ukja.tistory.com/157 참조하세요.

Write a comment

티스토리 툴바