꿈꾸는 개발자, DBA 커뮤니티 구루비

SQL 추적 파일 분석

주로 특정 시점이나 구간에 SQL 성능이 저하되거나 문제가 발생하는 이유를 파악하기 위해 분석함
커서 번호는 커서 종료 시까지 유지되므로 하나의 SQL 추적 파일 내에서 동일한 SQL 이 서로 다른 커서 번호 부여 가능

SQL 추적 파일 직접 분석 시 얻을 수 있는 정보

1. SQL 이 수행될 때마다 사용하는 바인드 변수 값
2. SQL 이 수행될 때마다 발생시키는 파스, 실행, 패치에 대한 수행 시간
3. SQL 이 수행될 때마다 발생시키는 대기 이벤트 발생 시간 및 이벤트 대상 오브젝트

특정 시점이나 구간에 SQL 성능이 저하되는 이유

1. WHERE 절에 특정 값이 들어온 경우 추출하는
데이터가 급격히 증가,WHERE 절에 따른 추출건수 변경에 따른 SQL성능저하
2. 특정 시점에 시스템 자원 사용 과부하 및 병목 발생,
순간적인 핫 블록 경합에 인해 latch: cache buffers chain 발생
3. 특정 시점에 DB 과부하 및 락 경합 등 병목 현상 발생
오른쪽 인덱스 확장 인덱스 경합 ( enq: TX - index contention ) 발생

SQL 이 사용하는 바인드 변수 확인

1. 데이터에 대한 락 경합이 지속적으로 발생
2. 특정 조건에서만 대량 결과 값을 추출하는 WHERE 조건 값 확인
3. SQL 수행 시 에러 발생
4. SQL 튜닝을 위해 샘플 바인드 변수 값 추출

가. SQL 추적 파일을 위한 SQL 수행

 
SQL> ALTER SESSION SET TRACEFILE_IDENTIFIER='10046_sample';

Session altered.

SQL> ALTER SESSION SET TIMED_STATISTICS = TRUE ;

Session altered.

SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE=UNLIMITED ;

Session altered.

SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

Session altered.

SQL> var x char(32);
SQL> var y number;
SQL> exec :x:='TG';

PL/SQL procedure successfully completed.

SQL> exec :y:=123;

PL/SQL procedure successfully completed.

SQL> select count(*) from scott.emp where ename=:x and empno=:y;

  COUNT(*)
----------
         0

SQL> exec :x:='TGGO';

PL/SQL procedure successfully completed.

SQL> exec :y:=1234;

PL/SQL procedure successfully completed.

SQL> select count(*) from scott.emp where ename=:x and empno=:y;

  COUNT(*)
----------
         0

SQL> exec :x:='TGCOME';

PL/SQL procedure successfully completed.

SQL> exec :y:=12345;

PL/SQL procedure successfully completed.

SQL> select count(*) from scott.emp where ename=:x and empno=:y;

  COUNT(*)
----------
         0

SQL> select from scott.emp where ename=:x and empno=:y;
select from scott.emp where ename=:x and empno=:y
       *
ERROR at line 1:
ORA-00936: missing expression


SQL> ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

Session altered.

SQL>

#################

나. SQL 추적 파일 내용

 
[tgdom]tgunix:/app/oracle/admin/tgdom/udump> cat tgdom_ora_20337_10046_sample.trc
/app/oracle/admin/tgdom/udump/tgdom_ora_20337_10046_sample.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, Data Mining and Real Application Testing options
ORACLE_HOME = /app/oracle/product/10.2.0
System name:    HP-UX
Node name:      tgunix
Release:        B.11.31
Version:        U
Machine:        ia64
Instance name: tgdom
Redo thread mounted by this instance: 1
Oracle process number: 322
Unix process pid: 20337, image: oracle@tgunix (TNS V1-V3)

