메뉴 건너뛰기

bysql.net

3._SQL트레이스

2012.04.03 16:50

sapius 조회 수:37297

03. SQL 트레이스

(1) 자기 세션에 트레이스 걸기

alter session set sql_trace = true ;
select * from scott.emp where empno = 7900 ;
select * from dual ;
alter session set sql_trace = false ;

user_dump_dest (udump) 파라미터로 지정된 서브 디렉토리에 트레이스 파일 (*.trc) 생성. 
가장 최근에 생성된 파일을 찾아서 분석.

■실습
racodbt1:/oracle/oraracr sql
sqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 19:03:53 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL> show parameter user_dump_dest
NAME                                 TYPE                   VALUE
------------------------------------ ---------------------- ------------------------------
user_dump_dest                       string                 /oracle/orarac/diag/rdbms/orar
                                                           act/ORARACT1/trace

SQL> alter session set sql_trace = true ;

Session altered.

SQL> select * from scott.emp where empno = 7900 ;


    EMPNO ENAME                JOB                       MGR HIREDATE
---------- -------------------- ------------------ ---------- ------------
      SAL       COMM     DEPTNO
---------- ---------- ----------
     7900 JAMES                CLERK                    7698 03-DEC-81
      950                    30


SQL> select * from dual ;


DU
--
X

SQL> SQL> alter session set sql_trace = false ;


Session altered.






racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracels -al

....


drwxr-xr-x    8 orarac   dba          438272 Apr 01 19:03 .
-rw-r-----    1 orarac   dba             136 Apr 01 19:03 ORARACT1_ora_3997708.trm
-rw-r-----    1 orarac   dba            7003 Apr 01 19:03 ORARACT1_ora_3997708.trc
-rw-r-----    1 orarac   dba          848801 Apr 01 19:05 ORARACT1_lmhb_13500578.trm
-rw-r-----    1 orarac   dba        14592326 Apr 01 19:05 ORARACT1_lmhb_13500578.trc
-rw-r-----    1 orarac   dba           78910 Apr 01 19:05 ORARACT1_dbrm_19595516.trm
-rw-r-----    1 orarac   dba         1339312 Apr 01 19:05 ORARACT1_dbrm_19595516.trc
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace



생성된 트레이스 파일 이름 추적

select r.value || '/' || lower(t.instance_name) || '_ora_' || trim(to_char(p.spid)) || '.trc' trace_file
from v$process p, v$session s, v$parameter r, v$instance t
where       p.addr = s.paddr
and          r.name = 'user_dump_dest'
and          s.sid = (select sid from v$mystat where rownum = 1);

■실습
SQL> select r.value || '/' || lower(t.instance_name) || '_ora_' || trim(to_char(p.spid)) || '.trc' trace_file
 2  from v$process p, v$session s, v$parameter r, v$instance t
where       p.addr = s.paddr
and          r.name = 'user_dump_dest'
and          s.sid = (select sid from v$mystat where rownum = 1);
 3    4    5 
TRACE_FILE
--------------------------------------------------------------------------------
/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace/oraract1_ora_3997806.trc

SQL>



> 상기 query 의 경우 dynamic view 에 조회 권한이 있어야하기 때문에 identifier 를 지정해서 트레이스 파일을 생성할 수 있음

alter session set tracefile_identifier = 'oraking';

■실습
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracer sql
sqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 19:30:41 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL> alter system flush buffer_cache;

System altered.

SQL> alter session set tracefile_identifier = 'oraking';

Session altered.

SQL> alter session set sql_trace = true ;

Session altered.

SQL> select * from scott.emp where empno = 7900 ;

    EMPNO ENAME                JOB                       MGR HIREDATE
---------- -------------------- ------------------ ---------- ------------
      SAL       COMM     DEPTNO
---------- ---------- ----------
     7900 JAMES                CLERK                    7698 03-DEC-81
      950                    30


SQL> select * from dual ;

DU
--
X

SQL> alter session set sql_trace = false ;

Session altered.

SQL> quit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracell -tr | tail -15
-rw-r--r--    1 orarac   dba            2721 Apr 01 19:22 report.prf
-rw-r-----    1 orarac   dba              67 Apr 01 19:27 ORARACT1_gcr0_12517592.trm
-rw-r-----    1 orarac   dba            1340 Apr 01 19:27 ORARACT1_gcr0_12517592.trc
-rw-r-----    1 orarac   dba           41900 Apr 01 19:28 ORARACT1_lms0_11599940.trm
-rw-r-----    1 orarac   dba          251237 Apr 01 19:28 ORARACT1_lms0_11599940.trc
-rw-r-----    1 orarac   dba          849761 Apr 01 19:30 ORARACT1_lmhb_13500578.trm
-rw-r-----    1 orarac   dba        14616856 Apr 01 19:30 ORARACT1_lmhb_13500578.trc
-rw-r-----    1 orarac   dba          147278 Apr 01 19:30 alert_ORARACT1.log
drwxr-xr-x    8 orarac   dba          442368 Apr 01 19:31 .
-rw-r-----    1 orarac   dba           38308 Apr 01 19:31 ORARACT1_mmon_8781916.trm
-rw-r-----    1 orarac   dba          386302 Apr 01 19:31 ORARACT1_mmon_8781916.trc
-rw-r-----    1 orarac   dba           79230 Apr 01 19:31 ORARACT1_dbrm_19595516.trm
-rw-r-----    1 orarac   dba         1344132 Apr 01 19:31 ORARACT1_dbrm_19595516.trc
-rw-r-----    1 orarac   dba             130 Apr 01 19:31 ORARACT1_ora_24051824_oraking.trm
-rw-r-----    1 orarac   dba            3167 Apr 01 19:31 ORARACT1_ora_24051824_oraking.trc




* TKProf 유틸리티

trace 파일을 보통의 사용자가 그대로 해석하여 보기는 상당히 난해한 일.

■실습
Trace file /oracle/orarac/diag/rdbms/oraract/ORARACT1/trace/ORARACT1_ora_24051824_oraking.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options
ORACLE_HOME = /oracle/orarac/db
System name:    AIX
Node name:      racodbt1
Release:        1
Version:        6
Machine:        00F6F8FA4C00
Instance name: ORARACT1
Redo thread mounted by this instance: 1
Oracle process number: 40
Unix process pid: 24051824, image: oracle@racodbt1 (TNS V1-V3)


*** 2012-04-01 19:31:07.077
*** SESSION ID:(18.4245) 2012-04-01 19:31:07.077
*** CLIENT ID:() 2012-04-01 19:31:07.077
*** SERVICE NAME:(SYS$USERS) 2012-04-01 19:31:07.077
*** MODULE NAME:(sqlplus@racodbt1 (TNS V1-V3)) 2012-04-01 19:31:07.077
*** ACTION NAME:() 2012-04-01 19:31:07.077

