[Oracle] 10046 event Trace 분석

10046 TRACE 기본

- Header

  - 서버정보

  - 세션정보

- Content

  - SQL 수행 정보

     - SQL 문 메타 정보

     - SQL Statement

     - Bind 정보

     - Execute 정보

     - Fetch 정보

     - Wait Event 정보

     - Stat 정보

  - SQL 수행 정보

  - SQL 수행 정보

  - SQL 수행 정보

 

 

10046 TRACE 상세

[ 8i Header ]

 

Dump file /app/oracle/admin/tgdom/udump/ora_809958_tgdom_t.trc

Oracle8i <?xml:namespace prefix = st1 ns = "urn:schemas-microsoft-com:office:smarttags" /><?xml:namespace prefix = st1 />Enterprise Edition Release 8.1.7.4.0 - Production

With the Partitioning option

JServer Release 8.1.7.4.0 - Production

ORACLE_HOME = /app/oracle/product/8.1.7

System name:       AIX

Node name:          sel630a

Release: 2

Version:  5

Machine:             005DC2AF4C00

Instance name: tgdom

Redo thread mounted by this instance: 1

Oracle process number: 275

Unix process pid: 809958, image: oracle@sel630a (TNS V1-V3)

*** 2009-04-17 13:24:41.098

*** SESSION ID:(196.1903) 2009-04-17 13:24:41.082

APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240

 

[ 9 Header ]

 

/app/oracle/admin/tgdom/udump/ora_1042212.trc

Oracle9i Enterprise Edition Release 9.0.1.4.0 - Production

With the Partitioning and Real Application Clusters options

JServer Release 9.0.1.4.0 - Production

ORACLE_HOME = /app/oracle/product/9.0.1

System name:       OSF1

Node name:          tgdom1

Release: V5.1

Version:  1885

Machine:             alpha

Instance name: tgdom1

Redo thread mounted by this instance: 1

Oracle process number: 22

Unix process pid: 1042212, image: oracle@tgdom1 (TNS V1-V3)

 

*** 2009-04-17 13:28:04.795

*** SESSION ID:(14.2507) 2009-04-17 13:28:04.779

APPNAME mod='SQL*Plus' mh=18446744073084533344 act='' ah=18446744073444361560

 

[ 10G(R2) ]

 

/app/oracle/admin/tgdom/udump/tgdom_ora_3562.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production

With the Partitioning, OLAP, 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: 37

Unix process pid: 3562, image: oracle@ktx6600t (TNS V1-V3)

 

*** 2009-04-17 13:34:34.710

*** ACTION NAME:() 2009-04-17 13:34:34.709

*** MODULE NAME:(SQL*Plus) 2009-04-17 13:34:34.709

*** SERVICE NAME:(SYS$USERS) 2009-04-17 13:34:34.709

*** SESSION ID:(74.5978) 2009-04-17 13:34:34.709

 

 

[19c]  --> 얘만 SQL 문장이 다름

Trace file /u01/app/oracle/diag/rdbms/pgdb1t/PGDB11T/trace/PGDB11T_ora_8913292_10046_truncate.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.16.0.0.0
Build label:    RDBMS_19.16.0.0.0DBRU_AIX.PPC64_220701
ORACLE_HOME:    /u01/app/oracle/product/19.0.0.0/dbhome_1
System name: AIX
Node name: pgdb11t
Release: 2
Version: 7
Machine: 00C50CC14B00
Instance name: PGDB11T
Redo thread mounted by this instance: 1
Oracle process number: 114
Unix process pid: 8913292, image: oracle@pgdb11t

 

8,9 Field	10g Field	의미
act	ACTION NAME	DBMS_APPLICATION_INFO 에 설정한 Action 명
ah		Action 의 Hash Value
mod	MODULE NAME	DBMS_APPLICATION_INFO 에 설정한 Module 명
mh		Module의 Hash Value
	SERVICE NAME	Listener 의 Service Name 으로 Local 에서 접속할 경우 SYS$USER로 부여됨

 

 