*** 2013-01-09 17:34:45.915
*** ACTION NAME:() 2013-01-09 17:34:45.915
*** MODULE NAME:(SQL*Plus) 2013-01-09 17:34:45.915
*** SERVICE NAME:(SYS$USERS) 2013-01-09 17:34:45.915
*** SESSION ID:(768.5763) 2013-01-09 17:34:45.915
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462426293956
*** 2013-01-09 17:35:00.674
WAIT #3: nam='SQL*Net message from client' ela= 14413549 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462440707755
=====================
PARSING IN CURSOR #4 len=22 dep=0 uid=59 oct=47 lid=59 tim=1462440708028 hv=3923811375 ad='b3d06db8'
BEGIN :x:='TG'; END;
END OF STMT
PARSE #4:c=10000,e=116,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462440708019
BINDS #4:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=32 off=0
  kxsbbbfp=9fffffffbf3dc898  bln=32  avl=00  flg=05
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462440708283
EXEC #4:c=0,e=168,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462440708308
*** 2013-01-09 17:35:22.125
WAIT #4: nam='SQL*Net message from client' ela= 20947018 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462461655374
=====================
PARSING IN CURSOR #3 len=21 dep=0 uid=59 oct=47 lid=59 tim=1462461655844 hv=2424522537 ad='9c8329c8'
BEGIN :y:=123; END;
END OF STMT
PARSE #3:c=0,e=129,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462461655838
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=9fffffffbf3dc470  bln=22  avl=00  flg=05
WAIT #3: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462461656069
EXEC #3:c=0,e=181,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462461656105
WAIT #3: nam='SQL*Net message from client' ela= 3701026 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462465357187
=====================
PARSING IN CURSOR #4 len=58 dep=0 uid=59 oct=3 lid=59 tim=1462465357869 hv=3866278416 ad='adf220f8'
select count(*) from scott.emp where ename=:x and empno=:y
END OF STMT
PARSE #4:c=0,e=450,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1462465357862
BINDS #4:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=56 off=0
  kxsbbbfp=9fffffffbf3dc450  bln=32  avl=32  flg=05
  value="TG                              "
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
  kxsbbbfp=9fffffffbf3dc470  bln=22  avl=03  flg=01
  value=123
EXEC #4:c=0,e=2342,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1462465360284
WAIT #4: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462465360388
FETCH #4:c=0,e=39,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=1462465360464
WAIT #4: nam='SQL*Net message from client' ela= 394 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462465360905
FETCH #4:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462465360932
WAIT #4: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462465360954
WAIT #4: nam='SQL*Net message from client' ela= 4027206 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462469388182
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=82 us)'
STAT #4 id=2 cnt=0 pid=1 pos=1 obj=611995 op='TABLE ACCESS BY INDEX ROWID EMP (cr=1 pr=0 pw=0 time=48 us)'
STAT #4 id=3 cnt=0 pid=2 pos=1 obj=611997 op='INDEX UNIQUE SCAN XPK_EMP (cr=1 pr=0 pw=0 time=42 us)'
=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=59 oct=47 lid=59 tim=1462469388667 hv=472480725 ad='b8439bd0'
BEGIN :x:='TGGO'; END;
END OF STMT
PARSE #3:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462469388659
BINDS #3:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=32 off=0
  kxsbbbfp=9fffffffbf3dc468  bln=32  avl=32  flg=05
  value="TG                              "
WAIT #3: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462469389037
EXEC #3:c=0,e=234,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462469389075
*** 2013-01-09 17:35:34.307
WAIT #3: nam='SQL*Net message from client' ela= 4162706 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462473551836
=====================
PARSING IN CURSOR #4 len=22 dep=0 uid=59 oct=47 lid=59 tim=1462473552224 hv=4033148776 ad='9e41c078'
BEGIN :y:=1234; END;
END OF STMT
PARSE #4:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462473552212
BINDS #4:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=9fffffffbf3dc040  bln=22  avl=03  flg=05
  value=123
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462473552535
EXEC #4:c=0,e=225,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462473552564
WAIT #4: nam='SQL*Net message from client' ela= 4624455 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462478177067
=====================
PARSING IN CURSOR #3 len=58 dep=0 uid=59 oct=3 lid=59 tim=1462478177580 hv=3866278416 ad='adf220f8'
select count(*) from scott.emp where ename=:x and empno=:y
END OF STMT
PARSE #3:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462478177574
BINDS #3:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=56 off=0
  kxsbbbfp=9fffffffbf3dc020  bln=32  avl=32  flg=05
  value="TGGO                            "
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
  kxsbbbfp=9fffffffbf3dc040  bln=22  avl=03  flg=01
  value=1234
EXEC #3:c=0,e=221,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462478177887
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462478177937
FETCH #3:c=0,e=41,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=1462478178007
WAIT #3: nam='SQL*Net message from client' ela= 293 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462478178349
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462478178376
WAIT #3: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462478178397
*** 2013-01-09 17:35:48.364
WAIT #3: nam='SQL*Net message from client' ela= 9101594 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462487280025
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=57 us)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=611995 op='TABLE ACCESS BY INDEX ROWID EMP (cr=1 pr=0 pw=0 time=36 us)'
STAT #3 id=3 cnt=0 pid=2 pos=1 obj=611997 op='INDEX UNIQUE SCAN XPK_EMP (cr=1 pr=0 pw=0 time=31 us)'
=====================
PARSING IN CURSOR #4 len=26 dep=0 uid=59 oct=47 lid=59 tim=1462487280421 hv=2829649640 ad='ac79e968'
BEGIN :x:='TGCOME'; END;
END OF STMT
PARSE #4:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462487280417
BINDS #4:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=32 off=0
  kxsbbbfp=9fffffffbf3dc038  bln=32  avl=32  flg=05
  value="TGGO                            "