=====================
PARSING IN CURSOR #4573197400 len=35 dep=0 uid=0 oct=42 lid=0 tim=6091944501798 hv=3545163288 ad='11091fe10' sqlid='dbmatmr9nxths'
alter session set sql_trace = true
END OF STMT
EXEC #4573197400:c=31,e=52,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=6091944501797

*** 2012-04-01 19:31:10.212
CLOSE #4573197400:c=6,e=11,dep=0,type=0,tim=6091947636777
=====================
PARSING IN CURSOR #4573197400 len=43 dep=0 uid=0 oct=3 lid=0 tim=6091947636951 hv=180439914 ad='70000004dec4460' sqlid='7sav7r85c2kva'
select * from scott.emp where empno = 7900
END OF STMT
PARSE #4573197400:c=49,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2872589290,tim=6091947636950
EXEC #4573197400:c=24,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2872589290,tim=6091947637049
FETCH #4573197400:c=482,e=2084,p=6,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2872589290,tim=6091947639184
FETCH #4573197400:c=10,e=17,p=0,cr=5,cu=0,mis=0,r=0,dep=0,og=1,plh=2872589290,tim=6091947639517
STAT #4573197400 id=1 cnt=1 pid=0 pos=1 obj=61279 op='TABLE ACCESS FULL EMP (cr=8 pr=6 pw=0 time=2077 us cost=3 size=87 card=1)'

*** 2012-04-01 19:31:15.764
CLOSE #4573197400:c=10,e=17,dep=0,type=1,tim=6091953188812
=====================
PARSING IN CURSOR #4573196224 len=19 dep=0 uid=0 oct=3 lid=0 tim=6091953188976 hv=4060673173 ad='70000004df41c18' sqlid='01fwpqgt0jx4p'
select * from dual
END OF STMT
PARSE #4573196224:c=51,e=86,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3543395131,tim=6091953188976
EXEC #4573196224:c=21,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3543395131,tim=6091953189079
FETCH #4573196224:c=309,e=1423,p=2,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=3543395131,tim=6091953190543
STAT #4573196224 id=1 cnt=1 pid=0 pos=1 obj=116 op='TABLE ACCESS FULL DUAL (cr=2 pr=2 pw=0 time=1419 us cost=2 size=2 card=1)'
FETCH #4573196224:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3543395131,tim=6091953190797

*** 2012-04-01 19:31:19.476
CLOSE #4573196224:c=8,e=12,dep=0,type=1,tim=6091956900757
=====================
PARSING IN CURSOR #4573195048 len=36 dep=0 uid=0 oct=42 lid=0 tim=6091956901359 hv=2321248321 ad='11091fe10' sqlid='dtawmgk55qw21'
alter session set sql_trace = false
END OF STMT
PARSE #4573195048:c=318,e=520,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=6091956901358
EXEC #4573195048:c=23,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=6091956901452
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace


tkprof 유틸리티의 사용법

■실습
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetkprof
Usage: tkprof tracefile outputfile explain= table=
             print= insert= sys= sort=
 table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
 explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
 print=integer    List only the first 'integer' SQL statements.
 aggregate=yes|no
 insert=filename  List SQL statements and data inside INSERT statements.
 sys=no           TKPROF does not list SQL statements run as user SYS.
 record=filename  Record non-recursive statements found in the trace file.
 waits=yes|no     Record summary for any wait events found in the trace file.
 sort=option      Set of zero or more of the following sort options:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    prsela  elapsed time parsing
    prsdsk  number of disk reads during parse
    prsqry  number of buffers for consistent read during parse
    prscu   number of buffers for current read during parse
    prsmis  number of misses in library cache during parse
    execnt  number of execute was called
    execpu  cpu time spent executing
    exeela  elapsed time executing
    exedsk  number of disk reads during execute
    exeqry  number of buffers for consistent read during execute
    execu   number of buffers for current read during execute
    exerow  number of rows processed during execute
    exemis  number of library cache misses during execute
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    fchela  elapsed time fetching
    fchdsk  number of disk reads during fetch
    fchqry  number of buffers for consistent read during fetch
    fchcu   number of buffers for current read during fetch
    fchrow  number of rows fetched
    userid  userid of user that parsed the cursor

racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetkprof ORARACT1_ora_24051824_oraking.trc report.prf sys=no

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 19:33:16 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracecat report.prf

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 19:33:16 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: ORARACT1_ora_24051824_oraking.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch        4      0.00       0.00          8         10          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       11      0.00       0.00          8         10          0           2

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


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

    4  user  SQL statements in session.
    0  internal SQL statements in session.
    4  SQL statements in session.
********************************************************************************
Trace file: ORARACT1_ora_24051824_oraking.trc
Trace file compatibility: 11.1.0.7
Sort options: default

      1  session in tracefile.
      4  user  SQL statements in trace file.
      0  internal SQL statements in trace file.
      4  SQL statements in trace file.
      4  unique SQL statements in trace file.
     60  lines in trace file.
     12  elapsed seconds in trace file.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace

Note ☞ 11g 에서의 결과인데, 책에 나온 10g 샘플과 달라서 10g환경에서 수행하고 결과를 비교해야할 필요가 있음.
       Rows Source Operation 내용이 나오지 않음.


트레이스 결과 분석


OVERALL TOTALS 항목 - Call 통계 - 
autotrace 결과와 비교를 해보면 

* db block gets                     = current
* consistent gets                   = query
* physical reads                    = disk
* SQL*Net roundtrips to/from client = fetch count
* rows processed                    = fetch rows


Rows Source Operation 항목


Note ☞ 11g 실행에서는 이 내용이 없어서 책에 출력된 내용으로 정리

Rows : 수행 단계에서 출력 (Flow-Out)된 로우수를 의미함.

      덧붙임
      버전 7까지는 Process Count 를 보여주다가 8i부터 출력 건수를 바뀌기 시작해
      9i에서는 출력건수 표현으로 확정됨.

      출력건수 표현으로 바뀌면서 생긴 단점 보완을 위해 cr (consistent 모드 블록 읽기),
      pr (디스크 블록 읽기), pw (디스크 블록 쓰기), time (소요시간, us, microsecond)를 표시함.

      9i에서는 pr, pw 대신 r, w로 표현하기도 했음.

부모 row는 자식 노드의 값을 누적한 값을 가짐
      rows source operation 에 표현되는 모든 수치에 이 룰이 적용됨.


* 이벤트 트레이스

