태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

TKPROF 결과 해석시 조심해야할 함정 - CURSOR #0

오라클 2009.09.17 14:16
TKPROF 에서 "시간값"이 완전한 거짓말을 하는 경우가 있습니다. 아주 쉽게 재현할 수 있습니다. 아래 테스트를 보세요.

1. 다음과 같이 테이블을 만들고, 10,000건의 데이터를 Insert하는 Script를 생성합니다.

drop table t1 purge;
create table t1(c1 number);

set term off
set heading off
set feedback off
set echo off
set timing off

spool insert.sql
select 
	'insert into t1 values(:b1);' || chr(13)
from dual 
connect by level <= 10000
;
spool off
2. insert.sql은 다음과 같은 내용을 포함하게 됩니다.
insert into t1 values(:b1);

insert into t1 values(:b1);

insert into t1 values(:b1);

insert into t1 values(:b1);
...
3. AUTOCOMMIT을 활성화시키고, insert.sql을 수행한 후 수행 시간을 계산해봅니다.
set autocommit on

var b1 number;
exec :b1 := 1;

col hsecs new_value v_hsecs

select hsecs from v$timer;

@insert

select (hsecs-&v_hsecs)/100 from v$timer;
다음과 같이 32초 정도의 시간이 걸렸습니다.
UKJA@ukja1021> select (hsecs-&v_hsecs)/100 from v$timer;
old   1: select (hsecs-&v_hsecs)/100 from v$timer
new   1: select (hsecs- 139710015)/100 from v$timer

(HSECS-139710015)/100
---------------------
                32.42
4. 하지만 TKPROF의 결과는 전혀 다릅니다. Idle 대기시간을 다 합쳐도 8초 정도 밖에 안됩니다. 무려 24초 정도의 오차가 발생하고 있습니다.
insert into t1 
values
(:b1)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10000      0.48       0.28          0          0          0           0
Execute  10000      1.31       1.34          0      10007      50155       10000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20000      1.79       1.63          0      10007      50155       10000

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

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   10000        0.00          0.03
  SQL*Net message from client                 10000        0.04          6.79
********************************************************************************
5. 이 오차는 어디서 발생한 것일까요? TKPROF 결과 중 Summary 부분을 보시면 잃어버린 24초가 존재하는 것을 알 수 있습니다.
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10004      0.51       0.30          0          0          0           0
Execute  10005      1.31       1.34          0      10007      50155       10001
Fetch        4      0.00       0.00          0          0          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    20013      1.82       1.64          0      10007      50155       10003

Misses in library cache during parse: 3
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   20007        0.00          0.06
  SQL*Net message from client                 20007        0.05         20.56
  log file sync                               10000        0.04          4.99
왜! 이 24초가 INSERT 문장에 포함되지 않고 Summary에만 나오는 것일까요?

6. TKPROF가 이상하므로 그 원본 데이터를 통해서 원인을 찾아야 합니다. 아래는 특정 INSERT 문장에 대한 트레이스 결과입니다.

PARSING IN CURSOR #5 len=26 dep=0 uid=61 oct=2 lid=61 tim=1397114954939 hv=78085
insert into t1 values(:b1)                                                      
END OF STMT                                                                     
PARSE #5:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1397114954935          
EXEC #5:c=0,e=112,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=1397114955118          
WAIT #5: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3
WAIT #5: nam='SQL*Net message from client' ela= 349 driver id=1413697536 #bytes=
XCTEND rlbk=0, rd_only=0                                                        
WAIT #0: nam='log file sync' ela= 359 buffer#=2403 p2=0 p3=0 obj#=-1 tim=1397114
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3
WAIT #0: nam='SQL*Net message from client' ela= 886 driver id=1413697536 #bytes=
XCTEND(Transaction End)가 보이고, 그 다음의 log file sync 대기와 SQL*Net message 대기는 #5가 아닌 #0으로 바뀌어 버립니다. 즉 AUTOCOMMIT에 의해 내부적으로 수행되는 커밋에 의한 시간은 INSERT 문장에 포함되지 않으며 별개의 내부 커서로 처리된다는 것을 알 수 있습니다. 명시적으로 커밋을 수행한 적이 없기 때문에 commit 문장도 전혀 관찰되지 않습니다. 덕분에 AUTOCOMMIT에 의한 시간은 오로지 Summary 부분에만 반영됩니다.

TKPROF 결과에서 보고하는 SQL 문장의 수행 시간을 믿을 수 없는 대표적인 경우입니다.

AUTOCOMMIT을 사용하는 경우는 거의 없으니까 문제가 없겠네?라고 했다면 아래 예를 보면 생각이 바뀔겁니다.

7. 다음과 같이 LOB 타입을 정의하고 4K 바이트 정도의 데이터를 추가합니다. 크기가 4K 바이트이므로 별도의 세그먼트에 저장될 것이고 direct path read를 통해 읽게 될 것입니다.

drop table t1 purge;

create table t1(c1 int, c2 clob);

declare
    v_clob clob := rpad('x', 4000, 'x');
begin
    for idx in 1 .. 1000 loop
        insert into t1 values(idx, v_clob);
    end loop;
end;
/
8. 다음과 같이 데이터를 읽어 보면 1분 45초 정도의 시간이 걸립니다.
UKJA@ukja1021> set autot trace  -- 출력 억제
UKJA@ukja1021> select * from t1;

1000 rows selected.

Elapsed: 00:01:45.70
9. 하지만 TKPROF 결과를 보면 Idle 대기시간을 다 합쳐도 0.3초가 채 되지 않습니다. 대부분의 시간이 전혀 보고되지 않고 있습니다. 기대했던 direct path read 이벤트는 아예 보이지도 않습니다.
select *
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.00          0          0          0           0
Fetch     1001      0.09       0.12         35       1030          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      0.09       0.12         35       1030          0        1000

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

Rows     Row Source Operation
-------  ---------------------------------------------------
   1000  TABLE ACCESS FULL T1 (cr=1030 pr=35 pw=0 time=66068 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    1002        0.00          0.00
  SQL*Net message from client                  1002        0.00          0.15
  db file sequential read                         3        0.00          0.00
  db file scattered read                          1        0.02          0.02
10. 이번에도 역시 Summary 부분에만 시간이 정확하게 계산되어서 보고됩니다.
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       12      0.01       0.18          0          0          0           0
Execute     12      0.04       0.14         18        147          4           2
Fetch     1012      0.15       0.19         35       1030          0        1024
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1036      0.21       0.52         53       1177          4        1026

Misses in library cache during parse: 6
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                  102017        0.00          0.35
  SQL*Net message from client                102016        0.02         19.69
  db file sequential read                        22        0.01          0.11
  db file scattered read                          1        0.02          0.02
  direct path read                           201000        0.05         47.75
11. 이번에도 트레이스 원본 파일을 봐야겠죠. 아래 내용을 보면 동일한 패턴이 관찰됩니다.
  
select * from t1                                                           
END OF STMT                                                                
PARSE #26:c=0,e=1314,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1382035591807  
EXEC #26:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1382035592024     
WAIT #26: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes
WAIT #26: nam='SQL*Net message from client' ela= 473 driver id=1413697536 #b
WAIT #26: nam='db file sequential read' ela= 302 file#=7 block#=30 blocks=1
WAIT #26: nam='db file sequential read' ela= 235 file#=7 block#=9 blocks=1 o
WAIT #26: nam='db file sequential read' ela= 244 file#=7 block#=29 blocks=1
WAIT #26: nam='db file scattered read' ela= 20637 file#=7 block#=41 blocks=3
WAIT #26: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes
FETCH #26:c=0,e=22152,p=35,cr=15,cu=0,mis=0,r=1,dep=0,og=1,tim=1382035614925
WAIT #26: nam='SQL*Net message from client' ela= 287 driver id=1413697536 #b
WAIT #0: nam='direct path read' ela= 10386 file number=7 first dba=1500 bloc
WAIT #0: nam='direct path read' ela= 277 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 317 driver id=1413697536 #by
WAIT #0: nam='direct path read' ela= 354 file number=7 first dba=1500 block
WAIT #0: nam='direct path read' ela= 277 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 197 driver id=1413697536 #by
WAIT #0: nam='direct path read' ela= 288 file number=7 first dba=1500 block
WAIT #0: nam='direct path read' ela= 359 file number=7 first dba=1500 block
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=
WAIT #0: nam='SQL*Net message from client' ela= 185 driver id=1413697536 #by
#26번으로 작업을 하다가 정작 LOB을 Fetch할 때는 갑자기 #0번으로 바뀌어 버립니다. 따라서 TKPROF에서 정확하게 반영을 못하는 것입니다.

Oracle이 어떤 작업을 수행하다가 별도의 OCI 호출을 통해(AUTOCOMMIT, LOB 등) 처리를 해야하는 경우 기존의 Cursor와는 무관하게 작업이 이루어지는 경우가 있습니다. 이럴 경우에 Oracle은 #0번을 부여해서 트레이스 파일에 남깁니다. 따라서 TKPROF가 이것을 제대로 해석못하게 되는 것이지요.

위의 내용을 잘 이해했다면 TKPROF 리포트가 제공하는 시간 정보를 100% 믿을 수 없다는 제 의견에 충분히 공감하실 것입니다.

저작자 표시
신고
tags :
Trackback 0 : Comments 3
  1. 박성은 2009.09.19 15:51 신고 Modify/Delete Reply

    좋은정보 감사합니다

  2. 왕만두 2009.10.30 16:53 신고 Modify/Delete Reply

    예리하시네요.. 그런게 있었군요

  3. 권대욱 2012.02.18 17:31 Modify/Delete Reply

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

Write a comment

티스토리 툴바