태터데스크 관리자

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

태터데스크 메시지

저장하였습니다.

'tkprof'에 해당되는 글 3건

  1. 2009.09.17 TKPROF 결과 해석시 조심해야할 함정 - CURSOR #0 (3)
  2. 2009.09.04 TKPROF 리포트 해석시 시간값을 조심하자 (5)
  3. 2008.01.09 How to trace sql exectuion - Oracle 11g의 Real-Time SQL Monitoring (4)

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

오라클 2009. 9. 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 : tkprof
Trackbacks 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


TKPROF 리포트 해석시 시간값을 조심하자

오라클 2009. 9. 4. 11:26
SQL*Trace와 그 친구인 Tkprof는 너무나 사용하기 편하고, 또 사랑스러운 친구들이지만 "시간"에 관해서는 종종 혼란을 줍니다. 흔히 접하게 되는 SQL*Trace의 시간 오류는 다음과 같습니다.
  • CPU Wait Time: 보통 대기 시간이라고 하면 경합이 발생해서 CPU를 점유하지 않고 대기하는 시간을 말하지만, CPU 자체를 획득하기 위해 대기하는 시간도 있습니다. 이 시간은 Oracle의 측정 범위 자체를 벗어나는 값입니다. 동시 사용자가 많은 시스템에서는 이 값으로 인한 오류가 더욱 커집니다.
  • CURSOR #0 시간: Oracle이 내부적으로 수행하는 특정 Query는 CURSOR#0으로 표현됩니다. 가령 LOB 데이터를 Fetch하는 과정은 부모 Cursor와는 별개로 CURSOR# 0이라는 Internal Cursor를 사용하게 됩니다. 당연히 이 시간은 부모 Cursor에 반영되지 않습니다. 실제 수행 시간은 100초인데 tkprof의 결과를 보면 1초 이렇게 나오게 됩니다. 이런 사례가 종종 존재합니다.
  • 아직 계산하지 않는 대기시간: Oracle 내부에서 대기가 발생할 때 아직 대기 이벤트로 기록되지 않는 경우도 있습니다. 이런 경우는 당연히 대기 시간에서 빠지게 됩니다.
  • 기타 등등?
아래는 측정 오류를 보여주는 테스트 결과입니다.
create table t1
as 
select level as c1, level as c2, level as c3, level as c4, level as c5
from dual
connect by level <= 1000;

select * from t1;

-- 1st 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.00       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.01       0.02          0         73          0        1000

-- 2nd 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.01       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.03       0.02          0         73          0        1000

-- 3rd 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.03       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.04       0.02          0         73          0        1000


-- 4th 실행
select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.00       0.00          0         73          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.04       0.02          0         73          0        1000
상당히 부정확해보이죠?

하지만 이런 시간 오류들은 Oracle의 잘못이라기 보다는 아키텍처 차원의 문제에 가깝습니다. 계속 보완해 나가겠지만 완전한 측정은 절대 기대해서는 안됩니다. 그래서 해석을 하는 실력이 중요한 것이지요.