오라클은 다양한 이벤트 트레이스 방법을 제공함

■실습
racodbt1:/oracle/oraracsqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 20:08:13 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL> alter session set events '10046 trace name context forever, level 1';

Session altered.

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

Session altered.


장점 : 바인드 변수, 대기 이벤트 현황까지 수집 가능. 설정 가능한 레벨은 1, 4, 8, 12 이며 레벨 1은 일반적은 SQL Trace 와 동일함.

Note ☞ 이벤트 10046 트레이스에 관하여 http://is.gd/KJP00l


이벤트 트레이스의 레벨을 높이면 아래와 같이 해당 세션에서 어떤 부분에서 wait 이벤트가 발생했는지
추적이 가능하며 좀 자세한 병목 지점을 확인하는게 가능하다.

대기이벤트 정보는 쿼리 튜닝의 결정적인 정보를 제공한다.


트레이스 레벨 4 이상을 걸 경우에는 로그 파일의 크기가 급격하게 커지기 때문에 주의 필요.

■실습
ORARACT1_mmon_8781916.trc (0%)racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracer sql
sqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 20:25:54 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

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

Session altered.

SQL> select * from scott.emp e
 2  where e.empno = 9999999
 3  and e.deptno = 10
 4  ;

no rows selected

SQL> select r.value || '/' || lower(t.instance_name) || '_ora_' || trim(to_char(p.spid)) || '.trc' trace_file
 2  from v$process p, v$session s, v$parameter r, v$instance t
where       p.addr = s.paddr
and          r.name = 'user_dump_dest'
and          s.sid = (select sid from v$mystat where rownum = 1);  3    4    5 

TRACE_FILE
--------------------------------------------------------------------------------
/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace/oraract1_ora_15532120.trc

SQL>









racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracemore ORARACT1_ora_15532120.trc 
Trace file /oracle/orarac/diag/rdbms/oraract/ORARACT1/trace/ORARACT1_ora_15532120.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options
ORACLE_HOME = /oracle/orarac/db
System name:    AIX
Node name:      racodbt1
Release:        1
Version:        6
Machine:        00F6F8FA4C00
Instance name: ORARACT1
Redo thread mounted by this instance: 1
Oracle process number: 42
Unix process pid: 15532120, image: oracle@racodbt1 (TNS V1-V3)


*** 2012-04-01 20:26:05.153
*** SESSION ID:(402.2993) 2012-04-01 20:26:05.153
*** CLIENT ID:() 2012-04-01 20:26:05.153
*** SERVICE NAME:(SYS$USERS) 2012-04-01 20:26:05.153
*** MODULE NAME:(sqlplus@racodbt1 (TNS V1-V3)) 2012-04-01 20:26:05.153
*** ACTION NAME:() 2012-04-01 20:26:05.153

WAIT #4573199448: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=6095242573292

*** 2012-04-01 20:26:30.407
WAIT #4573199448: nam='SQL*Net message from client' ela= 25254306 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=6095267828302
CLOSE #4573199448:c=6,e=10,dep=0,type=1,tim=6095267828402
WAIT #4573194168: nam='row cache lock' ela= 294 cache id=8 mode=0 request=3 obj#=-1 tim=6095267829241
=====================
PARSING IN CURSOR #4573192720 len=202 dep=1 uid=0 oct=3 lid=0 tim=6095267829424 hv=3819099649 ad='70000005344a7b0' sqlid='3nkd3g3ju5ph1'
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3
and remoteowner is null and linkname is null and subname is null
END OF STMT
PARSE #4573192720:c=79,e=131,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=853875749,tim=6095267829424
EXEC #4573192720:c=31,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=853875749,tim=6095267829563
WAIT #4573192720: nam='gc cr grant 2-way' ela= 476 p1=1 p2=345 p3=1 obj#=37 tim=6095267830198
WAIT #4573192720: nam='db file sequential read' ela= 193 file#=1 block#=345 blocks=1 obj#=37 tim=6095267830437
WAIT #4573192720: nam='db file sequential read' ela= 164 file#=1 block#=46187 blocks=1 obj#=37 tim=6095267830694
WAIT #4573192720: nam='gc cr grant 2-way' ela= 238 p1=1 p2=15816 p3=1 obj#=37 tim=6095267830995
WAIT #4573192720: nam='db file sequential read' ela= 145 file#=1 block#=15816 blocks=1 obj#=37 tim=6095267831175
FETCH #4573192720:c=424,e=1626,p=3,cr=3,cu=0,mis=0,r=0,dep=1,og=4,plh=853875749,tim=6095267831207
.....














racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetkprof ORARACT1_ora_15532120.trc report.prf sys=no

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 20:29:43 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracecat repo
cat: 0652-050 Cannot open repo.
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracecat report.prf

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 20:29:43 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: ORARACT1_ora_15532120.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

The following statement encountered a error during parse:

select *
from emp e
where e.empno = 9999999
and e.deptno = 10

Error encountered: ORA-00942



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.02         52        493          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.01       0.03         52        500          0           1

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                       6        0.00          0.00
 SQL*Net message from client                     6       44.69        116.87
 row cache lock                                 24        0.00          0.00
 library cache lock                              7        0.00          0.00
 library cache pin                               6        0.00          0.00
 SQL*Net break/reset to client                   3        0.00          0.00
 KJC: Wait for msg sends to complete             1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       38      0.02       0.05          2         18          0           0
Execute    218      0.02       0.06          0          0          0           0
Fetch      228      0.00       0.06         64        605          0         791
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      484      0.05       0.17         66        623          0         791

Misses in library cache during parse: 21
Misses in library cache during execute: 12

Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 row cache lock                                 86        0.00          0.02
 gc cr grant 2-way                              34        0.00          0.01
 db file sequential read                        64        0.01          0.03

    2  user  SQL statements in session.
  26  internal SQL statements in session.
  28  SQL statements in session.
********************************************************************************
Trace file: ORARACT1_ora_15532120.trc
Trace file compatibility: 11.1.0.7
Sort options: default

      1  session in tracefile.
      2  user  SQL statements in trace file.
     26  internal SQL statements in trace file.
     28  SQL statements in trace file.
     26  unique SQL statements in trace file.
    1191  lines in trace file.
     91  elapsed seconds in trace file.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace



* Elapsed time = CPU time + Wait time

내부적 측정 단위와 방법때문에 오차가 있기는 하지만 elapsed time 은 cpu time 과 wait time 의 합으로 정의할 수 있음.

elapsed time = reponse 시점 - call 시점
            ~ cpu time + wait time

elapsed time 은 call 단위 측정