[세션 정보]
*** 2024-09-05T17:46:39.228412+09:00
*** SESSION ID:(969.45621) 2024-09-05T17:46:39.228440+09:00
*** CLIENT ID:() 2024-09-05T17:46:39.228446+09:00
*** SERVICE NAME:(PGDB1T) 2024-09-05T17:46:39.228453+09:00
*** MODULE NAME:(Orange for ORACLE DBA ) 2024-09-05T17:46:39.228459+09:00
*** ACTION NAME:(7.0.0 (Build:12,S)) 2024-09-05T17:46:39.228466+09:00
*** CLIENT DRIVER:() 2024-09-05T17:46:39.228472+09:00
 

 

Contents 부분비교

앞서 언급한 Trace Log 의 구조에서 보면 Contents 는 각 단위 SQL의 수행정보의 모음이라고 했기 때문에 많은 양의 로그는 볼 것도 없고 우리가 수행한 SQL의 수행정보만 골라서 분석하면 될 것이다.

그렇다면 우선 SQL 수행정보에서 메타 정보와 SQL 문장 정보를 비교해 보자.

 

[8i 에서의 SQL 메타 정보와 Statement ]

PARSING IN CURSOR #1 len=276 dep=0 uid=21 oct=3 lid=21 tim=3735144217 hv=372838635 ad='36becc74'

select rnum, b.object_name, object_id, owner

from test10046 a, test_master b

where a.object_name = b.object_name

and b.owner = :v_owner

union

select sum(rnum), min(b.object_name), avg(object_id), max(owner)

from test10046 a, test_master b

where a.object_name = b.object_name

END OF STMT

 

[ 9i 에서의 SQL 메타 정보와 Statement ]

PARSING IN CURSOR #1 len=275 dep=0 uid=61 oct=3 lid=61 tim=1239942507562337 hv=1316923968 ad='9729678'

select rnum, b.object_name, object_id, owner

from test10046 a, test_master b

where a.object_name = b.object_name

and b.owner = :v_owner

union

select sum(rnum), min(b.object_name), avg(object_id), max(owner)

from test10046 a, test_master b

where a.object_name = b.object_name

END OF STMT

 

[ 10g 에서의 SQL 메타 정보와 Statement ]

PARSING IN CURSOR #2 len=275 dep=0 uid=64 oct=3 lid=64 tim=415143425622 hv=146669042 ad='f22c6278'

select rnum, b.object_name, object_id, owner

from test10046 a, test_master b

where a.object_name = b.object_name

and b.owner = :v_owner

union

select sum(rnum), min(b.object_name), avg(object_id), max(owner)

from test10046 a, test_master b

where a.object_name = b.object_name

END OF STMT

 

[19c 에서의 SQL 메타정보와 Statement ]

PARSING IN CURSOR #4848485816 len=332 dep=1 uid=0 oct=3 lid=0 tim=6716713899272 hv=2698389488 ad='700010053e4ece0' sqlid='acmvv4fhdc9zh'
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2, spare3, signature, spare7, spare8, spare9, nvl(dflcollid, 16382), creappid, creverid, modappid, modverid, crepatchid, modpatchid 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

 

각 버전에서 우리는 동일한 문장을 수행했기 때문에 SQL Statement 는 당연히 동일할 것이다.

그리고 PARSING IN CURSOR 로 시작하는 부분도 내용은 약간 틀리지만 그 항목은 동일하다는 것을 알 수 있다. 이 부분의 내용은 다음과 같다.

8i, 9i, 10g Field	의미
CURSOR#	Cursor 의 번호로 이것은 이 SQL 이 수행할 당시의 오픈된 Cursor 의 최대값을 의미
len	수행한 SQL 문장의 Length
dep	Recursive SQL 의 Depth를 의미하는데 0 이 아니면 Recursive SQL임 반대로 말하면 dep=0 만 일반 SQL
uid	Current Schema의 UserID 로 ALL_USERS 의 User_ID 와 같은 값
oct	Oracle Command Type 으로 파싱 시 SQL 의 형태를 나타내는 코드를 의미함. 여기서는 3은 Select 임.
lib	Privilege 를 체크 하기 위해 사용하는 User ID 로 보통 uid 와 같음
tim	해당 라인이 기록된 시간으로 V$TIMER 의 값을 사용함 보통 9i 이전에는 1/100초 단위(millisecond) 이고         9i 이후 부터는 1/1,000,000 단위(Microsecond)임
hv	SQL 문의 Hash id
ad	SQL Text Address 로 V$SQLAREA 또는 V$SQLTEXT 의 ADDR 과 동일함

 

 

SQL 문을 수행하는 프로세스에서 SQL 문장의 구문 분석이 끝나면 Parsing, Bind, Execute, Fetch 순으로 진행되는데 Trace Log 에도 이러한 순서로 기록이 되어 있다.

이 과정에 대한 각각의 log 내용을 살펴보도록 하자.

 

[8i 에서의 Parsing ]

PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=3735144217

[ 9i 에서의 Parsing ]

PARSE #1:c=1952,e=2930,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=1239942507562337

[10g 에서의 Parsing ]

PARSE #2:c=0,e=1064,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,tim=415143425617

[19c에서의 Parsing ]

PARSE #4848485816:c=214,e=673,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=6716713899271

 

8i,9i,10g Field	의미
#	Cursor 의 번호
c	CPU Time 으로 9i 까지는 millisecond 이고,                10g 부터 microsecond 임
e	Elapsed Time 으로 8i 까지는 millisecond 이고                    9i 부터는 microsecond 임
p	Physical Read 횟수
cr	Consistent Block Read 의 횟수
cu	Current Block Read 의 횟수
mis	Cursor 의 Cache Miss 의 횟수
r	진행된 Row 수
dep	Recursive Call 의 Depth
og	Optimizer Goal 을 의미함 [ 1: All_Rows, 2: First_Rows, 3: Rule, 4: Choose ]
tim	기록 시간

 

Bind 의 경우는 다음과 같다.

Bind 는 8i 와 9i 는 동일하지만 10g 에서는 많은 변화가 있는 듯 하지만

실제로는 Field 의 명칭만 변경되었다.

[8i 에서의 Binds ]

BINDS #1:

 bind 0: dty=1 mxl=32(03) mal=00 scl=00 pre=00 oacflg=03 oacfl2=10 size=32 offset=0

   bfp=2015516c bln=32 avl=03 flg=05

   value="SYS"

 

[9i 에서의 Binds ]

BINDS #1:

 bind 0: dty=1 mxl=32(03) mal=00 scl=00 pre=00 oacflg=03 oacfl2=10 size=32 offset=0

   bfp=14032f9a8 bln=32 avl=03 flg=05

   value="SYS"

 

[10g 에서의 Binds ]

BINDS #2:

kkscoacd

 Bind#0

  oacdty=01 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00

  oacflg=03 fl2=1000000 frm=01 csi=871 siz=32 off=0

  kxsbbbfp=9fffffffbee21d50  bln=32  avl=03  flg=05

value="SYS"

 

[19c에서의 Binds ]

BINDS #4848485816:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=80 off=0
  kxsbbbfp=121134448  bln=22  avl=03  flg=05
  value=156
 Bind#1
  oacdty=01 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=846 siz=0 off=24
  kxsbbbfp=121134460  bln=32  avl=08  flg=01
  value="EDI_RECV"
 Bind#2
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=0 off=56
  kxsbbbfp=121134480  bln=22  avl=02  flg=01
  value=1

 

8i,9i Field	10g Field	의미
Binds#	BINDS#	Bind 하는 SQL 의 Cursor 번호
bind	BIND#	KK 는 SQL 의 Parsing 및 Optimizer 을 담당하는 Compilation Layer를 의미함. Kkscoacd는 해당 layer의 함수로 생각됨
dty	oacdty	Data Type code [ 1: Varchar2, 2: Number, 8: Long, 12: date, 23: Raw,  69: rowed, 96: Char, 111: Clob, 112: Blob, 180: Timestamp ]
mxl	mxl	Bind 변수의 Max Length, 괄호 안은 현재 value 의 Length
mal	mal	Array Bind 변수나 bulk Operation 을 수행할 때의 max array length
scl	scl	Scale
pre	pre	Precision
oacflg	oacflg	Internal flag 로 만약 값이 홀수 이면 Bind 변수는 null 이 가능하다는 의미임(nullable)
oacfl2	fl2	Internal flag 의 확장을 위해 마련해 놓은 field
size	siz	Bind Buffer 를 위해 할당된 Memory Chunk 의 크기
offset	off	해당 Memory Chunk의 시작점
bfp	kxsbbbfp	Bind Buffer 의 주소
bin	bin	Bind Buffer 의 길이
avl	avl	Actual Value Length 로 실제 value 또는 array 의 길이
flg	flg	Bind 변수의 상태를 알려주는 flag
value	value	Bind 변수의 실제 값

 

 

다음은 Execute 와 Fetch 의 내용인데 이 Operation 의 내용은 Parse 와 동일하며

역시 버전 별로도 거의 동일함을 알 수 있다.

[ 8i 에서의 Execute, Fetch ]

EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3735144217

WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0

WAIT #1: nam='file open' ela= 0 p1=0 p2=0 p3=0

WAIT #1: nam='db file sequential read' ela= 1 p1=4 p2=93322 p3=1

WAIT #1: nam='db file sequential read' ela= 0 p1=4 p2=93450 p3=1

WAIT #1: nam='db file sequential read' ela= 1 p1=4 p2=94765 p3=1

…중간 생략…

WAIT #1: nam='db file scattered read' ela= 0 p1=4 p2=93226 p3=16

WAIT #1: nam='db file scattered read' ela= 0 p1=4 p2=93244 p3=32

WAIT #1: nam='db file scattered read' ela= 0 p1=4 p2=93276 p3=14

FETCH #1:c=42,e=231,p=2333,cr=4221,cu=27,mis=0,r=1,dep=0,og=4,tim=3735144448

 

[ 9i 에서의 Execute, Fetch ]

EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1239942507565267

WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0

FETCH #1:c=584624,e=584956,p=0,cr=3511,cu=0,mis=0,r=1,dep=0,og=4,tim=1239942508151199

WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1650815232 p2=1 p3=0

WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0

FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=1239942508151199

이하 생략…

 

[ 10g 에서의 Execute, Fetch ]

EXEC #2:c=10000,e=1477,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=415143427263

WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=54384 tim=415143427297

FETCH #2:c=1840000,e=1805913,p=0,cr=2527,cu=0,mis=0,r=1,dep=0,og=2,tim=415145233236

WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=54384 tim=415145233803

WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=54384 tim=415145233845

FETCH #2:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=2,tim=415145233879

이하 생략…

 

[19c 에서의 Execute, Fetch ]

EXEC #4849994224:c=1376,e=7109,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,plh=3984801583,tim=6716713915007
WAIT #4849994224: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915067
WAIT #4849994224: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915105
WAIT #4849994224: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915137

FETCH #4849994224:c=54,e=172,p=0,cr=3,cu=0,mis=0,r=0,dep=2,og=4,plh=3984801583,tim=6716713915202

 

8i,9i,10g Field	의미
#	Cursor의 번호
c	CPU Time 으로 9i 까지는 millisecond 이고                10g 부터 microsecond 임
e	Elasped Time 으로 8i 까지는 millisecond 이고                    10g 부터 microsecond 임
p	Physical Read 횟수
cr	Consistent Block Read 의 횟수
cu	Current Block Read 의 횟수
mis	Cursor 의 Cache Miss의 횟수
r	진행된 Row 수
dep	Recursive Call 의 Depth
og	Optimizer Goal 을 의미함 [ 1: All_rows, 2:First_Rows, 3: Rule, 4:Choose ]
tim	기록 시간

 

그런데 8i 에서 진행된 Row 수가 굉장히 큰 수지로 나타나는 것을 확인 할 수 있다.

 

[ 잡지와 다르 테스트 수행 결과 ]

그런데 이것을 TKPROF 로 돌린 결과로 보면 Execute 때는 0으로 표시된다.

원래 r Filed 의 값은 double 형이기 때문에 유효숫자의 자리수가 15자리 밖에 되지 않음에도

불구하고 19가지로 표시되었다.

이는 이것이 10진수가 아니라는 의미이다. 그렇다. 이 수치는 16진수이다.

Execute 시의 Row 수는 ‘9223372041149743104’ 라고 표시 되는데 이를 16 진수로 나타내 보면

‘8000 0001 0000 0000’ 이다. 앞의 8자리는 flag 라고 생각하고 나머지 수치를 보면 0 이다.

그래서 TKPROF 를 수행한 결과가 0인 것이다.

그 밖에 버전 별로 차이가 나타나는 것은 없다.

 

이제 Trace Log 에서 남은 부분은 Stat 과 Event 를 나타내어 주는 부분이다.

이 중 Event 를 표시하는 부분은 8 Level 또는 12 Level 로 Trace 를 남길 경우 가장 많은 부분을 차지 한다고 생각된다. 또한 이 부분은 성능 분석에 있어 병문의 원인을 알 수 있는 부분이기 때문에 OWI 와 같은 Wait Event 기반의 성능 분석에 있어서 가장 중요한 항목이다.

오라클도 10g 에서 보다 더 분석에 용이하도록 인터페이스를 변경시킨 것으로 보인다.

아래의 버전 별 예를 살펴보도록 하자.

[ 8i 에서의 Event ]

WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0

WAIT #1: nam='file open' ela= 0 p1=0 p2=0 p3=0

WAIT #1: nam='db file sequential read' ela= 1 p1=4 p2=93322 p3=1

 

[ 9i 에서의 Event ]

WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1650815232 p2=1 p3=0

WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1650815232 p2=1 p3=0

 

[ 10g 에서의 Event ]

WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=54384 tim=415145233803

WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=54384 tim=415145233845

 

[ 19c 에서의 Event ] 

WAIT #4849994224: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915067
WAIT #4849994224: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915105
WAIT #4849994224: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=-1 tim=6716713915137

 

8i,9i Field	10g Field	의미
WAIT#	WAIT#	Wait 을 발생시키는 SQL의 Cursor 번호
nam	nam	발생한 Wait Event 의 이름
ela	ela	Wait 시간으로 8i 까지는 millisecond 이고               9i 부터 microsecond 임
P1	Parameter1	Wait Event 의 p1,p2,p3 로 9i 까지는 Filed 명에 p1,p2,p3 로 찍히지만, 10g 부터는 각 Parameter가 의미하는 내용을 표시. 이는 V$EVENT_NAME 의 내용과 동일함
P2	Parameter2
P3	Parameter3
	Obj#	해당 Event 가 발생한 Object ID 로 실제 Object 와 관련이 없는 Wait Event( 예를 들면 네트웍크 관련 Event) 는 의미가 없는 값이 들어감
	tim	해당 Log 가 기록된 시간

 

 

State 은 쉽게 말해 tkprof 의 Plan 정보를 보여주는 부분이다.

오라클은 9i 부터 Stat 부분의 내용을 보강하였다.

