浅谈Oracle SQL trace-ylw6006

dickrong

　　[oracle@dg53 udump]$ cat /home/oracle/trace02.log （tkprof处理后将看不到绑定变量信息）

　　TKPROF:>　　Copyright (c) 1982, 2005, Oracle.  All rights reserved.
　　Trace file: dg53_ora_18857_hr_trace02.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
　　********************************************************************************
　　alter session set events '10046 trace name context forever,level 12'
　　call     count       cpu    elapsed       disk      query    current        rows
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　Parse        0      0.00       0.00          0          0          0           0
　　Execute      1      0.00       0.00          0          0          0           0
　　Fetch        0      0.00       0.00          0          0          0           0
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　total        1      0.00       0.00          0          0          0           0
　　Misses in library cache during parse: 0
　　Optimizer mode: ALL_ROWS

　　Parsing user>　　Elapsed times include waiting on following events:
　　Event waited on                             Times   Max. Wait  Total Waited
　　----------------------------------------   Waited  ----------  ------------
　　SQL*Net message to client                       1        0.00          0.00
　　SQL*Net message from client                     1        0.00          0.00
　　********************************************************************************
　　select salary
　　from
　　employees where employee_id=:id
　　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        2      0.00       0.01          1          2          0           1
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　total        4      0.00       0.01          1          2          0           1
　　Misses in library cache during parse: 0
　　Optimizer mode: ALL_ROWS

　　Parsing user>　　Rows     Row Source Operation
　　-------  ---------------------------------------------------
　　1  TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=1 pw=0 time=16216 us)

　　1   INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=0 pw=0 time=128 us)(object>　　Rows     Execution Plan
　　-------  ---------------------------------------------------
　　0  SELECT STATEMENT   MODE: ALL_ROWS
　　1   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'EMPLOYEES'
　　(TABLE)
　　1    INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_EMP_ID_PK' (INDEX
　　(UNIQUE))
　　Elapsed times include waiting on following events:
　　Event waited on                             Times   Max. Wait  Total Waited
　　----------------------------------------   Waited  ----------  ------------
　　SQL*Net message to client                       2        0.00          0.00
　　db file sequential read                         1        0.01          0.01
　　SQL*Net message from client                     2        0.00          0.00
　　********************************************************************************
　　alter session set events '10046 trace name context off'
　　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        0      0.00       0.00          0          0          0           0
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　total        2      0.00       0.00          0          0          0           0
　　Misses in library cache during parse: 0
　　Optimizer mode: ALL_ROWS

　　Parsing user>　　********************************************************************************
　　OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
　　call     count       cpu    elapsed       disk      query    current        rows
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　Parse        2      0.00       0.00          0          0          0           0
　　Execute      3      0.00       0.00          0          0          0           0
　　Fetch        2      0.00       0.01          1          2          0           1
　　------- ------  -------- ---------- ---------- ---------- ----------  ----------
　　total        7      0.00       0.01          1          2          0           1
　　Misses in library cache during parse: 0
　　Elapsed times include waiting on following events:
　　Event waited on                             Times   Max. Wait  Total Waited
　　----------------------------------------   Waited  ----------  ------------
　　SQL*Net message to client                       5        0.00          0.00
　　SQL*Net message from client                     5       10.32         15.71
　　db file sequential read                         1        0.01          0.01
　　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
　　3  user  SQL statements in session.
　　0  internal SQL statements in session.
　　3  SQL statements in session.
　　1  statement EXPLAINed in this session.
　　********************************************************************************
　　Trace file: dg53_ora_18857_hr_trace02.trc
　　Trace file compatibility: 10.01.00
　　Sort options: default
　　0  session in tracefile.
　　3  user  SQL statements in trace file.
　　0  internal SQL statements in trace file.
　　3  SQL statements in trace file.
　　3  unique SQL statements in trace file.
　　1  SQL statements EXPLAINed using schema:
　　HR.prof$plan_table
　　Default table was used.
　　Table was created.
　　Table was dropped.
　　46  lines in trace file.
　　15  elapsed seconds in trace file.
　　[oracle@dg53 udump]$ head -30 dg53_ora_18857_hr_trace02.trc
　　/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc
　　*** TRACE DUMP CONTINUED FROM FILE
　　/u01/app/oracle/admin/orcl10g/udump/dg53_ora_18857_hr_trace02.trc ***
　　*** 2012-06-08 14:28:26.627
　　=====================
　　PARSING IN CURSOR #2 len=68 dep=0 uid=55 oct=42 lid=55 tim=1307750885378875
　　hv=2804619552 ad='2349fc80'
　　alter session set events '10046 trace name context forever,level 12'
　　END OF STMT
　　EXEC #2:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750885378870

　　WAIT #2: nam='SQL*Net message to client' ela= 2 driver>　　obj#=-1 tim=1307750885378967

　　WAIT #2: nam='SQL*Net message from client' ela= 126 driver>　　obj#=-1 tim=1307750885379118

　　WAIT #0: nam='SQL*Net message to client' ela= 1 driver>　　obj#=-1 tim=1307750885379173

　　WAIT #0: nam='SQL*Net message from client' ela= 5384831 driver>　　p3=0 obj#=-1 tim=1307750890764022
　　=====================
　　PARSING IN CURSOR #3 len=50 dep=0 uid=55 oct=3 lid=55 tim=1307750890764197  hv=2273608758 ad='2349fa44'
　　select salary from employees where employee_id=:id
　　END OF STMT
　　PARSE #3:c=0,e=96,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764193
　　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=b7fb9ad0  bln=22  avl=02  flg=05
　　value=200
　　EXEC #3:c=0,e=334,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1307750890764600

　　WAIT #3: nam='SQL*Net message to client' ela= 2 driver>　　WAIT #3: nam='db file sequential read' ela= 13073 file#=5 block#=84 blocks=1 obj#=51857 tim=1307750890780678
　　FETCH #3:c=5999,e=16119,p=1,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=1307750890780769