WAIT #4: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462487280707
EXEC #4:c=0,e=218,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462487280734
WAIT #4: nam='SQL*Net message from client' ela= 3897109 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462491177886
=====================
PARSING IN CURSOR #3 len=23 dep=0 uid=59 oct=47 lid=59 tim=1462491178316 hv=260797585 ad='b88c3950'
BEGIN :y:=12345; END;
END OF STMT
PARSE #3:c=0,e=136,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462491178308
BINDS #3:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=9fffffffbf3dbc10  bln=22  avl=03  flg=05
  value=1234
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462491178703
EXEC #3:c=0,e=328,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1462491178730
WAIT #3: nam='SQL*Net message from client' ela= 3913389 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462495092161
=====================
PARSING IN CURSOR #4 len=58 dep=0 uid=59 oct=3 lid=59 tim=1462495092538 hv=3866278416 ad='adf220f8'
select count(*) from scott.emp where ename=:x and empno=:y
END OF STMT
PARSE #4:c=0,e=147,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462495092533
BINDS #4:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=56 off=0
  kxsbbbfp=9fffffffbf3dbbf0  bln=32  avl=32  flg=05
  value="TGCOME                          "
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
  kxsbbbfp=9fffffffbf3dbc10  bln=22  avl=04  flg=01
  value=12345
EXEC #4:c=0,e=297,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462495092948
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462495093013
FETCH #4:c=0,e=32,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=1462495093074
WAIT #4: nam='SQL*Net message from client' ela= 284 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462495093404
FETCH #4:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462495093433
WAIT #4: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462495093455
*** 2013-01-09 17:36:05.587
WAIT #4: nam='SQL*Net message from client' ela= 9006306 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462504099783
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=51 us)'
STAT #4 id=2 cnt=0 pid=1 pos=1 obj=611995 op='TABLE ACCESS BY INDEX ROWID EMP (cr=1 pr=0 pw=0 time=30 us)'
STAT #4 id=3 cnt=0 pid=2 pos=1 obj=611997 op='INDEX UNIQUE SCAN XPK_EMP (cr=1 pr=0 pw=0 time=26 us)'
=====================
PARSE ERROR #3:len=50 dep=0 uid=59 oct=3 lid=59 tim=1462504100477 err=936
select from scott.emp where ename=:x and empno=:y
WAIT #3: nam='SQL*Net break/reset to client' ela= 47 driver id=1650815232 break?=1 p3=0 obj#=-1 tim=1462504100636
WAIT #3: nam='SQL*Net break/reset to client' ela= 185 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=1462504100842
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462504100863
WAIT #3: nam='SQL*Net message from client' ela= 6709819 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462510810750
=====================
PARSING IN CURSOR #4 len=55 dep=0 uid=59 oct=42 lid=59 tim=1462510810950 hv=524428051 ad='0'
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'
END OF STMT
PARSE #4:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462510810943
EXEC #4:c=0,e=123,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462510811136
[tgdom]tgunix:/app/oracle/admin/tgdom/udump>

SQL 추적 파일 주요 항목 설명(1)

항목	설명
PARSING IN CURSOR	커서의 구문 및 관련 정보, SQL 추적 파일에 기록된 커서 번호, 커서의 번호는 추적 파일에 기록된 순서이며, 파일 내에서 재사용될 수 있다.
PARSE	파스 정보
BINDS	사용한 바인드 변수 정보
EXEC	실행 정보
FETCH	패치 정보
WAIT	각 단계에서 발생한 대기 이벤트 정보
STAT	수행한 SQL 실행 계획 정보
ERROR	에러 정보
XCTEND	롤백, 커밋 정보

SQL 추적 파일 주요 항목 설명(2)