8i 까지 SQL 튜닝을 하다 보면 아쉬웠던 부분이 가장 오랫동안 지속된 Operation 이 무엇인지 그리고 얼마나 많은 블록을 사용했는지에 대한 것이다.

9i 에서는 STATISTICS_LEVEL 이라는 파라미터가 TYPICAL 이 Default 이다.

이럴 경우 10046 이벤트는 8i 와 같은 수준의 Trace Log 를 남기기 때문에 새로이 추가된 정보를 보기 위해서는 세션레벨이라도 STATISTICS_LEVEL을 ALL 로 변경시키고 나서 Event 를 걸어주여야 한다. 다음의 예를 통해 어떠한 변화가 있는지를 살펴보도록 하자.

 

[ 8i 에서의 Stat ]

STAT #1 id=1 cnt=2001 pid=0 pos=0 obj=0 op='SORT UNIQUE '

STAT #1 id=2 cnt=2001 pid=1 pos=1 obj=0 op='UNION-ALL '

STAT #1 id=3 cnt=2000 pid=2 pos=1 obj=0 op='NESTED LOOPS '

STAT #1 id=4 cnt=96 pid=3 pos=1 obj=79770 op='TABLE ACCESS BY INDEX ROWID TEST_MASTER '

STAT #1 id=5 cnt=96 pid=4 pos=1 obj=79772 op='INDEX RANGE SCAN '

STAT #1 id=6 cnt=2000 pid=3 pos=2 obj=79769 op='TABLE ACCESS BY INDEX ROWID TEST10046 '

STAT #1 id=7 cnt=2095 pid=6 pos=1 obj=79771 op='INDEX RANGE SCAN '

STAT #1 id=8 cnt=1 pid=2 pos=2 obj=0 op='SORT AGGREGATE '

STAT #1 id=9 cnt=4112 pid=8 pos=1 obj=0 op='HASH JOIN '

STAT #1 id=10 cnt=173 pid=9 pos=1 obj=79770 op='TABLE ACCESS FULL TEST_MASTER '

STAT #1 id=11 cnt=500000 pid=9 pos=2 obj=79769 op='TABLE ACCESS FULL TEST10046 '

 

[ 9i 에서의 Stat ]

STAT #1 id=1 cnt=9984 pid=0 pos=0 obj=0 op='SORT UNIQUE '

STAT #1 id=2 cnt=9984 pid=1 pos=1 obj=0 op='UNION-ALL '

STAT #1 id=3 cnt=9983 pid=2 pos=1 obj=0 op='HASH JOIN '

STAT #1 id=4 cnt=109 pid=3 pos=1 obj=879881 op='TABLE ACCESS BY INDEX ROWID TEST_MASTER '

STAT #1 id=5 cnt=109 pid=4 pos=1 obj=879883 op='INDEX RANGE SCAN '

STAT #1 id=6 cnt=500000 pid=3 pos=2 obj=879880 op='TABLE ACCESS FULL TEST10046 '

STAT #1 id=7 cnt=1 pid=2 pos=2 obj=0 op='SORT AGGREGATE '

STAT #1 id=8 cnt=15396 pid=7 pos=1 obj=0 op='HASH JOIN '

STAT #1 id=9 cnt=164 pid=8 pos=1 obj=879881 op='TABLE ACCESS FULL TEST_MASTER '

STAT #1 id=10 cnt=500000 pid=8 pos=2 obj=879880 op='TABLE ACCESS FULL TEST10046 '

 

[ 10g 에서의 Stat ]

STAT #2 id=1 cnt=178645 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2527 pr=0 pw=0 time=1810096 us)'

STAT #2 id=2 cnt=178645 pid=1 pos=1 obj=0 op='UNION-ALL  (cr=2527 pr=0 pw=0 time=1608806 us)'

STAT #2 id=3 cnt=178644 pid=2 pos=1 obj=0 op='HASH JOIN  (cr=1263 pr=0 pw=0 time=537044 us)'