application layer 의 caching 이 없이 dbms transaction 이 들어온다면 select statement 는 최소 3번의 call 이 발생하며, 
dml 문의 경우에는 최소 2번의 call 일 발생한다.

SELECT = PARSE CALL + EXECUTE CALL + FETCH CALL (over 1 times)
DML    = PARSE CALL + EXECUTE CALL 

SELECT 문의 FETCH CALL 횟수는 '전송 레코드 개수 / ARRAY SIZE' 만큼 발생
total elapsed time 은 수행시 발생하는 모든 call 의 elapsed time 을 더해서 구하게 된다,

■실습
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracesqlplus scott/tiger

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 20:48:01 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL> CREATE TABLE BIG_TABLE (USER_SEQ NUMBER, USER_ID VARCHAR2(20), USER_NM VARCHAR2(20), EMAIL VARCHAR2(100), GENDER CHAR(1), NOTE VARCHAR2(500));

Table created.

SQL> DECLARE
 2      I NUMBER := 0;
    BEGIN
       WHILE I < 10000 LOOP
       INSERT INTO BIG_TABLE VALUES (I + 1000001, DBMS_RANDOM.STRING('X', 20), DBMS_RANDOM.STRING('U',20), TO_CHAR(I), 'T', DBMS_RANDOM.STRING('A',100));
       I := I + 1;
       END LOOP;
    END;
/
 3    4    5    6    7    8    9 

PL/SQL procedure successfully completed.

SQL> 
SQL> quit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracesqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 20:49:18 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL> alter system flush buffer_cache;
SQL> set timing on
SQL> set arraysize 100
SQL> alter session set events '10046 trace name context forever, level 8';

Session altered.

Elapsed: 00:00:00.00

SQL> set lines 512 pages 9999
SQL> select * from scott.big_table where user_seq between 1001000 and 1001150;

 USER_SEQ USER_ID                                   USER_NM                                   EMAIL                                                                                                                                                                                                    GE
---------- ---------------------------------------- ---------------------------------------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- --
NOTE
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  1001036 6UP5YQNCT40QU6FG6GJH                      QCZJOVKLKZZEQTZEVOPG                      1035                                                                                                                                                                                                     T
VSjQHXxdqnlJIsRljFeSkhaYtAujlBlerMqpdvwSfGgerRuRsdabJFlPSeztYiIhzbyloOEOLKwbyVpldVLvGWtKrpiCdEAfheQf

  1001037 LZM2RF26II0X07RL30UT                      IQTJJCXWUGDPJKUJWHCQ                      1036                                                                                                                                                                                                     T
xuGrAWhiFsWyLExyDaxdjJnuxqOsYsMCvyiRDVAYxQsAQEdXvmvbXravkVjZPtlBqEQPZyXAqpezNQRtdKTwjnxgTRrSOmanUIQp

  1001038 10GQJIIP5UR9L1FZMON7                      LDQUSYUFZXUIIUPCSXQV                      1037                                                                                                                                                                                                     T
fluyUMRvVIyqQxeoyMwaVQBYiTUQwDqMVcJqUzjHFmBOsTEPCcgGKiQOFOPRPIIrkHhkxOvEzypOjFnkvBXHlGaaqYHkIsyquizq

.
.
.
.


151 rows selected.

Elapsed: 00:00:00.10

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


-rw-r-----    1 orarac   dba             424 Apr 01 20:58 ORARACT1_ora_18481170.trm
-rw-r-----    1 orarac   dba           12209 Apr 01 20:58 ORARACT1_ora_18481170.trc
-rw-r-----    1 orarac   dba           80308 Apr 01 20:58 ORARACT1_dbrm_19595516.trm
-rw-r-----    1 orarac   dba         1360845 Apr 01 20:58 ORARACT1_dbrm_19595516.trc
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetkprof ORARACT1_ora_18481170.trc report.prf sys=no

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 20:58:31 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracecat report.prf 

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 20:58:31 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: ORARACT1_ora_18481170.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.02        166         69          1           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.04         83        257          1         151
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.01       0.06        249        326          2         151

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                       4        0.00          0.00
 SQL*Net message from client                     3       36.95         36.97
 Disk file operations I/O                        1        0.00          0.00
 gc cr grant 2-way                               3        0.00          0.00
 db file sequential read                         5        0.01          0.01
 gc cr multi block request                       8        0.00          0.00
 db file scattered read                         19        0.00          0.01
 SQL*Net more data to client                     2        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

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        1      0.00       0.01        165         68          1           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.01        165         68          1           1

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 gc cr grant 2-way                               3        0.00          0.00
 db file sequential read                         6        0.00          0.00
 gc cr multi block request                       7        0.00          0.00
 db file scattered read                         18        0.00          0.00
 gc current grant 2-way                          1        0.00          0.00

    1  user  SQL statements in session.
    1  internal SQL statements in session.
    2  SQL statements in session.
********************************************************************************
Trace file: ORARACT1_ora_18481170.trc
Trace file compatibility: 11.1.0.7
Sort options: default

      1  session in tracefile.
      1  user  SQL statements in trace file.
      1  internal SQL statements in trace file.
      2  SQL statements in trace file.
      2  unique SQL statements in trace file.
    125  lines in trace file.
      0  elapsed seconds in trace file.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace



책에 소개된 예제를 설명하자면



1000 건을 읽는 상황에서 array size 를 100건으로 설정했기 때문에 one-row fetch 까지 합쳐서 11번의 fetch call 이 발생함. parse/execute 까지합하면 총 13번의 call 이 발생함. 실제 DB 내부적으로 수행한 시간은 0.07초이지만 나버지 시간은 애플리케이션의 추가 call을 기다리면서 서버 프로세스가 idle 상태로 대기한 시간이된다.

Note ☞ one-row fetch 란 sqlplus 등에서 첫번째 fetch 는 arraysize와 무관하게 한건만 가져오는 것을 말함.
       5장 데이터베이스 call 최소화 원리에서 해설함.

cpu time과 elaspe time의 시간차이는 0.07초 동안 DB 내부적으로 일하는 동안에도 cpu를 점유하면서 서버 프로세스가 작업을 한 시간은 불과 0.03초에 불과하다는 것을 말한다. 나머지 0.04초는 서버 프로세스가 wait state 에 있었다는 것을 의미한다.


트레이스 레벨8 설정을 했기 때문에 아래와 같은 대기 이벤트 현황도 tkprof 결과에 출력된다.


SQL*Net message from client / Idle 이벤트로 오라클 서버 프로세스가 사용자에게 결과를 정송하고 다음 Fetch Call이 올때까지 대기한 시간을 더한 값.
11번 발생하는 동안 8.43초 (中 8.71초) 대략 97%의 시간을 차지함. 대체로 이부분은 App과 Network 에서 소모된 시간.

Application 에서 DBMS에서 얻어온 데이터를 가져가는 시간 간격 (think time)이 길다라고 표현하며, think time 이 긴 경우는 보통 서버에서 
데이터를 fetch 하고 클라이언트 내부적으로 많은 연산을 수행한 후에 다음 fetch call 을 날리는 배치 프로그램에서 특히 이 값이 크게 나타남.

SQL*Net message to client / Idle 이벤트. 클라이언트에 메시지를 보냈는데 클라이언트가 ACK를 정해진 시간내에 보내지 못한 경우
db file sequential read / Single Block Read 방식으로 디스크 블록을 읽을때 발생하는 이벤트
SQL*Net more data to client / 클라이언트에 전송할 데이터가 남은 상태에서 네트워크 부하 때문에 바로 전송하지 못할때 발생하는 이벤트
내부적으로 SDU(session data unit)단위로 패킷을 나누어 전송하는데 하나의 SDU 단위 패킷을 전송하는데 받았다는 신호가 정해진 시간보다 늦게 도착하면 이 대기 이벤트가 발생

Elapsed Time 은 Reponse time 과 Call time 의 시점의 차이를 이용해서 구하지만 내부 CPU time과 Wait time 은 각 발생구간의 시간을 더해서 구하며
내부 타이머의 측정 단위 때문에 반올림된 수치를 사용. 따라서 차이가 발생할 수 있는 여지가 존재함.


(2) 다른 세션에 트레이스 걸기

튜닝 대상 SQL이 명확할 경우에는 세션을 열고 해당 세션에 트레이스를 걸고 쿼리를 수행하여 문제를 분석할 수 있지만 실제 시스템에서는 대상을
특정지을 수 없는 경우가 많고, n-tier 기반 시스템에서는 connection pool을 이용한 시스템이 많기 때문에 시스템 레벨로 트레이스를 걸고 수행정보를 수집해야하는 경우가 많다.

Oracle 9i
exec dbms_system.set_ev (145, 3, 10046, 12, '');                                   -- 145번 세션, 시리얼번호 3 세션에 레벨 12로 10046이벤트 트레이스를 걸음.
exec dbms_system.set_ev (145, 3, 10046, 0, '');                                    -- 145번 세션, 시리얼번호 3 세션에 트레이스를 해지함.

exec dmbs_system.set_sql_trace_in_session(sid=>145, serial#=>3, sql_trace=>true);  -- 오라클 권장 방식이 아님.


Oracle 10g 이상
-- dbms_monitor 패키지를 사용해서 트레이스 걸기
begin
    dbms_monitor.session_trace_enable (
         session_id => 145
         , serial_num => 3
         , waits => true
         , binds => true );
end;
/

-- dbms_monitor 패키지를 사용해서 트레이스 해제
begin
    dbms_monitor.session_trace_disable (
         session_id => 145
         , serial_num => 3 );
end;
/


버전 무관

■실습 - 세션 레벨 트레이스 ON/OFF
* 1번 세션
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracesqlplus dbadmin      

SQL*Plus: Release 11.2.0.3.0 Production on Sun Apr 1 22:10:56 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

Enter password:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters and Real Application Testing options

SQL>

* 2번 세션
Wrote file afiedt.buf

 1  SELECT     s.saddr, s.sid, s.serial#, s.username,
 2     s.osuser, s.machine, s.program, s.logon_time, s.status,
 3     p.program, p.spid
 4  FROM v$session s, v$process p
 5  WHERE s.paddr = p.addr
 6* and   s.username='DBADMIN'
SQL> /

SADDR                   SID    SERIAL# USERNAME                                                      OSUSER                                                        MACHINE                                                                                                                          PROGRAM                                                                                          LOGON_TIME   STATUS
---------------- ---------- ---------- ------------------------------------------------------------ ------------------------------------------------------------ -------------------------------------------------------------------------------------------------------------------------------- ------------------------------------------------------------------------------------------------ ------------ ----------------
PROGRAM                                                                                          SPID
------------------------------------------------------------------------------------------------ ------------------------------------------------
070000005D7D6B68         18       4313 DBADMIN                                                       orarac                                                        racodbt1                                                                                                                         sqlplus@racodbt1 (TNS V1-V3)                                                                     01-APR-12    INACTIVE
oracle@racodbt1 (TNS V1-V3)                                                                      18481180
SQL> oradebug setospid 18481180
Oracle pid: 40, Unix process pid: 18481180, image: oracle@racodbt1 (TNS V1-V3)
SQL> oradebug unlimit
Statement processed.
SQL> oradebug event 10046 trace name context forever, level 8
Statement processed.
SQL> oradebug tracefile_name
/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace/ORARACT1_ora_18481180.trc

* 1번 세션

SQL> select * from scott.emp;

    EMPNO ENAME                JOB                       MGR HIREDATE
---------- -------------------- ------------------ ---------- ------------
      SAL       COMM     DEPTNO
---------- ---------- ----------
     7369 SMITH                CLERK                    7902 17-DEC-80
      800                    20

     7499 ALLEN                SALESMAN                 7698 20-FEB-81
     1600        300         30
.
.
.

* 3번 세션

racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracell -tr | tail -15
-rw-r-----    1 orarac   dba           38692 Apr 01 22:12 ORARACT1_mmon_8781916.trm
-rw-r-----    1 orarac   dba          390175 Apr 01 22:12 ORARACT1_mmon_8781916.trc
-rw-r-----    1 orarac   dba           45975 Apr 01 22:13 ORARACT1_lms1_11731096.trm
-rw-r-----    1 orarac   dba          276523 Apr 01 22:13 ORARACT1_lms1_11731096.trc
-rw-r-----    1 orarac   dba           42203 Apr 01 22:13 ORARACT1_lms0_11599940.trm
-rw-r-----    1 orarac   dba          253109 Apr 01 22:13 ORARACT1_lms0_11599940.trc
drwxr-xr-x    8 orarac   dba          450560 Apr 01 22:14 .
-rw-r-----    1 orarac   dba              98 Apr 01 22:15 ORARACT1_ora_15532100.trm
-rw-r-----    1 orarac   dba            1716 Apr 01 22:15 ORARACT1_ora_15532100.trc
-rw-r-----    1 orarac   dba           81268 Apr 01 22:15 ORARACT1_dbrm_19595516.trm
-rw-r-----    1 orarac   dba         1375562 Apr 01 22:15 ORARACT1_dbrm_19595516.trc
-rw-r-----    1 orarac   dba          856164 Apr 01 22:15 ORARACT1_lmhb_13500578.trm
-rw-r-----    1 orarac   dba        14772886 Apr 01 22:15 ORARACT1_lmhb_13500578.trc
-rw-r-----    1 orarac   dba             419 Apr 01 22:15 ORARACT1_ora_18481180.trm
-rw-r-----    1 orarac   dba           17608 Apr 01 22:15 ORARACT1_ora_18481180.trc
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace3
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetkprof ORARACT1_ora_18481180.trc report.prf sys=no

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 22:16:53 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracecat report.prf

TKPROF: Release 11.2.0.3.0 - Development on Sun Apr 1 22:16:53 2012

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: ORARACT1_ora_18481180.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: ggqns3c1jz86c Plan Hash: 2872589290

select *
from
scott.emp


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.01          2         59          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          3          7          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.02          5         66          0          14

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 47 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       14         14         14  TABLE ACCESS FULL EMP (cr=7 pr=3 pw=0 time=1709 us cost=3 size=532 card=14)


Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 library cache lock                              1        0.00          0.00
 row cache lock                                 11        0.00          0.00
 library cache pin                               1        0.00          0.00
 SQL*Net message to client                       2        0.00          0.00
 Disk file operations I/O                        1        0.00          0.00
 gc cr grant 2-way                               1        0.00          0.00
 db file sequential read                         1        0.00          0.00
 gc cr multi block request                       1        0.00          0.00
 db file parallel read                           1        0.00          0.00
 SQL*Net message from client                     1        0.00          0.00



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.01          2         59          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          3          7          0          14
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.02          5         66          0          14

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 from client                     3      283.53        293.95
 SQL*Net message to client                       3        0.00          0.00
 library cache lock                              1        0.00          0.00
 row cache lock                                 11        0.00          0.00
 library cache pin                               1        0.00          0.00
 db file sequential read                         1        0.00          0.00
 Disk file operations I/O                        1        0.00          0.00
 gc cr grant 2-way                               1        0.00          0.00
 gc cr multi block request                       1        0.00          0.00
 db file parallel read                           1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     20      0.00       0.00          0          0          0           0
Fetch       30      0.00       0.00          2         59          0          25
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       51      0.00       0.00          2         59          0          25

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

Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 gc cr block 2-way                               5        0.00          0.00
 db file sequential read                         2        0.00          0.00
 gc current block 2-way                          4        0.00          0.00

    1  user  SQL statements in session.
  13  internal SQL statements in session.
  14  SQL statements in session.
********************************************************************************
Trace file: ORARACT1_ora_18481180.trc
Trace file compatibility: 11.1.0.7
Sort options: default

      1  session in tracefile.
      1  user  SQL statements in trace file.
     13  internal SQL statements in trace file.
     14  SQL statements in trace file.
     14  unique SQL statements in trace file.
    205  lines in trace file.
      0  elapsed seconds in trace file.

.
.
.

* 2번 세션
SQL> oradebug event 10046 trace name context off
Statement processed.
SQL> oradebug close_trace
Statement processed.



■실습 - 시스템 레벨 트레이스 ON/OFF
* 1번 세션

SQL> alter system set sql_trace = true;

System altered.

SQL> alter system set sql_trace = false;

System altered.

SQL>

* 2번 세션

racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracell -tr | tail -15
-rw-r-----    1 orarac   dba          253318 Apr 01 22:19 ORARACT1_lms0_11599940.trc
-rw-r-----    1 orarac   dba            1392 Apr 01 22:21 ORARACT1_reco_9830434.trm
-rw-r-----    1 orarac   dba           52573 Apr 01 22:21 ORARACT1_reco_9830434.trc
-rw-r-----    1 orarac   dba              67 Apr 01 22:21 ORARACT1_gcr0_24707114.trm
-rw-r-----    1 orarac   dba            1340 Apr 01 22:21 ORARACT1_gcr0_24707114.trc
drwxr-xr-x    8 orarac   dba          450560 Apr 01 22:21 .
-rw-r-----    1 orarac   dba           81340 Apr 01 22:21 ORARACT1_dbrm_19595516.trm
-rw-r-----    1 orarac   dba         1376654 Apr 01 22:21 ORARACT1_dbrm_19595516.trc
-rw-r-----    1 orarac   dba             102 Apr 01 22:21 ORARACT1_cjq0_24903810.trm
-rw-r-----    1 orarac   dba            2925 Apr 01 22:21 ORARACT1_cjq0_24903810.trc
-rw-r-----    1 orarac   dba          147604 Apr 01 22:21 alert_ORARACT1.log
-rw-r-----    1 orarac   dba             155 Apr 01 22:21 ORARACT1_ora_15532100.trm
-rw-r-----    1 orarac   dba            3228 Apr 01 22:21 ORARACT1_ora_15532100.trc
-rw-r-----    1 orarac   dba          856400 Apr 01 22:21 ORARACT1_lmhb_13500578.trm
-rw-r-----    1 orarac   dba        14778613 Apr 01 22:21 ORARACT1_lmhb_13500578.trc
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/tracetail -20 alert_ORARACT1.log
Sun Apr 01 05:31:08 2012
CJQ0 started with pid=41, OS id=24903810
Sun Apr 01 06:00:00 2012
Setting Resource Manager plan DEFAULT_MAINTENANCE_PLAN via parameter
Sun Apr 01 06:00:00 2012
Starting background process VKRM
Sun Apr 01 06:00:00 2012
VKRM started with pid=43, OS id=16253114
Sun Apr 01 19:30:42 2012
ALTER SYSTEM: Flushing buffer cache
Sun Apr 01 20:17:31 2012
ALTER SYSTEM: Flushing buffer cache
Sun Apr 01 20:20:02 2012
ALTER SYSTEM: Flushing buffer cache
Sun Apr 01 20:57:33 2012
ALTER SYSTEM: Flushing buffer cache
Sun Apr 01 22:21:02 2012
ALTER SYSTEM SET sql_trace=TRUE SCOPE=MEMORY;
Sun Apr 01 22:21:26 2012
ALTER SYSTEM SET sql_trace=FALSE SCOPE=MEMORY;
racodbt1:/oracle/orarac/diag/rdbms/oraract/ORARACT1/trace



(3) Service, Module, Action 단위로 트레이스 걸기

10g 부터 도입된 기능으로 service, module, action 별로 트레이스를 설정하고 해제할 수 있는 dbms_monitor 패키지가 소개되었음.


- 특정 서비스 명으로 트레이스를 거는 방법
SQL> SQL> begin
 dbms_monitor.serv_mod_act_trace_enable (
    service_name => 'eCRM'
    , module_name => dbms_monitor.all_modules
    , action_name => dbms_monitor.all_actions
    , waits => true
    , binds => true
 );
end;
/
 2    3    4    5    6    7    8    9   10 
PL/SQL procedure successfully completed.

SQL>

SQL> ed
Wrote file afiedt.buf

 1  select primary_id service_name
 2  , qualifier_id1 module
 3  , qualifier_id2 action
 4  , waits, binds
 5* from dba_enabled_traces
SQL> /

SERVICE_NAME    MODULE                                             ACTION               WAITS      BINDS
--------------- -------------------------------------------------- -------------------- ---------- ----------
eCRM                                                                                    TRUE       TRUE

SQL>


이렇게 Service Name 기준으로 트레이스를 걸 경우 앞으로 새로 맺는 커넥션중에서 service_name 이 eCRM이면 자동으로 트레이스가 설정됨.

- 특정 모듈/액션 별로 트레이스 거는 방법
* 1번세션

SQL> begin
 2     dbms_application_info.set_module (
 3             module_name => 'emp manager'
 4             , action_name => 'select emp');
 5  end;
 6  /

PL/SQL procedure successfully completed.

SQL>

* 2번 세션

SQL> select sid, service_name, module, action from v$session where service_name <> 'SYS$BACKGROUND' ;

      SID SERVICE_NAME                                                                                                                     MODULE                                                                                                                           ACTION
---------- -------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------
       13 SYS$USERS                                                                                                                        sqlplus@racodbt1 (TNS V1-V3)
       18 SYS$USERS                                                                                                                        emp manager                                                                                                                      select emp
      398 SYS$USERS                                                                                                                        oraagent.bin@racodbt1 (TNS V1-V3)
      580 SYS$USERS                                                                                                                        oraagent.bin@racodbt1 (TNS V1-V3)
      588 SYS$USERS                                                                                                                        oraagent.bin@racodbt1 (TNS V1-V3)

SQL>

SQL> begin
 2     dbms_monitor.serv_mod_act_trace_enable (
 3             service_name => 'SYS$USERS'
 4             , module_name => 'emp manager'
 5             , action_name => dbms_monitor.all_actions
 6             , waits => true
 7             , binds => true
 8     );
 9  end;
10  /

PL/SQL procedure successfully completed.

SQL> select primary_id service_name, qualifier_id1 module, qualifier_id2 action, waits, binds from dba_enabled_traces;

SERVICE_NAME                                                                                                                     MODULE                                                                                           ACTION                                                            WAITS      BINDS
-------------------------------------------------------------------------------------------------------------------------------- ------------------------------------------------------------------------------------------------ ---------------------------------------------------------------- ---------- ----------
eCRM                                                                                                                                                                                                                                                                                               TRUE       TRUE
SYS$USERS                                                                                                                        emp manager                                                                                                                                                       TRUE       TRUE

SQL>

SQL> begin
  dbms_monitor.serv_mod_act_trace_disable (
          service_name => 'SYS$USERS'
          , module_name => 'emp manager'
          , action_name => dbms_monitor.all_actions
  );
end;
/  2    3    4    5    6    7    8 

PL/SQL procedure successfully completed.

SQL> select primary_id service_name, qualifier_id1 module, qualifier_id2 action, waits, binds from dba_enabled_traces;

SERVICE_NAME                                                                                                                     MODULE                                                                                           ACTION                                                            WAITS      BINDS
-------------------------------------------------------------------------------------------------------------------------------- ------------------------------------------------------------------------------------------------ ---------------------------------------------------------------- ---------- ----------
eCRM                                                                                                                                                                                                                                                                                               TRUE       TRUE

SQL>


상기와 같은 스타일의 트레이싱 가능하게 만들려면 Application 에서 아래와 같은 처리를 해주면서 진행하면 좋다.


상기와 같이 설정하면 update emp 부분에서 병목이 발생하면 해당 SQL을 바로 추적하여 튜닝 포인트로 잡고 튜닝을 실시할 수 있다.

이와 같이 module 기준으로 트레이스를 하기위해서도 dbms_application_info.set_module 프로시저를 한번씩 호출하도록 프로그램을 변경해야한다.
DBMS CALL이 한번씩 더 발생하지만 I/O 작업이 없고 세션 Global 변수값만 바꾸기 때문에 부하와 거의 무관하게 시스템의 상태 추적 정보를
남길 수 있다.

set_action 의 경우에는 OLTP 보다는 OLAP 스타일의 프로그램에 더 적합한 추적 방식이라고 할 수 있다,

이와는 별도로 v$session 뷰의 client_identifier 칼럼에 특정 값이 설정된 세션에만 트레이스를 걸 수 있도있다.
* 1번 세션
SQL> exec dbms_session.set_identifier('oraking');

PL/SQL procedure successfully completed.

* 2번 세션
SQL> select sid, client_identifier, service_name, module, action from v$session where service_name <> 'SYS$BACKGROUND'
/  2 

      SID CLIENT_IDENTIFIER                                   SERVICE_NAME    MODULE                                              ACTION
---------- -------------------------------------------------- --------------- -------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------
       13                                                    SYS$USERS       sqlplus@racodbt1 (TNS V1-V3)
       18 oraking                                             SYS$USERS       emp manager                                         select emp
      398                                                    SYS$USERS       oraagent.bin@racodbt1 (TNS V1-V3)
      580                                                    SYS$USERS       oraagent.bin@racodbt1 (TNS V1-V3)
      588                                                    SYS$USERS       oraagent.bin@racodbt1 (TNS V1-V3)

SQL> begin
 2     dbms_monitor.client_id_trace_enable (
 3             client_id => 'oraking'
 4             , waits => false
 5             , binds => false );
 6  end;
 7  /

PL/SQL procedure successfully completed.

SQL> select primary_id service_name, qualifier_id1 module, qualifier_id2 action, waits, binds from dba_enabled_traces;

SERVICE_NAME    MODULE                                              ACTION                                                            WAITS      BINDS
--------------- -------------------------------------------------- ---------------------------------------------------------------- ---------- ----------
eCRM                                                                                                                                TRUE       TRUE
oraking                                                                                                                             FALSE      FALSE

SQL>


dbms_monitor 패키지를 이용해서 row source operation 과 대기 이벤트 발생현황만 수집 할 수 있는게 아니라 service, module, action 단위로 v$sesstat 통계 정보를 수집하는 기능도 제공함.
dbms_monitor 의 serv_mod_act_stat_enable/serv_mod_act_stat_disable 프로시저를 이용하면 된다.
진행 상태는 dba_enabled_aggregations 뷰를 사용한다.
※ 너무 피곤해서 실습은 ㅜㅜ




■실습 - DBMS에 접속한 세션에 저장된 Module 명 보기
SQL> col module for a50
SQL> col action for a20
SQL> col service_name for a15
SQL> select sid, service_name, module, action
from v$session
where service_name <> 'SYS$BACKGROUND'
/

      SID SERVICE_NAME    MODULE                                             ACTION
---------- --------------- -------------------------------------------------- --------------------
     4918 SYS$USERS
     4920 SYS$USERS       oracle@ngora2 (TNS V1-V3)
     4921 SYS$USERS       JDBC Thin Client
     4922 SYS$USERS       JDBC Thin Client
     4926 SYS$USERS       oracle@ngora3 (TNS V1-V3)
     4929 SYS$USERS       oracle@ngora3 (TNS V1-V3)
     4935 SYS$USERS       oracle@ngora2 (TNS V1-V3)
     4939 SYS$USERS       JDBC Thin Client
     4940 SYS$USERS       JDBC Thin Client
     4942 SYS$USERS       oracle@ngora2 (TNS V1-V3)
     4943 SYS$USERS       JDBC Thin Client
     4947 SYS$USERS       oracle@ngora2 (TNS V1-V3)
...
..



참고자료 ☞ http://is.gd/0GTzlJ, http://is.gd/YAnFl1
■참고 - 어떻게 SERVICE_NAME 을 세팅하는가? http://is.gd/uA0RHT
If you want to use a Oracle Net service name, you must apply following steps to configure Oracle Net on the client side (tnsnames.ora) and on the server side (instance configuration):

1.Configure tnsnames ora:

mytns = 
(DESCRIPTION= 
     (ADDRESS = (PROTOCOL = TCP)(HOST = pbell)(PORT = 1395))
  (CONNECT_DATA= 
    (SERVICE_NAME=myservice)))



2. Configure the instance with the right service name and to register to the right listener

alter system set service_names=myservice;
alter system set local_listener='(ADDRESS=(PROTOCOL=TCP)(HOST=pbell)(PORT=1395))'
alter system register;



Wait 60 seconds and check:

$ tnsping mytns

TNS Ping Utility for Linux: Version 10.2.0.1.0 - Production on 25-MAY-2009 12:39:56

Copyright (c) 1997, 2005, Oracle.  All rights reserved.

Used parameter files:


Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION= (ADDRESS = (PROTOCOL = TCP)(HOST = pbell)(PORT = 1395)) (CONNECT_DATA= (SERVICE_NAME=myservice)))
OK (0 msec)


$ lsnrctl status 

LSNRCTL for Linux: Version 10.2.0.1.0 - Production on 25-MAY-2009 12:41:36

Copyright (c) 1991, 2005, Oracle.  All rights reserved.

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=pbell)(PORT=1395)))
STATUS of the LISTENER
------------------------
Alias                     LISTENER
Version                   TNSLSNR for Linux: Version 10.2.0.1.0 - Production
Start Date                25-MAY-2009 12:35:12
Uptime                    0 days 0 hr. 6 min. 23 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /oracle/product/10.2.0/db_1/network/admin/listener.ora
Listener Log File         /oracle/product/10.2.0/db_1/network/log/listener.log
Listening Endpoints Summary...
 (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=pbell)(PORT=1395)))
Services Summary...
Service "MYSERVICE" has 1 instance(s).
 Instance "db01", status READY, has 1 handler(s) for this service...
Service "db01" has 1 instance(s).
 Instance "db01", status READY, has 1 handler(s) for this service...
Service "db01XDB" has 1 instance(s).
 Instance "db01", status READY, has 1 handler(s) for this service...
Service "db01_XPT" has 1 instance(s).
 Instance "db01", status READY, has 1 handler(s) for this service...
The command completed successfully

$ sqlplus test/test@mytns

SQL*Plus: Release 10.2.0.1.0 - Production on Mon May 25 12:44:12 2009

