Wednesday, January 16, 2013

Oracle 11g - Tracing and TKPROF experiments

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:




No comments:

Post a Comment