03.SQL 트레이스

이벤트 트레이스 테스트

--level별 테스트

--level4
SQL>  alter session set events '10046 trace name context forever, level 4';

세션이 변경되었습니다.

SQL> var col17 varchar2(20);
SQL> exec :col17 := '642101930';

PL/SQL 처리가 정상적으로 완료되었습니다.

SQL> select a.col5
  2    from test_table1 a
  3       , test_table2 b
  4   where a.col1 = '20160718578354013'
  5     and a.col1 = b.col1
  6     and b.col7 = :col17;

COL5
-------------------------------------------------------------------------------
테스트1857835
테스트1857835

SQL> alter session set events '10046 trace name context off';

--trace 파일 내용
PARSING IN CURSOR #11529215044982025096 len=149 dep=0 uid=0 oct=3 lid=0 tim=16830876425546 hv=1635187749 ad='c000000088bab468' sqlid='2hxjps9hrdz15'
select a.col5
  from test_table1 a
     , test_table2 b
 where a.col1 = '20160718578354013'
   and a.col1 = b.col1
   and b.col7 = :col17
END OF STMT
PARSE #11529215044982025096:c=0,e=349,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=16830876425544
BINDS #11529215044982025096:
 Bind#0
  oacdty=01 mxl=128(40) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=840 siz=128 off=0
  kxsbbbfp=9fffffffbf3e0668  bln=128  avl=09  flg=05
  value="642101930"
EXEC #11529215044982025096:c=0,e=1758,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1594570479,tim=16830876427454
FETCH #11529215044982025096:c=0,e=98,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,plh=1594570479,tim=16830876427583
FETCH #11529215044982025096:c=0,e=160,p=0,cr=12,cu=0,mis=0,r=1,dep=0,og=1,plh=1594570479,tim=16830876428580
STAT #11529215044982025096 id=1 cnt=2 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=21 pr=0 pw=0 time=93 us cost=16 size=52 card=1)'
STAT #11529215044982025096 id=2 cnt=1 pid=1 pos=1 obj=353487 op='TABLE ACCESS BY INDEX ROWID TEST_TABLE1 (cr=3 pr=0 pw=0 time=26 us cost=2 size=26 card=1)'
STAT #11529215044982025096 id=3 cnt=1 pid=2 pos=1 obj=353488 op='INDEX UNIQUE SCAN TEST_TABLE1_PK (cr=2 pr=0 pw=0 time=17 us cost=1 size=0 card=1)'
STAT #11529215044982025096 id=4 cnt=2 pid=1 pos=2 obj=353489 op='TABLE ACCESS BY INDEX ROWID TEST_TABLE2 (cr=18 pr=0 pw=0 time=64 us cost=14 size=26 card=1)'
STAT #11529215044982025096 id=5 cnt=148 pid=4 pos=1 obj=353490 op='INDEX RANGE SCAN TEST_TABLE2_PK (cr=3 pr=0 pw=0 time=17 us cost=1 size=0 card=142)'

BINDS로 시작되는 정보가 추가되었다.
value="642101930" 부분을 보면 쿼리를 수행하며 입력하였던 bind 값을 확인할 수 있다.

--level8
alter session set events '10046 trace name context forever, level 8';

다음 내용이 추가되었다.
WAIT #11529215044982021216: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=16833712920967

tkprof output 파일에 다음 내용이 추가되었다.
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       13.14         13.14
********************************************************************************

--level12
BIND 정보와 WAIT 정보가 추가되었다.

Elapsed time 테스트

SQL> set timing on
SQL> set arraysize 10
SQL> alter session set events '10046 trace name context forever, level 8';

세션이 변경되었습니다.

경   과: 00:00:00.00
SQL> select patname from acpatbat where resno1 like '81%';

PATNAME
--------------------------------------------------------------------------------
테스트0559111
테스트0294403
테스트0294417
테스트0497943
테스트0524114
테스트0669113
테스트0669225
테스트0669228

45790 개의 행이 선택되었습니다.

경   과: 00:00:23.66