STAT #2 id=4 cnt=109 pid=3 pos=1 obj=54384 op='TABLE ACCESS BY INDEX ROWID TEST_MASTER (cr=2 pr=0 pw=0 time=373 us)'

STAT #2 id=5 cnt=109 pid=4 pos=1 obj=54386 op='INDEX RANGE SCAN IDX_MASTER (cr=1 pr=0 pw=0 time=68 us)'

STAT #2 id=6 cnt=500000 pid=3 pos=2 obj=54383 op='TABLE ACCESS FULL TEST10046 (cr=1261 pr=0 pw=0 time=40 us)'

STAT #2 id=7 cnt=1 pid=2 pos=2 obj=0 op='SORT AGGREGATE (cr=1264 pr=0 pw=0 time=795897 us)'

STAT #2 id=8 cnt=178644 pid=7 pos=1 obj=0 op='HASH JOIN  (cr=1264 pr=0 pw=0 time=536975 us)'

STAT #2 id=9 cnt=288 pid=8 pos=1 obj=54384 op='TABLE ACCESS FULL TEST_MASTER (cr=3 pr=0 pw=0 time=34 us)'

STAT #2 id=10 cnt=500000 pid=8 pos=2 obj=54383 op='TABLE ACCESS FULL TEST10046 (cr=1261 pr=0 pw=0 time=25 us)'

 

 

[19c 에서의 Stat]

STAT #4849994224 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 str=1 time=188 us cost=6 size=386 card=2)'
STAT #4849994224 id=2 cnt=0 pid=1 pos=1 obj=0 op='HASH JOIN OUTER (cr=3 pr=0 pw=0 str=1 time=174 us cost=5 size=386 card=2)'
STAT #4849994224 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=3 pr=0 pw=0 str=1 time=26 us cost=2 size=300 card=2)'
STAT #4849994224 id=4 cnt=0 pid=3 pos=1 obj=19 op='TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 str=1 time=23 us cost=2 size=196 card=2)'
STAT #4849994224 id=5 cnt=1 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 str=1 time=14 us cost=1 size=0 card=1)'
STAT #4849994224 id=6 cnt=0 pid=3 pos=2 obj=75 op='TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=0 pr=0 pw=0 str=0 time=0 us cost=0 size=52 card=1)'
STAT #4849994224 id=7 cnt=0 pid=6 pos=1 obj=76 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=0 pr=0 pw=0 str=0 time=0 us cost=0 size=0 card=1)'
STAT #4849994224 id=8 cnt=0 pid=2 pos=2 obj=0 op='VIEW  (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=43 card=1)'
STAT #4849994224 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT GROUP BY (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=15 card=1)'
STAT #4849994224 id=10 cnt=0 pid=9 pos=1 obj=31 op='TABLE ACCESS CLUSTER CDEF$ (cr=0 pr=0 pw=0 str=0 time=0 us cost=2 size=15 card=1)'
STAT #4849994224 id=11 cnt=0 pid=10 pos=1 obj=30 op='INDEX UNIQUE SCAN I_COBJ# (cr=0 pr=0 pw=0 str=0 time=0 us cost=1 size=0 card=1)'

 

8i Field	9i Field	10g Filed	의미
STAT#	STAT#	STAT#	SQL의 Cursor 번호
id	id	Id	Plan 의 Line 번호 1부터 시작
cnt	cnt	cnt	해당 Operation 에서 진행된 Row 수
pid	pid	pid	Hierachical 하게 생성되는 Plan 에서 해당 Step의 Parent 가 되는 Operation 의 id, 즉 Parent ID
pos	pos	pos	Plan 에서의 Position
obj	obj	obj	해당 Operation 에서 참조하는 Object id
op	op	op	Operation 이 이름으로 9i, 10g 에서는 이 op 항목에서 아래와 같은 부가적인 정보가 기록됨
	cr	cr	해당 Operation 에서 발생한 logical Reads 의 의미
	r	pr	해당 Operation 에서 발생한 Physical Reads 의 의미
	w	pw	해당 Operation 에서 발생한 Physical Writes 의 의미
	time	Time	해당 Operation 의 소요 시간

 