항목	설명
len	SQL 의 길이(단위: 바이트)
dep	SQL 의 재귀 수준, 값이 0이면 사용자가 사용한 SQL이며 값이 0보다 크면, 사용자 SQL을 처리 하기 위해 오라클이 사용한 재귀 SQL
uid	SQL 을 실행한 사용자 ID, DBA_USER.USER_ID
oct	SQL 명령어 코드, V$SESSION.COMMAND
lid	사용자 ID의 권한 번호
tim	해당 작업이 수행된 시점의 SQL 타임 스탬프
hv	SQL 구문의 해시 값, V$SQ.HASH_VALUE, V$SQLTEXT.HASH_VALUE
ad	해당 작업이 수행된 시점의 SQL 타임 스탬프
END OF STMT	해당 작업이 수행된 시점의 SQL 타임 스탬프


BINDS #4:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(32) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=871 siz=56 off=0
  kxsbbbfp=9fffffffbf3dc450  bln=32  avl=32  flg=05
  value="TG                              "
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
  kxsbbbfp=9fffffffbf3dc470  bln=22  avl=03  flg=01
  value=123

SQL 추적 파일 주요 항목 설명(3)

항목	설명
BINDS #4	SQL 추적 파일의 4번 커서에 대한 바인드 변수 값
Bind#0 ~#1	4번 커서의 바인드 변수 번호
value	바인드 변수의 값
oacdty	바인드 변수 데이터 타입 CHAR 96 VARCHAR2 1 NUMBER 2
mxl	바인드 변수 최대 크기
mal	어레이(Array) 크기
siz	바인드 변수에 할당된 메모리 크기

세션에 레벨 4,12 로 10046 트레이스를 적용해야 함


CURSOR #4
PARSE #4:c=0,e=450,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1462465357862
EXEC #4:c=0,e=2342,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1462465360284
FETCH #4:c=0,e=39,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=1462465360464
FETCH #4:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462465360932

CURSOR #3 
PARSE #3:c=0,e=144,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462478177574
EXEC #3:c=0,e=221,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1462478177887
FETCH #3:c=0,e=41,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,tim=1462478178007
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1462478178376

SQL 추적 파일 주요 항목 설명(4)

항목	설명
c	CPU 사용 시간( 단위: 1/1,000,000 초)
e	SQL 수행 시간( 단위: 1/1,000,000 초)
p	디스크 I/O 횟수
cr	읽기 일관성 블록을 읽은 횟수
cu	현재 블록을 읽은 횟수
mis	공유 풀에 SQL이 저장되어 있지 않아서 하드 파싱이 수행된 횟수
r	추출 행 수
og	옵티마이저 모드 1 - ALL_ROWS 2 - FIRST_ROWS, FIRST_ROWS_n 3 - RULE 4 - CHOOSE
tim	해당 작업이 수행된 시점의 오라클 타임 스탬프


STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=0 pw=0 time=82 us)'
STAT #4 id=2 cnt=0 pid=1 pos=1 obj=611995 op='TABLE ACCESS BY INDEX ROWID EMP (cr=1 pr=0 pw=0 time=48 us)'
STAT #4 id=3 cnt=0 pid=2 pos=1 obj=611997 op='INDEX UNIQUE SCAN XPK_EMP (cr=1 pr=0 pw=0 time=42 us)'

SQL 추적 파일 주요 항목 설명(5)

항목	설명
id	실행 계획 단계 ID
cnt	실행 계획 단계별 추출 행 수
pid	부모 실행 계획 ID
pos	실행 계획 단계별 위치
obj	실행 계획에서 사용한 오브젝트 ID. DBA_OBJECTS.OBJECT_ID
op	실행 계획
cr	읽기 일관성 버퍼 캐시 I/O 횟수
pr	디스크에서 읽은 I/O 횟수
pw	디스크로 내려쓴 I/O 횟수
time	수행 시간(단위:1/1,000,000초)


WAIT #4: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462465360954
WAIT #4: nam='SQL*Net message from client' ela= 4027206 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1462469388182

SQL 추적 파일 주요 항목 설명(6)

항목	설명
nam	대기 이벤트 이름
Ela	이벤트 대기 시간(단위, 1/1,000,000 초)
p1,p2,p3	대기 벤트 파라미터 값


XCTEND rlbk=0, rd_only=1
...
PARSE ERROR #3:len=50 dep=0 uid=59 oct=3 lid=59 tim=1462504100477 err=936

SQL 추적 파일 주요 항목 설명(7)

항목	설명
rlbk	ROLLBACK 이라면 1, COMMIT 이라면 0 이 표시된다.
rd_only	COMMIT 이나 ROLLBACK 시 변경된 데이터 없으면 1 있으면 0으로 표시된다.
err	오라클 에러 코드

ORA-00936: missing expression

SQL 추적 파일 분석 (by darkturtle) [2013.01.09]