SQL ID: cbdv9jruuwpcu
Plan Hash: 3743901090
select patname 
from
 acpatbat where resno1 like '81%'


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     4580      1.14       3.27      22558      27772          0       45790
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4582      1.14       3.27      22558      27772          0       45790

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

Rows     Row Source Operation
-------  ---------------------------------------------------
  45790  INDEX FAST FULL SCAN ACPATBAT_IDX1 (cr=27772 pr=22558 pw=0 time=965233 us cost=4011 size=1007391 card=47971)(object id 137687)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    4580        0.00          0.00
  Disk file operations I/O                        2        0.00          0.00
  db file scattered read                        237        0.10          2.41
  SQL*Net message from client                  4580       58.52         78.70
  db file sequential read                         3        0.00          0.00

=>
총 건수 45790개이고 arraysize를 10으로 해서 fetch count는 4580, DB 내부적으로는 총 3.27초 소요가 되었으나 경과 시간은 23.66초이다. 
나머지 시간은 애플리케이션으로부터 추가 Call을 기다리면서 Idle 상태로 대기한 시간이다.
또한 cpu time은 1.14초이나 elapsed time은 3.27초이고 나머지 2.13초는 대기 상태에 빠졌던 것으로 이해하면 된다.
--------------------------------------------------------------------------------------------------------------------
그런데.. 대기이벤트에서 보면 80초가량이 대기인데.. 왜 실제 경과시간은 23초 정도이지??
arraysize 설정을 하지 않고 실행해보니 그래도 비슷한 대기 시간이 나왔다. 

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     459        0.00          0.00
  SQL*Net message from client                   458        0.08         22.31

arraysize 관련해서 제대로 대기시간을 측정하지 못하는 것 같다.
--------------------------------------------------------------------------------------------------------------------

Service

SQL> show parameter service_name

NAME                                 TYPE                   VALUE
------------------------------------ ---------------------- ------------------------------
service_names                        string                 ORA11G
SQL> select sid, service_name, module, action
  2  from v$session
  3  where service_name <> 'SYS$BACKGROUND';
  SID SERVICE_NAME     MODULE              ACTION
----- ---------------- ------------------- -----------------------
~~ 생략

서비스별 trace

--설정
--dbms_monitor 패키지는 10g부터 사용 가능
exec dbms_monitor.serv_mod_act_trace_enable(service_name=>'ORA11G'
,module_name=>dbms_monitor.all_modules
,action_name=>dbms_monitor.all_actions
,waits=>true
,binds=>true
);

--실행중인 trace 확인
select primary_id service_name
     , qualifier_id1 module
     , qualifier_id2 action
     , waits, binds
from dba_enabled_traces;

--해제
exec dbms_monitor.serv_mod_act_trace_disable(service_name=>'ORA11G'
,module_name=>dbms_monitor.all_modules
,action_name=>dbms_monitor.all_actions
);

모듈별 trace

--모듈 설정
exec dbms_application_info.set_module(module_name = > 'son manager', action_name => 'son select test');

--설정
exec dbms_monitor.serv_mod_act_trace_enable(service_name=>'ORA11G'
,module_name=>'son manager'
,action_name=>dbms_monitor.all_actions
,waits=>true
,binds=>true
);

--해제
exec dbms_monitor.serv_mod_act_trace_disable(service_name=>'ORA11G'
,module_name=>'son manager'
,action_name=>dbms_monitor.all_actions
);

액션별 trace

--액션 설정
exec dbms_application_info.set_action(action_name => 'son select test2');

--설정
exec dbms_monitor.serv_mod_act_trace_enable(service_name=>'ORA11G'
,module_name=>'son manager'
,action_name=>'son select test2'
,waits=>true
,binds=>true
);

--해제
exec dbms_monitor.serv_mod_act_trace_disable(service_name=>'ORA11G'
,module_name=>'son manager'
,action_name=>'son select test2'
);

client_indentifier별 trace

--client_identifier 설정
exec dbms_session.set_identifier('sontest');

--설정
exec dbms_monitor.client_id_trace_enable(client_id=>'sontest',waits=>false,binds=>false);

--해제
exec dbms_monitor.client_id_trace_disable(client_id=>'sontest');