태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

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

티스토리 툴바