Tracing for fun and (tk)profit

If you ever wanted proof that time is relative, just consider The Good Old Days.
Depending on your age, nationality, personal preferences etc, that time could be when rationing finally ended; or when Trevor Brooking won the Cup for West Ham with a “bullet” header; or possibly when Joe Carter hit a three-run homer to seal back-to-back World Series for the Blue Jays.
Alternatively, it could be when you were able to get on to the database server and use tkprof to analyse those tricky database performance issues.

In these days of siloed IT Departments, Oracle trace files, nevermind the tkprof utility are out of the reach of many developers.
The database server itself is the preserve of Unix Admins and DBAs, groups which, with good reason, are a bit reluctant to allow anyone else access to the Server at the OS level.

Which is a pity. Sometimes there is just no substitute for getting into the nitty gritty of exactly what is happening inside a given session.

For those of you who miss The Good Old Days of tkprof, what follows is an exploration of how to access both trace files and even the tkprof utility itself without leaving the comfort of your database.
I’ll go through a quick recap of :

  • how to generate a trace file for a session
  • using tkprof to make sense of it all

Then, coming bang up to date :

  • viewing a trace file using an external table – and why you might want to
  • Using a preprocessor to generate tkprof output
  • implementing a multi-user solution for tkprof

Before I go any further, I think it’s only right to acknowledge this excellent article by Adrian Billington on the same theme.

Generating a trace file just like Mother used to make

First of all, we need to know where oracle will put any trace files that we generate.
This is simple enough, we can just look at the USER_DUMP_DEST parameter :

select value
from v$parameter
where name = 'user_dump_dest'
/

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xe/XE/trace

This directory may well already be choc full of trace files generated by background processes so it might be an idea to make sure that we can easily identify the trace file that we’re interested in.

We can specify a string to use in the file name by doing the following in the session we want to trace:

alter session set_tracefile_identifier='are_policeman_getting_younger';

Now, we’re ready to initiate the trace in the session :

alter session set timed_statistics=true
/
alter session set events '10046 trace name context forever, level 12'
/

Now let’s run a couple of queries to trace…

select * from hr.departments
/
...
select emp.first_name||' '||emp.last_name
from employees emp, departments dept
where emp.department_id = dept.department_id
and dept.department_name = 'IT Helpdesk'
/
...

Once we’re done, we can exit the session and then see if we can find the trace file :

ls -l /u01/app/oracle/diag/rdbms/xe/XE/trace/*are_policemen_getting_younger.trc
XE_ora_2995_are_policemen_getting_younger.trc

I think that’s our trace file.

If we now look at this, we’ll see something like :

Trace file /u01/app/oracle/diag/rdbms/xe/XE/trace/XE_ora_2995_are_policemen_getting_younger.trc
Oracle Database 11g Express Edition Release 11.2.0.2.0 - 64bit Production
ORACLE_HOME = /u01/app/oracle/product/11.2.0/xe
System name:    Linux
Node name:      netbook-eM350
Release:        3.5.0-17-generic
Version:        #28-Ubuntu SMP Tue Oct 9 19:31:23 UTC 2012
Machine:        x86_64
Instance name: XE
Redo thread mounted by this instance: 1
Oracle process number: 22
Unix process pid: 2995, image: oracle@netbook-eM350 (TNS V1-V3)


*** 2014-04-22 13:04:58.945
*** SESSION ID:(12.3) 2014-04-22 13:04:58.945
*** CLIENT ID:() 2014-04-22 13:04:58.945
*** SERVICE NAME:(SYS$USERS) 2014-04-22 13:04:58.945
*** MODULE NAME:(SQL*Plus) 2014-04-22 13:04:58.945
*** ACTION NAME:() 2014-04-22 13:04:58.945

WAIT #140472211929432: nam='SQL*Net message to client' ela= 13 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1398168298928274

*** 2014-04-22 13:05:06.782
WAIT #140472211929432: nam='SQL*Net message from client' ela= 7836353 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1398168306782358
CLOSE #140472211929432:c=0,e=73,dep=0,type=1,tim=1398168306782754
=====================
...

In it’s raw form, the tracefile isn’t the easiest thing in the world to read. Fortunately, we can make things a little clearer by using tkprof :

tkprof XE_ora_2995_are_policemen_getting_younger.trc young_police.txt explain=uid/pwd@db sys=no

Run this replacing the uid/pwd@db with a valid database connect string for a user with an Explain table setup and you’ll get something a bit more readable generated in the young_police.txt file :


TKPROF: Release 11.2.0.2.0 - Development on Tue Apr 22 13:18:03 2014

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: XE_ora_2995_are_policemen_getting_younger.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
********************************************************************************

SQL ID: 1ac6kt76qnwsm Plan Hash: 4167016233

select * 
from
 hr.departments


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.10          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.01          6          8          0          27
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.04       0.11          6          8          0          27

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48  (MIKE)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        27         27         27  TABLE ACCESS FULL DEPARTMENTS (cr=8 pr=6 pw=0 time=11263 us cost=3 size=567 card=27)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
     27   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'DEPARTMENTS' (TABLE)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                         1        0.00          0.00
  db file scattered read                          1        0.00          0.00
  SQL*Net message from client                     3       81.55         81.57
********************************************************************************

select emp.first_name||' '||emp.last_name
from employees emp, departments dept
where emp.department_id = dept.department_id
and dept.department_name = 'IT Helpdesk'

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.02          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.03          6         12          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.06          6         12          0           0

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48  (MIKE)
Number of plan statistics captured: 2

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  HASH JOIN  (cr=6 pr=3 pw=0 time=17220 us cost=7 size=62 card=2)
         0          0          0   TABLE ACCESS FULL DEPARTMENTS (cr=6 pr=3 pw=0 time=17018 us cost=3 size=13 card=1)
         0          0          0   TABLE ACCESS FULL EMPLOYEES (cr=0 pr=0 pw=0 time=0 us cost=3 size=36 card=2)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      0   HASH JOIN
      0    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'DEPARTMENTS' (TABLE)
      0    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'EMPLOYEES' (TABLE)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  db file sequential read                         1        0.02          0.02
  db file scattered read                          1        0.00          0.00
  SQL*Net message from client                     3      109.59        120.58
  SQL*Net break/reset to client                   1        0.01          0.01
********************************************************************************

...
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.05       0.13          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        5      0.00       0.04         12         20          0          27
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.05       0.18         12         20          0          27

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       8        0.00          0.00
  SQL*Net message from client                     8      109.59        228.41
  db file sequential read                         2        0.02          0.03
  Disk file operations I/O                        1        0.00          0.00
  db file scattered read                          2        0.00          0.00
  SQL*Net break/reset to client                   3        0.01          0.01
  log file sync                                   1        0.01          0.01

...
    4  user  SQL statements in session.
   28  internal SQL statements in session.
   32  SQL statements in session.
    2  statements EXPLAINed in this session.
********************************************************************************
Trace file: XE_ora_2995_are_policemen_getting_younger.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
      28  internal SQL statements in trace file.
      32  SQL statements in trace file.
      19  unique SQL statements in trace file.
       2  SQL statements EXPLAINed using schema:
           MIKE.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
    2111  lines in trace file.
     221  elapsed seconds in trace file.

As they say in those smartphone ads, some sequences have been shortened.

New fangled tracing syntax

If you think the syntax to start tracing in a session is somewhat verbose, you’ll be pleased to know that there is a modern alternative.
Additionally, you don’t have to give your trace file a distinctive name to be able to work out which one it is that you’ve generated. You can instead simply issue the following query :

select value
from v$diag_info
where name = 'Default Trace File';

We can now start tracing the current session by simply doing the following :

exec  DBMS_MONITOR.SESSION_TRACE_ENABLE(null, null, true, true);

… and once we’re done, stop tracing even more easily…

exec dbms_monitor.session_trace_disable;

DBMS_MONITOR.SESSION_TRACE_ENABLE takes 4 parameters. The first two are the sid and serial# of the session you want to trace. If you specify null for these two parameters, it will simply start tracing in the current session.
The final two boolean arguments are to include binds and waits.
Specifying TRUE for both of these is the equivalent to a 10046 level 12 trace.

Viewing a Tracefile

In the here and now, there are a number of extremely useful IDEs for Oracle that do all sorts of wierd and wonderful things. SQLDeveloper, for example, will enable you to open a raw trace file and present the information in a more easily digestible fashion.

If you wanted to make use of this functionality ( or the equivalent in TOAD/PL/SQL Developer or whatever your favourite is), you may well find yourself faced with one of the ongoing issues in organisations of all sizes – i.e. which users should have access to the database server at the OS level.
In many organisations, the answer to this is Sysadmins and DBAs. Developers don’t get a look in.
Whilst the reasons behind these restrictions are, by-and-large completely valid, it does mean that the developers ( i.e. the people usually required to do the tuning) are denied a key part of Oracle functionality that enables diagnostics and tuning.

One solution to this problem is, of course, an External Table…

Trace file in an External Table

First of all, we need to create a directory object in the database on the trace file directory in the OS :

create or replace directory trace_dir for
    '/u01/app/oracle/diag/rdbms/xe/XE/trace'
/

The next step is to create a simple external table…with a twist…

create table trace_file_xt
( 
    line  number,
    text varchar2(4000)
)
    organization external
    (
        type oracle_loader
        default directory trace_dir
        access parameters
        (
            records delimited by newline
            nologfile
            fields terminated by whitespace
            (
                line recnum,
                text position(1:4000)
            )
        )
        location ('')
   )
   reject limit unlimited
/

Yep, we’ve not specified a location for the external table.
So, whilst the table is created without error, it’s not currently pointing to a trace file.

Let’s trace another session and this time, we can have a look at the trace file generated without leaving the comfort of the SQL prompt…

select value
from v$diag_info
where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xe/XE/trace/XE_ora_2007.trc

…now start tracing…

begin
    dbms_monitor.session_trace_enable(null, null);
end;
/

PL/SQL procedure successfully completed.

SQL> 

Now run a couple of statements…

select * from hr.departments;
select * from hr.employees;

…and now stop tracing the session :

begin
    dbms_monitor.session_trace_disable;
end;
/

PL/SQL procedure successfully completed.

SQL> 

Finally, in order to see our trace file in all it’s glory, simply point the external table at it…

alter table trace_file_xt location('XE_ora_2007.trc')
/

Table altered.

SQL> 

…and select from it…

select text
from trace_file_xt
order by line
/

TEXT
----------------------------------------------------------------------------------------------------------------------------------
Trace file /u01/app/oracle/diag/rdbms/xe/XE/trace/XE_ora_2007.trc
Oracle Database 11g Express Edition Release 11.2.0.2.0 - 64bit Production
ORACLE_HOME = /u01/app/oracle/product/11.2.0/xe
System name:	Linux
Node name:	netbook-eM350
Release:	3.5.0-17-generic
Version:	#28-Ubuntu SMP Tue Oct 9 19:31:23 UTC 2012
Machine:	x86_64
Instance name: XE
Redo thread mounted by this instance: 1
Oracle process number: 25
Unix process pid: 2007, image: oracle@netbook-eM350 (TNS V1-V3)


*** 2014-04-22 18:39:17.619
*** SESSION ID:(97.15) 2014-04-22 18:39:17.619
*** CLIENT ID:() 2014-04-22 18:39:17.619
*** SERVICE NAME:(SYS$USERS) 2014-04-22 18:39:17.619
*** MODULE NAME:(SQL*Plus) 2014-04-22 18:39:17.619
*** ACTION NAME:() 2014-04-22 18:39:17.619
...

Getting tkprof output

If you’re happy with your IDE’s interpretation of the trace file, or even just prefer looking directly at the trace file itself, this should be enough to be getting on with. For those of us who like tkprof to take some of the strain out of trace file interpretation, a bit more is required.

Yep, we’re going to need one of those external table preprocessor thingys.
I know what you’re thinking, when you’ve got a hammer, everything looks like a nail.

First, we’ll need a Pre-process directory :

cd /u01/app/oracle
mkdir pre_proc_dir

Next, we need to create the shell script in our new directory :

#!/bin/sh
#
# Script to check if a prf file already exists for this trace file.
# If not then run tkprof.
# Final step is to send the contents of the file to stdout
# which in this case means the external table
#
inFile=`/usr/bin/basename $1 .trc`

if [ ! -f $inFile.prf ]
then
   /u01/app/oracle/product/11.2.0/xe/bin/tkprof $1 $inFile.prf
fi
/bin/cat $inFile.prf

A quick note on the permissions for this file. If it’s not owned by oracle – which may well be regarded as a sensible precaution, you do still need to make sure that oracle can execute it.
The best way to ensure this would seem to be to make sure that the group is set to dba, which has execute permissions on the file :

chgrp dba run_tkprof.sh
chmod 755 run_tkprof.sh
ls -l run_tkprof.sh
-rwxr-xr-x 1 mike dba 366 May  4 14:33 run_tkprof.sh

And finally, the table …

create table tkprof_xt
( 
    line  number,
    text varchar2(4000)
)
    organization external
    (
        type oracle_loader
        default directory trace_dir
        access parameters
        (
            records delimited by newline
            nologfile
            preprocessor pre_proc_dir: 'run_tkprof.sh'
            fields terminated by whitespace
            (
                line recnum,
                text position(1:4000)
            )
        )
        location ('')
   )
   reject limit unlimited
/

Once again, we haven’t specified the table’s location as this will be the trace file that we want to look at.
However, for this External table, the output is a bit different :

alter table tkprof_xt location('XE_ora_2007.trc')
/

select text
from tkprof_xt
order by line;

Run this and we get :

TKPROF: Release 11.2.0.2.0 - Development on Thu Apr 24 20:03:27 2014

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: /u01/app/oracle/diag/rdbms/xe/XE/trace/XE_ora_2007.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
********************************************************************************

...

SQL ID: 7jk33n4f4mpy9 Plan Hash: 1445457117

select *
from
 hr.employees


call	 count	     cpu    elapsed	  disk	    query    current	    rows
------- ------	-------- ---------- ---------- ---------- ----------  ----------
Parse	     1	    0.04       0.05	     0		0	   0	       0
Execute      1	    0.00       0.00	     0		0	   0	       0
Fetch	     9	    0.00       0.01	     6	       14	   0	     107
------- ------	-------- ---------- ---------- ---------- ----------  ----------
total	    11	    0.05       0.06	     6	       14	   0	     107

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 48
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ----------------------------------------------
-----

       107	  107	     107  TABLE ACCESS FULL EMPLOYEES (cr=14 pr=6 pw=0 t
ime=12195 us cost=3 size=7383 card=107)



Elapsed times include waiting on following events:
  Event waited on			      Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client			  9	   0.00 	 0.00
  db file sequential read			  1	   0.01 	 0.01
  db file scattered read			  1	   0.00 	 0.00
  SQL*Net message from client			  9	  59.74 	59.85
********************************************************************************
...

We’re now looking at the output of tkprof, rather than at the raw trace file.

As for the .prf file we’ve generated, that has somehow ended up at /u01/app/oracle/product/11.2.0/xe/dbs/XE_ora_2007.prf.
Hmmm, not quite sure why that is.
Checking by re-running the script confirms that the file is simply read if it already exists.

Rather than worrying about how to ensure that the output files are all stored somewhere sensible, we could simply remove them once we’re finished.
Remember, the table only consumes the output of the shell script ( in this case, the cat command). Therefore, we can safely remove the file once we’ve used cat to echo it’s contents to stdout. More of that shortly.

Accessing this application when there’s more than one user

Whilst this functionality is never going to be accessed by a huge number of concurrent users, you are likely to have more than one developer in your team who may want to utilise tkprof in this way.
The problem here is that we can only process one trace file at one time.
Well, we could create a separate table for each developer. Alternatively, we could wrap access to the table in a package and then write out the result to a conventional table for the developers to look at in their own time.

Let’s start with the table we want to hold the tkprof output :

create table traced_sessions
(
    tracefile_name varchar2(512), 
    line_no number,
    text varchar2(4000),
    created_by varchar2(30),
    creation_date date,
    constraint tc_pk primary key (tracefile_name, line_no)
)
/

For the package, we just need two public procedures…

create or replace package tkprof_pkg as
    
    procedure start_trace_pr(i_identifier varchar2 default null);
    procedure stop_trace_pr;
end tkprof_pkg;
/

…which look like this…

create or replace package body tkprof_pkg as

procedure start_trace_pr( i_identifier varchar2 default null) 
is
--------------------------------------------------------------------------------
-- Start tracing in the current session 
--------------------------------------------------------------------------------
    l_location user_external_locations.location%type;
    l_tf_stmnt varchar2(4000);
    
    pragma autonomous_transaction;
begin
    --
    -- If we've been passed a tracefile identifier then check it's not an injection
    -- attempt. 
    -- Once we're happy then set it as the tracefile identifier.
    --
    if i_identifier is not null then
        if regexp_instr( replace( i_identifier, '_'), '[[:punct:]]|[[:space:]]') > 0
        then
            raise_application_error( -20000,
                'Identifier can contain only letters, numbers and underscores');
        end if;
        execute immediate 'alter session set tracefile_identifier = '||i_identifier;
    end if;
    --
    -- Make sure that the xt is not currently pointing to anything
    --
    select location
    into l_location
    from user_external_locations
    where table_name = 'TKPROF_XT';
    if l_location is not null then
        raise_application_error(-20001, 'External Table is currently in use.');
    end if;
    --
    -- start tracing in the current session
    -- we want wait and bind information (equivalent to level 12)
    --
    dbms_monitor.session_trace_enable
    (
        session_id => null,
        serial_num => null, 
        waits => true, 
        binds => true, 
        plan_stat => 'FIRST_EXECUTION'
    );
end start_trace_pr;

procedure stop_trace_pr
is
--------------------------------------------------------------------------------
-- Stop tracing in the current session
-- Then generate the tkprof output by setting the location of the
-- external table and selecting the results into a permanent table
-- NOTE - reference to v$parameter requires SELECT ANY DICTIONARY for the
-- package owner.
--
--------------------------------------------------------------------------------
    l_tracefile varchar2(512);
    l_stmnt VARCHAR2(4000);

    pragma autonomous_transaction;
begin
    dbms_monitor.session_trace_disable;
    --
    -- Get the tracefile basename (i.e. strip the path)
    --
    with dir as
    (
        select value||'/' as dirpath
        from v$parameter
        where name = 'user_dump_dest'
    )
    select replace( di.value, dirpath)
    into l_tracefile
    from v$diag_info di, dir
    where di.name = 'Default Trace File';
    
    l_stmnt := 'alter table tkprof_xt location ('
        ||chr(39)||l_tracefile||chr(39)||')';
    --
    -- Point the External Table at the tracefile
    --
    execute immediate l_stmnt;


    insert into traced_sessions
    (
        tracefile_name, line_no, text, created_by, creation_date
    )
        select l_tracefile, line, text, user, sysdate
        from tkprof_xt;
    --
    -- Now reset the xt location to null ready for the next run.
    -- As this is a DDL statement it'll also issue an implicit commit
    -- for the insert we've just done.
    --
    execute immediate q'[alter table tkprof_xt location('')]';
end stop_trace_pr;
end tkprof_pkg;
/

Of course, as we’re now persisting the output in the database, we don’t need to store the .prf file…

#!/bin/sh
#
# Run tkprof and then delete the .prf file generated.
#
inFile=`/usr/bin/basename $1 .trc`
/u01/app/oracle/product/11.2.0/xe/bin/tkprof $1 $inFile.prf
/bin/cat $inFile.prf
/bin/rm $inFile.prf

OK, it’s a bit rough and ready. We’re relying on the External Table’s location being re-set after every run. Provided the table is accessed only via the package, this should be the case.
As we’re accessing an External Table, where there is no concept of DML locking, we’re relying on the current location definition for the table to determine whether or not it’s in use.

Also, it’s all a bit serial. If the table is in use, then you just have to wait. Having said that, this isn’t going to be a massively multi-user application. It’s only developers/dbas that will be using it.
Additionally, the external table is only “in-use” for a very short time – i.e. the time it takes for the tkprof output to be generated and inserted into our TRACED_SESSIONS table.

Anyway, I suppose we’d better test it…

exec tkprof_pkg.start_trace_pr('dept_locations')

select dept.department_name
from hr.departments dept, hr.locations loc, hr.countries coun
where dept.location_id = loc.location_id
and loc.country_id = coun.country_id
and coun.country_name = 'United Kingdom';

DEPARTMENT_NAME
------------------------------
Human Resources
Sales


select dept.department_name
from hr.departments dept
inner join hr.locations loc on loc.location_id = dept.location_id
inner join hr.countries coun on coun.country_id = loc.country_id
where coun.country_name = 'United Kingdom';

DEPARTMENT_NAME
------------------------------
Human Resources
Sales

exec tkprof_pkg.stop_trace_pr;

select value
from v$diag_info
where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/xe/XE/trace/XE_ora_5010_DEPT_LOCATIONS.trc

Once we’re done, we should now be able to view the tkprof output with the following query (using good old SQL*Plus):

set linesize 130
set pages 5000
set heading off
select text
from traced_sessions
where tracefile_name = 'XE_ora_5010_DEPT_LOCATIONS.trc'
order by line_no
/

If we want to home in on the first of the two queries that we’ve run…

select line_no 
from traced_sessions
where tracefile_name = 'XE_ora_5010_DEPT_LOCATIONS.trc'
and text like '%select dept.department_name%' -- first line of the each query
/

LINE_NO
-------

548
586

Looks like the following query might be what we’re after …

select text
from traced_sessions
where tracefile_name = 'XE_ora_5010_DEPT_LOCATIONS.trc'
and line_no between 548 and 585
order by line_no
/

Sure enough, the output looks something like :

select dept.department_name
from hr.departments dept, hr.locations loc, hr.countries coun
where dept.location_id = loc.location_id
and loc.country_id = coun.country_id
and coun.country_name = 'United Kingdom'

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	     1	    0.00       0.00	     0		6	   0	       2
------- ------	-------- ---------- ---------- ---------- ----------  ----------
total	     3	    0.00       0.00	     0		6	   0	       2

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 49
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
	 2	    2	       2  NESTED LOOPS	(cr=6 pr=0 pw=0 time=101 us)
	 2	    2	       2   NESTED LOOPS  (cr=5 pr=0 pw=0 time=89 us cost=3 size=66 card=2)
	 3	    3	       3    NESTED LOOPS  (cr=3 pr=0 pw=0 time=74 us cost=2 size=36 card=2)
	 1	    1	       1     INDEX FULL SCAN COUNTRY_C_ID_PK (cr=1 pr=0 pw=0 time=39 us cost=1 size=12 card=1)(object id 1
6394)

	 3	    3	       3     TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=0 pw=0 time=28 us cost=1 size=12 card=2)
	 3	    3	       3      INDEX RANGE SCAN LOC_COUNTRY_IX (cr=1 pr=0 pw=0 time=10 us cost=0 size=0 card=2)(object id 1
6420)

	 2	    2	       2    INDEX RANGE SCAN DEPT_LOCATION_IX (cr=2 pr=0 pw=0 time=18 us cost=0 size=0 card=4)(object id 1
6414)

	 2	    2	       2   TABLE ACCESS BY INDEX ROWID DEPARTMENTS (cr=1 pr=0 pw=0 time=5 us cost=1 size=15 card=1)


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.20 	 0.20
********************************************************************************

It’s nice to know that you can use these new-fangled external tables to relive the Good Old Days of performance tuning.
Now, if only they’d add a feature to allow me to relive the Good Old Days when I could have a lie-in on a Saturday, rather than having to get up and mow the lawn.

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s