tags : SQL*Trace, tkprof
Trackbacks 0 : Comments 5
  1. 김진호 2009.09.05 19:06 Modify/Delete Reply

    감사합니다. 제가 질문한 내용을 포스팅까지 해주셨네요
    이제 오라클 시작하는 초보단계지만 열심히 해서 저도 엑셈에 도전하고 싶습니다.
    주말 잘보내세요^^

  2. 예맥 2010.04.29 11:40 Modify/Delete Reply

    4th에서의 실행시간은 0.02는 1/100분초 표현한것으로 압니다. 즉, 0.0002초가 수행된것으로 해석하는데
    어느곳은 1/1000초라는 곳도 있어요.. 헷갈리네요.. 또 트레이스에서 (cr=100 pr=1649 time=1234)라고 나오면
    time은 1/1000000라고 알고 있습니다.. 왜 이렇게 오라클은 헷갈리게 표현할까요? 제가 아는 단위가 정확한가요?

    • 욱짜 2010.04.29 15:55 신고 Modify/Delete

      Tkprof의 집계리포트에서 보여주는 부분(Parse/Execute/Fetch)은 초(second)단위입니다. 즉, 0.02는 0.02초입니다.

      최근 버전의 오라클에서는 시간을 측정할 때 항상 Microsecond(1/1000000)초를 사용합니다. 따라서 (cr=100 pr=1649 time=1234)에서의 time은 0.001234초가 됩니다. 10046 트레이스 파일에서도 CPU 사용시간은 Centisecod단위로 계산되는 것으로 알려져 있습니다. 이때문에 CPU 사용시간이 Elapsed Time보다 크게 나타나는 현상이 생깁니다.

      기타 Dynamic View에서는 아직도 많은 경우 Centisecond의 단위를 사용하고 있습니다.

  3. 예맥 2010.04.29 16:50 Modify/Delete Reply

    call count elapsed
    -------------------------------
    Parse 1 0.77
    Execute 1 0.21
    Fetch 1 50583.26
    ------
    Rosw Row Source Operation
    ------------------------------------------
    0 Table Access Full EMP (cr=5393 pr=4804 pw=0 time=5058305us)

    라고 되어있는데 이경우는 row souce가 1/백만 초 이므로 elapse time을 5초로 보아야하지 않나요?
    만약 버전 마다 틀리면 어떻게 해석하죠..
    욱짜님의 parse/execute/fetch 단위가 초이면 틀려지는것이 아닌가요? 참고로 위의 내용은 엔코아의 da#
    으로 트레이스를 남겼을때의 내용입니다.. 더 헷갈립니다..
    늘 빠른 답변, 정확한 답변에 감사드립니다.

    • 욱짜 2010.04.29 20:22 신고 Modify/Delete

      동일한 쿼리를 Oracle이 제공하는 tkprof를 이용하면 어떻게 나오나요?

Write a comment


How to trace sql exectuion - Oracle 11g의 Real-Time SQL Monitoring

오라클 2008. 1. 9. 11:41
우리가 실행한 SQL 문장이 "실제로" 어떻게 수행되었는지 손쉽게 추적하고 모니터링하는 방법은? 여기에 몇 개의 답변을 할 수 있을까?

1) ~ Oracle 9i
Autotrace
SQL Trace

Oracle 9i까지는 Autotrace와 SQL Trace를 이용하면 SQL이 실제로 수행하면서 얼마나 많은 일을 했는지 알 수 있다. 하지만 Autotrace는 실행 단계별 일량(Row source operation 정보라고 흔히 부름)을 남기지 않기 때문에 실제로 SQL을 추적하는데는 한계가 많다.

이런 이유 때문에 대부분의 경우 SQL Trace와 Tkprof를 이용해 SQL을 추적한다. 물론 이것이 얼마나 귀찮은 작업인지는 해본 사람은 다 공감할 것이다.

2) Oracle 10g ~
GATHER_PLAN_STATISTICS 힌트

Oracle 10g에 추가된 이 놀라운 힌트는 그 동안 우리가 그토록 목말라했던 기능을 제공한다. 쿼리를 수행하면서 바로 SQL Trace와 같은 실행 정보 추적을 할 수 없을까? 다음과 같이 가능하다.

select /*+ gather_plan_statistics */ * from t_rtm where id between 1 and 100;

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
SQL_ID  bnxtw0wqkqmx5, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ * from t_rtm where id between 1
and 100

Plan hash value: 2986615217

---------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------------------------------
|   1 |  TABLE ACCESS BY INDEX ROWID| T_RTM     |      1 |     94 |     50 |00:00:00.01 |       5 |
|*  2 |   INDEX RANGE SCAN          | T_RTM_IDX |      1 |     94 |     50 |00:00:00.01 |       3 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("ID">=1 AND "ID"<=100)

gather_plan_statistics라는 힌트 하나만으로 SQL Trace+Tkprof를 수행한 것과 거의 동일한 효과를 얻을 수 있다. 만세~
이 기능은 한가지 큰 장점은 Estimated 값과 Actual 값을 한 눈에 비교해 볼 수 있다는 것이다. 비용 계산이 합리적인지 가늠할 수 있는 기준이 된다.

gather_plan_statistics 힌트은 아래 블로그에서 아주 상세하게 다룬바 있다.
http://ukja.tistory.com/entry/%EC%98%A4%EB%9D%BC%ED%81%B4-%ED%8C%81-GATHERPLANSTATISTICS-%ED%9E%8C%ED%8A%B8

3) Oracle 11g ~
Real-Time SQL Monitoring (v$sql_monitor, v$sql_plan_monitor)

비록 gather_plan_statistics 힌트가 획기적인 기능을 제공하지만, 임시 방편에 불과하다.
가령 실행 시간이 5초 이상되는 느린 쿼리들의 실행 이력(plan과 row source operation까지 포함한)을 볼 수 있는 방법은 없을까?

Oracle 11g에서 추가된 Real-Time Monitoring기능이 그 해답을 제공한다. Oracle은 실행 시간이 5초 이상(_sqlmon_threshold 히든 파라미터로 조정)인 모든 쿼리의 실행 이력 정보를 v$sql_monitor와 v$sql_plan_monitor 뷰에 남긴다. 그리고 dbms_sqltune.report_sql_monitor 함수를 이용해서 정보를 조회할 수 있도록 해준다. 또는 MONITOR 힌트를 사용해서 강제로 추적하게 할 수도 있다. 아래 예를 보자. (정릴이 깨지는 현상 이해 바람)

select /*+ monitor */ * from t_rtm where id between 1 and 100;

select sql_id from v$sql where sql_text like 'select /*+ monitor */ * from t_rtm%';

sql_id = bpfu171khfbg6

select dbms_sqltune.report_sql_monitor(sql_id=>'bpfu171khfbg6') from dual

SQL Monitoring Report

SQL Text
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
select /*+ monitor */ * from t_rtm where id between 1 and 100
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Global Information
 Status              :  DONE (FIRST N ROWS)
 Instance ID         :  1                  
 Session ID          :  147                
 SQL ID              :  bpfu171khfbg6      
 SQL Execution ID    :  16777218           
 Plan Hash Value     :  2986615217         
 Execution Started   :  01/09/2008 11:05:18
 First Refresh Time  :  01/09/2008 11:05:18
 Last Refresh Time   :  01/09/2008 11:05:19

---------------------------------------
| Elapsed |  Other   | Fetch | Buffer |
| Time(s) | Waits(s) | Calls |  Gets  |
---------------------------------------
|    0.00 |     0.00 |     2 |      5 |
---------------------------------------

SQL Plan Monitoring Details
==========================================================================================================================================
| Id |           Operation           |   Name    |  Rows   | Cost |   Time    | Start  | Starts |   Rows   | Activity  | Activity Detail |
|    |                               |           | (Estim) |      | Active(s) | Active |        | (Actual) | (percent) |   (sample #)    |
==========================================================================================================================================
|  0 | SELECT STATEMENT              |           |         |    3 |           |        |      1 |          |           |                 |
|  1 |   TABLE ACCESS BY INDEX ROWID | T_RTM     |      94 |    3 |           |        |      1 |          |           |                 |
|  2 |    INDEX RANGE SCAN           | T_RTM_IDX |      94 |    2 |         1 |     +0 |      1 |       50 |           |                 |
==========================================================================================================================================

기본적으로 gather_plan_statistics와 거의 비슷한 데이터를 제공하는 것을 확인할 수 있다. 이 데이터들은 v$sql_monitor와 v$sql_plan_monitor 뷰에 상주하기 때문에 필요하면 언제든지 직접 조회할 수도 있고, dbms_sqltune.report_sql_monitor 함수를 이용해 간편하게 조회할 수도 있다.

Real-Time SQL Monitoring기능은 DBA나 SQL Tuner들이 쿼리를 튜닝하는 방법을 획기적으로 개선시킬 수 있을 것으로 기대된다. 특별한 이유가 없는 한 더 이상 SQL Trace와 Tkprof를 번갈아가며 사용할 필요가 없을 것이다.


PS) 비록 SQL 실행을 추적할 수 있는 다양한 기법들이 추가되고 있지만, 여전히 SQL Trace는 가장 강력한 SQL 추적 툴이다.

                      SQL Trace여 영원하라~
Trackbacks 0 : Comments 4
  1. 박광서 2010.04.29 15:15 Modify/Delete Reply

    언제나 유익한 정보 감사히 얻고 갑니다.
    늘 건강하세요^^

  2. 이종욱 2010.06.29 10:53 Modify/Delete Reply

    select dbms_sqltune.report_sql_monitor(sql_id=>'20bk5bj29ggpj') from dual;
    실행하면..

    SQL Monitoring Report 메세지와
    SQL Text 까지만 나옵니다~

    infomation 및 plan을 보려면.. 다른 세팅이 필요한건가요??

  3. 카미유 2011.05.05 10:20 Modify/Delete Reply

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

Write a comment