原文地址：http://www.oracle-base.com/articles/10g/SQLTrace10046TrcsessAndTkprof10g.php

SQL trace, 10046, trcsess and tkprof in Oracle 10g

The quickest way to capture the SQL is being processed by a session is to switch on SQL trace or set the 10046 event for a representative period of time. The resulting trace files can be read in their raw state or translated using the tkprof utility. Explaining the contents of the trace file is beyond the scope of this article, but the following sections explain how trace files can be created and processed.

  • Generating SQL Trace Files
  • Identifying Trace Files
  • trcsess
  • tkprof
  • Trace Example
  • Trace Analyzer

Generating SQL Trace Files

There are numerous ways to enable, disable and vary the contents of this trace. The following methods have been available for several versions of the database.

-- All versions.
SQL> ALTER SESSION SET sql_trace=TRUE;
SQL> ALTER SESSION SET sql_trace=FALSE;SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => TRUE);
SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => FALSE);SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
SQL> ALTER SESSION SET EVENTS '10046 trace name context off';SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>TRUE);
SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>FALSE);SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>8, nm=>' ');
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>0, nm=>' ');-- Available from SQL*Plus since 8i (commandline utility prior to this.
SQL> CONN sys/password AS SYSDBA;  -- User must have SYSDBA.
SQL> ORADEBUG SETMYPID;            -- Debug current session.
SQL> ORADEBUG SETOSPID 1234;       -- Debug session with the specified OS process.
SQL> ORADEBUG SETORAPID 123456;    -- Debug session with the specified Oracle process ID.SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
SQL> ORADEBUG TRACEFILE_NAME;      -- Display the current trace file.
SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;-- All versions, requires DBMS_SUPPORT package to be loaded.
SQL> EXEC DBMS_SUPPORT.start_trace(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace;SQL> EXEC DBMS_SUPPORT.start_trace_in_session(sid=>123, serial=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace_in_session(sid=>123, serial=>1234);

The DBMS_SUPPORT package is not present by default, but can be loaded as the SYS user by executing the "@$ORACLE_HOME/rdbms/admin/dbmssupp.sql" script.

For methods that require tracing levels the following are valid values.

  • 0 - No trace. Like switching sql_trace off.
  • 2 - The equivalent of regular sql_trace.
  • 4 - The same as 2, but with the addition of bind variable values.
  • 8 - The same as 2, but with the addition of wait events.
  • 12 - The same as 2, but with both bind variable values and wait events.

The same combinations are possible for those methods with boolean parameters for waits and binds.

With the advent of Oracle 10g the SQL tracing options have been centralized and extended using the DBMS_MONITOR package. The examples below show just a few possible variations for enabling and disabling SQL trace in Oracle 10g.

-- Oracle 10g
SQL> EXEC DBMS_MONITOR.session_trace_enable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable;SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id =>1234, serial_num=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable(session_id=>1234, serial_num=>1234);SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall', waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.client_id_trace_disable(client_id=>'tim_hall');SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running', -
> waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');

The package provides the conventional session level tracing along with two new variations. First, tracing can be enabled on multiple sessions based on the value of the client_identifier column of the V$SESSION view, set using the DBMS_SESSION package. Second, trace can be activated for multiple sessions based on various combinations of the service_name, module, action columns in the V$SESSION view, set using the DBMS_APPLICATION_INFO package, along with the instance_name in RAC environments. With all the possible permutations and default values this provides a high degree of flexibility.

Identifying Trace Files

Oracle allows you to set the TRACEFILE_IDENTIFIER parameter at session level, allowing you to include some recognizable text into the trace file name.

ALTER SESSION SET TRACEFILE_IDENTIFIER = "MY_TEST_SESSION";

Even without this, we can easily identify the trace file for the current session using the USER_DUMP_DEST value with the instance name and the session's process id. The identify_trace_file.sql script combines these values to produce the expected trace file name.

SET LINESIZE 100
COLUMN trace_file FORMAT A60SELECT s.sid,s.serial#,pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||    '_ora_' || p.spid || '.trc' AS trace_file
FROM   v$session s,v$process p,v$parameter pa
WHERE  pa.name = 'user_dump_dest'
AND    s.paddr = p.addr
AND    s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

If you are using a windows environment you will need to alter the "/" to a "\" in the concatenated string. The expected output from this script is displayed below.

Note. Identification of trace files is simpler in Oracle 11g due to the introduction of diagnostic views. The Oracle 11g version of the identify_trace_file.sql is shown below.

SET LINESIZE 100
COLUMN value FORMAT A60SELECT value
FROM   v$diag_info
WHERE  name = 'Default Trace File';

trcsess

Activating trace on multiple sessions means that trace information is spread throughout many trace files. For this reason Oracle 10g introduced the trcsess utility, which allows trace information from multiple trace files to be identified and consolidated into a single trace file. The trcsess usage is listed below.

trcsess [output=<output file name >]  [session=<session ID>] [clientid=<clientid>][service=<service name>] [action=<action name>] [module=<module name>] <trace file names>output=<output file name> output destination default being standard output.
session=<session Id> session to be traced.
Session id is a combination of session Index & session serial number e.g. 8.13.
clientid=<clientid> clientid to be traced.
service=<service name> service to be traced.
action=<action name> action to be traced.
module=<module name> module to be traced.
<trace_file_names> Space separated list of trace files with wild card '*' supported.

With all these options the consolidated trace file can be as broad or as specific as needed.

tkprof

The SQL trace files produced by the methods discussed previously can be read in their raw form, or they can be translated by the tkprof utility into a more human readable form. The output below lists the usage notes from the tkprof utility in Oracle 10g.

$ tkprof
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|noinsert=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 calledprscpu  cpu time parsingprsela  elapsed time parsingprsdsk  number of disk reads during parseprsqry  number of buffers for consistent read during parseprscu   number of buffers for current read during parseprsmis  number of misses in library cache during parseexecnt  number of execute was calledexecpu  cpu time spent executingexeela  elapsed time executingexedsk  number of disk reads during executeexeqry  number of buffers for consistent read during executeexecu   number of buffers for current read during executeexerow  number of rows processed during executeexemis  number of library cache misses during executefchcnt  number of times fetch was calledfchcpu  cpu time spent fetchingfchela  elapsed time fetchingfchdsk  number of disk reads during fetchfchqry  number of buffers for consistent read during fetchfchcu   number of buffers for current read during fetchfchrow  number of rows fetcheduserid  userid of user that parsed the cursor$

The waits parameter was only added in Oracle 9i, so prior to this version wait information had to be read from the raw trace file. The values of bind variables must be read from the raw files as they are not displayed in the tkprof output.

The following section shows an example of gathering SQL trace for a session to give you an idea of the whole process.

Trace Example

The following script creates a test table and a procedure that populates it. This procedure will be the subject of our example trace.

CREATE TABLE sql_trace_test (id  NUMBER,description  VARCHAR2(50)
);EXEC DBMS_STATS.gather_table_stats('test', 'sql_trace_test');CREATE OR REPLACE PROCEDURE populate_sql_trace_test (p_loops  IN  NUMBER) ASl_number  NUMBER;
BEGINFOR i IN 1 .. p_loops LOOPINSERT INTO sql_trace_test (id, description)VALUES (i, 'Description for ' || i);END LOOP;SELECT COUNT(*)INTO   l_numberFROM   sql_trace_test;COMMIT;DBMS_OUTPUT.put_line(l_number || ' rows inserted.');
END;
/
SHOW ERRORS

Gathering the statistics on the empty table may seem odd, but this prevents any dynamic sampling being added to the trace file contents, which would only serve to complicate the file.

Next, we identify the trace file for the current session.

SQL> @identify_trace_file.sqlSID    SERIAL# TRACE_FILE
---------- ---------- ------------------------------------------------------------130      26739 /u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc1 row selected.SQL>

Now we know the name of the trace file we can enable tracing, execute the procedure and disable tracing.

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';Session altered.SQL> SET SERVEROUTPUT ON
SQL> EXEC populate_sql_trace_test(p_loops => 5);
5 rows inserted.PL/SQL procedure successfully completed.SQL> ALTER SESSION SET EVENTS '10046 trace name context off';Session altered.SQL>

The contents of the file are listed below. The output looks a little confusing, but you can identify the individual statements and their associated waits and statistics.

/u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc
Oracle Database 10g Enterprise Edition Release 10.1.0.3.0 - Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining options
ORACLE_HOME = /u01/app/oracle/product/10.1.0/db_1
System name:    OSF1
Node name:  dbserver.oracle-base.com
Release:    V5.1
Version:    2650
Machine:    alpha
Instance name: DEV1
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 367660, image: oracleDEV1@dbserver.oracle-base.com*** 2005-04-05 09:46:51.499
*** ACTION NAME:() 2005-04-05 09:46:51.499
*** MODULE NAME:(SQL*Plus) 2005-04-05 09:46:51.499
*** SERVICE NAME:(SYS$USERS) 2005-04-05 09:46:51.499
*** SESSION ID:(130.26739) 2005-04-05 09:46:51.499
=====================
PARSING IN CURSOR #29 len=68 dep=0 uid=180 oct=42 lid=180 tim=11746409761792 hv=3847243385 ad='2bb57798'
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
END OF STMT
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746409761792
WAIT #29: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #29: nam='SQL*Net message from client' ela= 7358464 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #4 len=36 dep=0 uid=180 oct=47 lid=180 tim=11746417122304 hv=3425213768 ad='2c631cd8'
BEGIN DBMS_OUTPUT.ENABLE(2000); END;
END OF STMT
PARSE #4:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746417122304
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746417122304
WAIT #4: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message from client' ela= 6924288 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #18 len=51 dep=0 uid=180 oct=47 lid=180 tim=11746424051712 hv=2083693016 ad='27ecb338'
BEGIN populate_sql_trace_test(p_loops => 5); END;
END OF STMT
PARSE #18:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=11746424051712
=====================
PARSING IN CURSOR #19 len=86 dep=1 uid=180 oct=2 lid=180 tim=11746424052736 hv=3247833140 ad='28fa57f8'
INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) VALUES (:B1 , 'Description for ' || :B1 )
END OF STMT
PARSE #19:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424052736
=====================
PARSING IN CURSOR #23 len=69 dep=2 uid=0 oct=3 lid=0 tim=11746424053760 hv=1471956217 ad='2e7591f0'
select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1
END OF STMT
PARSE #23:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424053760
EXEC #23:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424059904
FETCH #23:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424059904
=====================
PARSING IN CURSOR #25 len=146 dep=2 uid=0 oct=3 lid=0 tim=11746424065024 hv=2107929772 ad='2e7b4b08'
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),rowid,cols,nvl(defer,0)
,mtime,nvl(spare1,0) from cdef$ where obj#=:1
END OF STMT
PARSE #25:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424065024
=====================
PARSING IN CURSOR #27 len=210 dep=3 uid=0 oct=3 lid=0 tim=11746424102912 hv=864012087 ad='2e351f08'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum,
distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
PARSE #27:c=50000,e=36864,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424102912
EXEC #27:c=16667,e=4096,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424108032
FETCH #27:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424109056
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424110080
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424110080
=====================
PARSING IN CURSOR #28 len=121 dep=3 uid=0 oct=3 lid=0 tim=11746424119296 hv=3150898423 ad='2e347db8'
select /*+ rule */ bucket, endpoint, col#, epvalue from histgrm$ where obj#=:1 and intcol#=:2 and row#=:3
order by bucket
END OF STMT
PARSE #28:c=0,e=9216,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424119296
EXEC #28:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424121344
FETCH #28:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=3,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424122368
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424123392
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424123392
EXEC #25:c=83334,e=61440,p=0,cr=18,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424126464
FETCH #25:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424126464
=====================
PARSING IN CURSOR #12 len=169 dep=2 uid=0 oct=3 lid=0 tim=11746424128512 hv=1173719687 ad='2e7c2c50'
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null
group by privilege#, col#, grantee# order by col#, grantee#
END OF STMT
PARSE #12:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424128512
EXEC #12:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424131584
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
=====================
PARSING IN CURSOR #26 len=151 dep=2 uid=0 oct=3 lid=0 tim=11746424131584 hv=4139184264 ad='2e7cc608'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,
privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
EXEC #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
FETCH #26:c=0,e=1024,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
=====================
PARSING IN CURSOR #7 len=175 dep=2 uid=0 oct=3 lid=0 tim=11746424132608 hv=1729330152 ad='2f3597a8'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled  from obj$ o,user$ u,trigger$ t  where
t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user#  order by o.obj#
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=4 cnt=0 pid=3 pos=1 obj=84 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=5 cnt=0 pid=4 pos=1 obj=128 op='INDEX RANGE SCAN I_TRIGGER1 (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=6 cnt=0 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=7 cnt=0 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=8 cnt=0 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=9 cnt=0 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)'
EXEC #19:c=83334,e=86016,p=0,cr=29,cu=21,mis=1,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
=====================
PARSING IN CURSOR #29 len=35 dep=1 uid=180 oct=3 lid=180 tim=11746424140800 hv=3788777626 ad='2c84eb58'
SELECT COUNT(*) FROM SQL_TRACE_TEST
END OF STMT
PARSE #29:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424140800
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
FETCH #29:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=11746424141824
=====================
PARSING IN CURSOR #4 len=6 dep=1 uid=180 oct=44 lid=180 tim=11746424141824 hv=255718823 ad='2e5363f0'
COMMIT
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
XCTEND rlbk=0, rd_only=0
EXEC #4:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=1,tim=11746424141824
EXEC #18:c=83334,e=91136,p=0,cr=36,cu=26,mis=0,r=1,dep=0,og=1,tim=11746424142848
WAIT #18: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #18: nam='SQL*Net message from client' ela= 1024 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #7 len=52 dep=0 uid=180 oct=47 lid=180 tim=11746424143872 hv=1029988163 ad='2c2ec1b8'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746424143872
WAIT #7: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746424144896
WAIT #7: nam='SQL*Net message from client' ela= 8560640 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #12 len=55 dep=0 uid=180 oct=42 lid=180 tim=11746432706560 hv=2655499671 ad='2a24eab8'
ALTER SESSION SET EVENTS '10046 trace name context off'
END OF STMT
PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432705536
EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432706560

The following command uses the tkprof utility to translate the trace file, placing the translated output in the translated.txt file.The explain and table parameters have been set to allow execution plans to be displayed and the sys parameter prevents recursive SQL being displayed.

$ cd /u01/app/oracle/admin/DEV/udump/
$ tkprof dev1_ora_367660.trc translated.txt explain=test/test table=sys.plan_table sys=no waits=yesTKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:22:43 2005Copyright (c) 1982, 2004, Oracle.  All rights reserved.$

The contents of the translated file are displayed below.

TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:53:50 2005Copyright (c) 1982, 2004, Oracle.  All rights reserved.Trace file: dev1_ora_367660.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 8'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           0Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)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.00SQL*Net message from client                     1        7.35          7.35
********************************************************************************BEGIN DBMS_OUTPUT.ENABLE(2000); END;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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)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.00SQL*Net message from client                     1        6.92          6.92
********************************************************************************BEGIN populate_sql_trace_test(p_loops => 5); END;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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)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.00SQL*Net message from client                     1        0.00          0.00
********************************************************************************INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION)
VALUES(:B1 , 'Description for ' || :B1 )call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          1         25           5
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0          1         25           5Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)Rows     Execution Plan
-------  ---------------------------------------------------0  INSERT STATEMENT   MODE: ALL_ROWS********************************************************************************SELECT COUNT(*)
FROMSQL_TRACE_TESTcall     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.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          7          0           1Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)Rows     Execution Plan
-------  ---------------------------------------------------0  SELECT STATEMENT   MODE: ALL_ROWS0   SORT (AGGREGATE)0    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'SQL_TRACE_TEST' (TABLE)********************************************************************************COMMITcall     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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)
********************************************************************************BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)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.00SQL*Net message from client                     1        8.56          8.56
********************************************************************************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           0Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.00       0.00          0          0          0           3Misses in library cache during parse: 1Elapsed times include waiting on following events:Event waited on                             Times   Max. Wait  Total Waited----------------------------------------   Waited  ----------  ------------SQL*Net message to client                       4        0.00          0.00SQL*Net message from client                     4        8.56         22.84OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.05       0.05          0          0          0           0
Execute     18      0.03       0.03          0          1         26           5
Fetch       12      0.00       0.00          0         35          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       40      0.08       0.08          0         36         26          14Misses in library cache during parse: 7
Misses in library cache during execute: 68  user  SQL statements in session.7  internal SQL statements in session.15  SQL statements in session.2  statements EXPLAINed in this session.
********************************************************************************
Trace file: dev1_ora_367660.trc
Trace file compatibility: 10.01.00
Sort options: default1  session in tracefile.8  user  SQL statements in trace file.7  internal SQL statements in trace file.15  SQL statements in trace file.15  unique SQL statements in trace file.2  SQL statements EXPLAINed using schema:sys.plan_tableSchema was specified.Existing table was used.146  lines in trace file.22  elapsed seconds in trace file.