Copyright (c) 1982, 2005, Oracle.  All rights reserved.


Connecte a :
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> select service_name, count(*) from v$session group by service_name;

SERVICE_NAME                                                       COUNT(*)
---------------------------------------------------------------- ----------
MYSERVICE                                                                 1
SYS$BACKGROUND                                                           16



See also Oracle Net Admin. Guidehttp://download.oracle.com/docs/cd/B19306_01/network.102/b14212/listenercfg.htm#sthref1022

JDBC client must also use in this case the tns service name (in this example 'mytns') from tnsnames.ora instead of the entry that refersto database instance name (SID=db1).
See JDBC doc:http://download.oracle.com/docs/cd/B19306_01/java.102/b14355/urls.htm#BEICDECB

Edited by: P. Forstmann on May 25, 2009 12:53 PM


  • 오라클 고도화 원리와 해법 1 (bysql.net 2012년 1차 스터디)
  • 작성자: 박영창 (sapius)
  • 최초작성일: 2012년 4월 1일
  • 본문서는 bysql.net 스터디 결과입니다 .본 문서를 인용하실때는 출처를 밝혀주세요. http://www.bysql.net
  • 문서의 잘못된 점이나 질문사항은 본 문서에 댓글로 남겨주세요. ^^
이 게시물을
목록
목록
번호 제목 글쓴이 날짜 조회 수
» 3._SQL트레이스 sapius 2012.04.03 37297
25 8._Statspack_AWR 시와처 2012.04.01 11767
24 7._Response_Time_Analysis_방법론과_OWI file 시와처 2012.04.01 5916
23 6._V$SYSTEM_EVENT 시와처 2012.04.01 3507
22 4._동시성_구현_사례 [1] dasini 2012.03.26 11962
21 5._오라클_Lock file 시와처 2012.03.25 12875
20 3._비관적_vs._낙관적_동시성_제어 dasini 2012.03.25 6396
19 2._AutoTrace 남송휘 2012.03.25 3138
18 1._Explain_Plan 남송휘 2012.03.25 4543
17 3장._오라클_성능_관리 남송휘 2012.03.25 3117
16 2._트랜잭션_수준_읽기_일관성 file AskZZang 2012.03.20 6364
15 1._트랜잭션_동시성_제어 AskZZang 2012.03.19 4883
14 11._Shared_Pool 박영창 2012.03.19 3395
13 10._대기_이벤트 박영창 2012.03.18 10624
12 9._Snapshot_too_old 박영창 2012.03.18 9969
11 8._블록_클린아웃 시와처 2012.03.18 12305
10 7._Consistent_vs._Current_모드_읽기 file 시와처 2012.03.18 5708
9 2장._트랜잭션과_Lock AskZZang 2012.03.16 5462
8 6._문장수준_읽기_일관성 file 정찬호 2012.03.11 57563
7 4._Redo file 남송휘 2012.03.11 5606
쓰기
태그