그 밖에도 아래와 같은 항목들이 Trace Log 에 기록된다.

 

[ 8i 에서의 항목 ]

UNMAP #1:c=0, e=0, p=0, cr=0, cu=0, mis=0, r=9223376430606319616, dep=0, og=3, tim=1430130863 [ 이 부분은 책에만 나옴 – 테스트 중에는 발생 하지 않았음 ]

XCTEND rlbk=0, rd_only=1

 

[ 9i 에서의 항목 ]

XCTEND rlbk=0, rd_only=1

 

[ 10g 에서의 항목 ]

XCTEND rlbk=0, rd_only=1

 

[19c 에서의 항목]

XCTEND rlbk=0, rd_only=1, tim=6716714881429

 

위의 8i 에서는 다른 버전과 달리 UNMAP 이라는 항목이 있다.

그러나 이것은 모든 버전에서 공통적으로 사용되지만 8i 에서는 위의 Event 에서 예를 든 것처럼 Direct IO 가 발생하였다. UNMAP 은 Direct IO 시 할당되는 Temporary segment 를 놓아줄 때 나타나는데 9i 부터는 PGA 부분의 아키텍쳐가 개선되어 Sort 나 Hash 작업을 할 때 상대적으로 넉넉한 공간을 사용하게 되어 direct IO 가 발생하지 않아 이러한 항목이 나타나지 않은 것으로 생각할 수 있다.

UNMAP 의 여러 항목들은 앞서 EXEC 나 PARSE 등과 내용이 같다.

 

XCTEND 는 Transaction Boundary 를 의미하는데 이 항목이 기록된 때 무언가 Transaction 이 구분되는 작업이 발생했음을 알 수 있게 된다.

세부 항목은 다음과 같다.

8i, 9i, 10g Field	의미
rlbk	Rollback flag 로 값이 0 이면 commit을                      1 이며 Rollback 이 되었음을 나타냄
rd_only	Read Only Flag 값이 1 이면 해당 transaction 은 read-only 이고                      0 이면 변경 및 commit 이 되었음을 나타냄

 

예에서는 모두 rlbk 가 0 이고 rd_only 가 1 인 것으로 보아 읽기 전용으로 작업을 했고,

Commit 을 했다는 것을 알수 있다.

그런데 우리는 select 작업을 했기 때문에 read only 인 것은 확실하나 commit 을 하지는 않았다.

SQL*PLUS 는 우리가 exit 로 프로그램을 끝마칠 때 암묵적으로 Commit 을 수행한다.

이러한 이유로 rlbk 값이 0 인 것이다.

 

결론

지금까지 10046 Trace Log 의 Raw Source 를 가지고 버전 별 비교를 수행하였다.

10046 Trace 는 개별 SQL 에 대한 성능을 분석하기 위한 목적으로 수행하는 것이니만큼

성능 분석 도구로서 얼마나 잘 이용할 수 있느냐에 초점을 맞추는 것이 당연하다 생각한다.

이러한 차원에서 버전이 올라가면서 Wait Event 와 Stat 에 정보가 추가되어 가는 추세는 아주 바람직하다고 생각한다. 이를 통해 우리는 해당 SQL 의 어느 부분에서 어떤 이유로 지연이 되고 있는지를

더욱 정확하고 빠르게 알 수 있게 되었기 때문이다.

 

그러나 TKPROF 에서는 아직도 추가된 정도를 적극적으로 활용하지 못하고 있는 측면도 있다고 생각한다.

그렇기 때문에 이렇게 Raw Source 를 놓고서 분석을 해보는 것도 의미가 있기는 하지만 무엇보다도 새로운 정보를 이용한 성능 분석 방법에 대한 모색이 필요할 것이라고 생각한다.