For each statement executed by the session, the file contains a record of the parse, execute and fetch statistics, an execution plan where necessary and a list of session waits.

Trace Analyzer

In addition to TKPROF, Oracle provide another tool for analyzing SQL trace files called Trace Analyzer. This is available for download from Metalink and can be installed on any version of the database server from Oracle8i upwards.

Trace Analyzer reads a raw SQL Trace file generated by standard SQL Trace or by EVENT 10046 (Level 4, 8 or 12), and generates a comprehensive HTML report with performance related details: time summary, call summary (parse, execute, fetch), identification of top SQL, row source plan, explain plan, CBO statistics, wait events, values of bind variables, I/O summary per schema object, latches, hot blocks, etc.

The HTML report includes all the details found on TKPROF, plus additional information normally requested and used for a transaction performance analysis.

For more information see:

  • Using Application Tracing Tools
  • DBMS_MONITOR
  • How to set trace... by Pete Finnigan
  • Trace Analyzer

Hope this helps. Regards Tim...

转载于:https://www.cnblogs.com/cqubityj/archive/2011/12/05/2276438.html

SQL trace, 10046, trcsess and tkprof in Oracle 10g（转）相关推荐

  1. oracle gather trace,Oracle 11g新SQL Trace 10046方法

    10046是每一个研究Oracle.进行SQL调优的朋友非常熟悉的工具.10046和10053两个诊断事件,可以方便的帮助我们了解Oracle CBO优化 10046是每一个研究Oracle.进行SQ ...

  2. oracle 读懂10046视频,Oracle 11g新SQL Trace 10046方法

    10046是每一个研究Oracle.进行SQL调优的朋友非常熟悉的工具.10046和10053两个诊断事件,可以方便的帮助我们了解Oracle CBO优化 10046是每一个研究Oracle.进行SQ ...

  3. oracle gather trace,读懂SQL TRACE TKProf报告

    TKPROF是一个可执行文件,自带在Oracle Server软件中,无需额外的安装. 该工具文件可以用来解析ORACLE的SQL TRACE(10046) 以便生成更可读的内容.  实际上tkpro ...

  4. sql trace基础

    一. 基础.SQL_TRACE 1． 在全局启用 在参数文件(pfile/spfile)中指定: sql_trace =true 在全局启用SQL_TRACE会导致所有进程的活动被跟踪,包括后台进程及 ...

  5. Oracle SQL Trace、Tkprof和10046事件

    一.SQL TRACE 当SQL语句出现性能问题时,我们可以用SQL_TRACE来跟踪SQL的执行情况,通过跟踪,我们可以了解一条SQL或者PL/SQL包的运行情况,SQL_TRACE命令会将SQL执 ...

  6. Oracle SQL Trace 和 10046 事件 .

    一. SQL_TRACE 当SQL语句出现性能问题时,我们可以用SQL_TRACE来跟踪SQL的执行情况,通过跟踪,我们可以了解一条SQL或者PL/SQL包的运行情况,SQL_TRACE命令会将SQL ...

  7. oracle 10046 看锁,Maclean教你读Oracle 10046 SQL TRACE

    有同学一直向Maclean反应希望做一期10046 SQL trace的教程, 正好这几天有空 我们就理一理. 为什么我们要使用10046 trace? 10046 trace帮助我们解析 一条/多条 ...

  8. oracle trace跟踪,浅析Oracle追踪工具SQL Trace的启用方式

    SQL Trace是Oracle提供的用于举行SQL追寻的手段,是强有力的帮助诊断工具.在平时的数据库问题诊断和处理中,SQL TRACE是极其常用的措施. SQL TRACE的顺次追寻能够分为以下几 ...

  9. oracle 10046详解,ORACLE TRACE 10046事件常见的几种方法

    下面是10046事件的几个等级分别表示什么意思 Level 0 Tracing is disabled. This is the same as setting SQL_TRACE = FALSE. ...

最新文章

  1. 微信小程序在showToast中换行并且隐藏icon
  2. 关于react diff 算法（译文）
  3. python打开excel的函数-Python读取excel文件中带公式的值的实现
  4. linux基本知识2
  5. c语言中调整颜色的函数_C语言中的输入输出函数
  6. C/C++函数调用约定
  7. Android Service学习之IntentService 深入分析
  8. 外星人跑深度学习_上海港汇外星人店，51M2020开光追和DLSS2.0畅玩《赛博朋克2077》...
  9. 分布式系统原理_终于有架构大牛把分布式系统概念讲明白了，竟然用了足足800页...
  10. Bailian1835 POJ1835 宇航员【模拟】
  11. java pdf添加图片_Java 给 PDF 设置背景图片
  12. 我的世界职业系统rpg服务器,我的世界1.8.X-1.10.X服务器七彩之风RPG混合生存群组服小游戏空岛海岛粘液丧尸世界职业...
  13. 载入模型部分权重的方法
  14. 【刷题打卡】day7-BFS
  15. 情态动词+have+done用法整理
  16. PHP出现中文乱码的解决方法
  17. pandas中DataFrame的.ix不能用怎么办
  18. 工业DLP投影仪在结构光3DScan应用中有什么优势？
  19. （附源码）SSM仓库管理系统 毕业设计 061015
  20. 什么是Cython？让Python有C语言的速度

热门文章

  1. 夺冠没含金量！用python和BI可视化分析，湖人赢在这点上
  2. 报表引擎API开发入门—带参程序数据集
  3. Tomcat绑定jre
  4. java 类变量 赋值_Java 中类变量，实例变量，局部变量的赋值
  5. python有多少个模块_python绘图模块有哪些
  6. (第三章)查看数据库
  7. Python模拟登陆，解密js代码实例：知乎登陆
  8. 1. 方程求根（二分法）
  9. 【干货】微信小程序如何设置背景图片
  10. LLVM和clang