关于oracle trace文件

结合Oracle文档学习Trace文件，以一个简单的例子创建trace

一．创建trace

SQL> create table t_trace(a number);

SQL> insert into t_trace values(1);

SQL> commit;

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

Session altered

SQL> select a from t_trace;

A

----------

1

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

SQL> SELECT a.VALUE

2 || b.symbol

3 || c.instance_name

4 || '_ora_'

5 || d.spid

6 || '.trc' trace_file

7 FROM (SELECT VALUE

8 FROM v$parameter

9 WHERE NAME = 'user_dump_dest') a,

10 (SELECT SUBSTR (VALUE, -6, 1) symbol

11 FROM v$parameter

12 WHERE NAME = 'user_dump_dest') b,

13 (SELECT instance_name

14 FROM v$instance) c,

15 (SELECT spid

16 FROM v$session s, v$process p, v$mystat m

17 WHERE s.paddr = p.addr AND s.SID = m.SID AND m.statistic# = 0) d

18 /

TRACE_FILE

--------------------------------------------------------------------------------

E:ORACLEPRODUCT10.2.0ADMINSPSDEVUDUMPspsdev_ora_17628.trc

二．分析trace

*** 2009-08-18 14:42:05.177

=====================

PARSING IN CURSOR #3 len=68 dep=0 uid=108 oct=42 lid=108 tim=6016648268 hv=2804619552 ad='2ee83408'

alter session set events '10046 trace name context forever,level 12'

END OF STMT

--------------------------------------------------

--------------------------------------------------

PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X'

END OF STMT

----------------------------------------------------------------------------

Cursor number.

len Length of SQL statement.

dep Recursive depth of the cursor.

uid Schema id under which SQL was parsed.

oct Oracle command type.

lid Privilege user id.

tim Timestamp.

Pre-Oracle9i, the times recorded by Oracle only have a resolution

of 1/100th of a second (10mS). As of Oracle9i some times are

available to microsecond accuracy (1/1,000,000th of a second).

The timestamp can be used to determine times between points

in the trace file.

The value is the value in V$TIMER when the line was written.

The timer has platform-specific implementation differences.

If there are TIMESTAMPS in the file you can use the difference

between 'tim' values to determine an absolute time.

hv Hash id.

ad SQLTEXT address (see views V$SQLAREA Note 43761.1 and V$SQLTEXT Note 43764.1).

The actual SQL statement being parsed.

----------------------------------------------------

逐个参数分析:

1.len=68

select length('alter session set events ''10046 trace name context forever,level 12''') from dual;

LENGTH('ALTERSESSIONSETEVENTS'

------------------------------

68

2. dep

3. uid & 5.lid

select username,user_id

from dba_users

where user_id=108;

-----------------------------

SPSCASE 108

4.oct ---

6.select t.SQL_TEXT,t.PARSING_USER_ID,t.PARSING_SCHEMA_ID,t.ADDRESS,t.HASH_VALUE

from v$sqlarea t

--------------------------------

alter session **** 108 108 2ee83408 2804619552

--------------------------------------------------

EXEC #3:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6016648263

WAIT #3: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6016689813

WAIT #3: nam='SQL*Net message from client' ela= 2745 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6016694135

WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6016696806

WAIT #0: nam='SQL*Net message from client' ela= 1063252 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017763492

--------------------------------------------------

--------------------------------------------------

c CPU time (centiseconds prior to 9i, microseconds rounded to

centiseconds granularity on 9i and above)

e Elapsed time (centiseconds prior to 9i, microseconds thereafter)

p Number of physical reads.

cr Number of buffers retrieved for CR reads.

cu Number of buffers retrieved in current mode.

mis Cursor missed in the cache.

r Number of rows processed.

dep Recursive call depth (0 = user SQL, >0 = recursive).

og Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose

tim Timestamp (100th's of sec < Oracle9i, Microseconds thereafter)

Use this to determine the time between any 2 operations.

c0 约等于0.01秒 e105 为105微秒

WAIT An event that we waited for.

nam What was being waited for .

The wait events here are the same as are seen in

view V$SESSION_WAIT Note 43718.1. For any Oracle release a

full list of wait events and the values in P1, P2 and P3 below

can be seen in view V$EVENT_NAME Note 43721.1

ela Elapsed time for the operation.

p1 P1 for the given wait event.

p2 P2 for the given wait event.

p3 P3 for the given wait event.

--------------------------------------------------

=====================

PARSING IN CURSOR #2 len=21 dep=0 uid=108 oct=3 lid=108 tim=6017767385 hv=1163816132 ad='2a61ad80'

select a from t_trace

END OF STMT

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

BINDS #2:

EXEC #2:c=0,e=1534,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6017776108

WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017777618

FETCH #2:c=0,e=121,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=6017779709

WAIT #2: nam='SQL*Net message from client' ela= 680 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017781881

FETCH #2:c=0,e=26,p=0,cr=2,cu=0,mis=0,r=0,dep=0,og=1,tim=6017783554

WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017785037

WAIT #2: nam='SQL*Net message from client' ela= 3182 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017789639

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=299419 op='TABLE ACCESS FULL T_TRACE (cr=7 pr=0 pw=0 time=102 us)'

WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6017793456

WAIT #0: nam='SQL*Net message from client' ela= 1133220 driver id=1413697536 #bytes=1 p3=0 obj#=10209 tim=6018928391

=====================

PARSING IN CURSOR #1 len=55 dep=0 uid=108 oct=42 lid=108 tim=6018932707 hv=2217940283 ad='2cff4894'

alter session set events '10046 trace name context off'

END OF STMT

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

BINDS #1:

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

--------------------------------------------------

--------------------------------------------------

STAT # id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']

----------------------------------------------------------------------------

STAT Lines report explain plan statistics for the numbered .

Cursor which the statistics apply to.

id Line of the explain plan which the row count applies to (starts

at line 1). This is effectively the row source row count

for all row sources in the execution tree.

cnt Number of rows for this row source.

As of 7.3.3 the items in '[...]' are also reported:

pid Parent id of this row source.

pos Position in explain plan.

obj Object id of row source (if this is a base object).

op='...' The row source access operation.

These let you know the 'run time' explain plan.

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=299419 op='TABLE ACCESS FULL T_TRACE (cr=7 pr=0 pw=0 time=102 us)'

--------------------------------------------------

参考: Metalink Document: Note 39817.1

[@more@]

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/256370/viewspace-1026137/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/256370/viewspace-1026137/