The version of Oracle we are working with is as follows.
SQL> select * from v$version where rownum <3;
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
PL/SQL Release 11.1.0.7.0 - Production
SQL>
SQL to determine the location and filename of the trace file (default extension is .trc) created by tracing the current session.
SQL> SET LINESIZE 100
SQL> COLUMN trace_file FORMAT A60
SQL>
SQL> SELECT s.sid,
s.serial#,
2 3 pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||
4 '_ora_' || p.spid || '.trc' AS trace_file
5 FROM v$session s,
6 v$process p,
7 v$parameter pa
8 WHERE pa.name = 'user_dump_dest'
9 AND s.paddr = p.addr
10 AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');
SID SERIAL# TRACE_FILE
---------- ---------- ------------------------------------------------------------
134 26360 /u01/app/diag/rdbms/orcl/orcl/trace/orcl_ora_478.trc
For this walk-through we follow the steps outlined below.
Login to SQLPLUS using HR user.
$ sqlplus hr/hr
SQL*Plus: Release 11.1.0.7.0 - Production on Tue Jan 15 20:39:57 2013
Copyright (c) 1982, 2008, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Initiate the tracing on the session.
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
Session altered.
Execute some SQL. (This can be SQL, PLSQL, package calls)
SQL> select t.*, count(*) over() from emp t;
Stop the tracing on the session.
ALTER SESSION SET EVENTS '10046 trace name context off';
Exit from SQLPLUS. Review “.trc” raw file. (Find and identify the file)
SQL> exit;
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
$ ls
alert_orcl.log orcl_lgwr_27455.trc orcl_lgwr_27455.trm orcl_ora_31860.trc orcl_ora_31860.trm orcl_ora_6677.trc orcl_ora_6677.trm sbtio.log
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
$ ls -ltr
total 5160
-rw-r--r-- 1 oracle oinstall 0 Jun 10 2012 sbtio.log
-rw-r----- 1 oracle oinstall 5235722 Jan 15 07:35 alert_orcl.log
-rw-r----- 1 oracle oinstall 108 Jan 15 18:51 orcl_ora_31860.trm
-rw-r----- 1 oracle oinstall 9528 Jan 15 18:51 orcl_ora_31860.trc
-rw-r----- 1 oracle oinstall 60 Jan 15 20:00 orcl_lgwr_27455.trm
-rw-r----- 1 oracle oinstall 952 Jan 15 20:00 orcl_lgwr_27455.trc
-rw-r----- 1 oracle oinstall 82 Jan 15 20:43 orcl_ora_6677.trm
-rw-r----- 1 oracle oinstall 1548 Jan 15 20:43 orcl_ora_6677.trc
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
Review TKPROF command options (with some basic options).
$ 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|no
insert=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 called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
Run TKPROF on the Trace file.
$ tkprof orcl_ora_6677.trc /tmp/mytest.txt sys=no explain=hr@orcl waits=yes
TKPROF: Release 11.1.0.7.0 - Production on Tue Jan 15 20:49:10 2013
Copyright (c) 1982, 2007, Oracle. All rights reserved.
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
$
Review the TKPROF output.
$ ls -ltr /tmp/
total 12
drwx------ 2 root root 4096 Aug 25 2009 keyring-FCJgQX
srwxr-xr-x 1 root root 0 Aug 25 2009 mapping-root
drwxr----- 2 oracle oinstall 4096 Jan 15 18:13 hsperfdata_oracle
-rw-r--r-- 1 oracle oinstall 1155 Jan 15 20:49 mytest.txt
oracle@domU-12-31-39-00-7C-94:[/u01/app/diag/rdbms/orcl/orcl/trace]
$ vi /tmp/mytest.txt
Head of the TKPROF output…
TKPROF: Release 11.1.0.7.0 - Production on Tue Jan 15 20:49:10 2013
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: orcl_ora_6677.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
0 statements EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_6677.trc
Trace file compatibility: 11.1.0.7
Sort options: default
<<<< SNIP SNIP SNIP >>>>
In our next posting we’ll review the content of TKPROF output and corresponding TRC file content.
Reference:
