Profiling trace files with preprocessor external tables in 11g

Advertisements

External tables were introduced in Oracle 9i but have had several new features added through the major releases of 10g and 11g. In particular, Oracle 11g added a range of support for compression, both in reading and writing data with external tables. The external table preprocessor (released in the 11.1.0.7 patchset) was possibly developed to enable the reading of compressed files but as we will see in this article, it can be used for other types of preprocessing tasks. In particular, we will be using the preprocessor to generate and read TKProf and OraSRP reports from trace files, all within SQL*Plus (or any other IDE of choice, such as SQL Developer, TOAD etc).

For a full description of the external table preprocessor and its capabilities, there are two oracle-developer.net articles available:

    External table enhancements in 11g describes all external table new features in 11g, including an example of the preprocessor being used to read from compressed files;
    Listing files with the external table preprocessor in 11g provides examples of using the preprocessor to get file listings and describes the security implications of the new feature.

Readers who are unfamiliar with the external table preprocessor feature should read the articles listed above. Some of the concepts described in them will not be repeated in the following article.
oracle directory setup

As with any external table, we need to begin by creating an Oracle directory to read our external files. As this article is related to generating profiler reports from extended SQL trace files, we need to create a directory over the user dump destination, as follows.

SQL> conn / as sysdba

Connected.


SQL> CREATE DIRECTORY trace_dir AS '/app/oracle/diag/rdbms/ora112/ORA112/trace';

Directory created.

We also need to grant our user both READ and WRITE privileges on this directory (READ to enable reading both the raw SQL trace files and the profiler reports and WRITE to generate the profiler reports), as follows.

SQL> GRANT READ, WRITE ON DIRECTORY trace_dir TO scott;

Grant succeeded.

In addition to a "standard" read/write directory, we also need an executable directory for our preprocessor scripts (as already stated, the background reading has full descriptions of all preprocessor concepts).

SQL> CREATE DIRECTORY bin_dir AS '/app/oracle/bin_dir';

Directory created.


SQL> GRANT EXECUTE ON DIRECTORY bin_dir TO scott;

Grant succeeded.

The executable directory is created in the same way as any other, but this time we have granted an EXECUTE privilege to our user. The executable directory will contain the preprocessor scripts needed to generate and read the profiler reports. Naturally, this has security implications, as described in the recommended reading and we'll assume for this article that the /app/oracle/bin_dir directory is strictly controlled.
generating and reading tkprof reports

Now that we have our Oracle directories, we can connect as our user and create an external table to generate and read TKProf reports, as follows.

SQL> conn scott/tiger

Connected.


SQL> CREATE TABLE tkprof_xt
  2  ( line  NUMBER
  3  , text  VARCHAR2(4000)
  4  )
  5  ORGANIZATION EXTERNAL
  6  (
  7    TYPE ORACLE_LOADER
  8    DEFAULT DIRECTORY trace_dir
  9    ACCESS PARAMETERS
 10    (
 11       RECORDS DELIMITED BY NEWLINE
 12       NOLOGFILE
 13       PREPROCESSOR bin_dir: 'tkprof.sh'
 14       FIELDS TERMINATED BY WHITESPACE
 15       (
 16          line RECNUM
 17       ,  text POSITION(1:4000)
 18       )
 19    )
 20    LOCATION ('')
 21  )
 22  REJECT LIMIT UNLIMITED;

Table created.

As highlighted, this is a preprocessor external table. Its data source is not a flat-file, but rather the output of the preprocessor script highlighted on line 21. The location clause on line 20 is unnecessary at create-time, but before we can query the external table, we'll need to provide a valid trace file (which we'll see later).

The preprocessor script that supports this external table is very simple, as follows.

[oracle@oel bin_dir]$ cat tkprof.sh
#!/bin/ksh
${ORACLE_HOME}/bin/tkprof $1 $1.prf
/bin/cat $1.prf

Obviously, this is a shell script for a *nix system but is simple to convert to a Windows batch-file equivalent. The preprocessor script simply generates and reads a TKProf report for the trace file provided as parameter $1 (as noted in the background reading, this $1 parameter is the name of the file set as the external table's location).

To test our external table, we'll generate an extended SQL trace file as follows.

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

Session altered.


SQL> SELECT COUNT(*) FROM emp;

  COUNT(*)
----------
        14

1 row selected.


SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

Session altered.

As long as we retain our database session, we can determine the name of the trace file we generated by querying the V$DIAG_INFO view, as follows.

SQL> SELECT REGEXP_SUBSTR(value, '[^/]+$') AS trace_file
  2  FROM   v$diag_info
  3  WHERE  name = 'Default Trace File';

TRACE_FILE
------------------------
ORA112_ora_5107.trc

1 row selected.

Now we have the name of our trace file, we can set the external table's location clause, as follows.

SQL> ALTER TABLE tkprof_xt LOCATION ('ORA112_ora_5107.trc');

Table altered.

We're now ready to generate and read a TKProf report for this trace file, which is as simple as querying the TKPROF_XT table, as below.

SQL> SELECT *
  2  FROM   tkprof_xt;

   LINE TEXT
------- --------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:34:21 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6
      7
      8 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:34:21 2011
      9
     10 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
     11
     12 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
     13 Sort options: default
     14
     15 ********************************************************************************
     16 count    = number of times OCI procedure was executed
     17 cpu      = cpu time in seconds executing
     18 elapsed  = elapsed time in seconds executing
     19 disk     = number of physical reads of buffers from disk
     20 query    = number of buffers gotten for consistent read
     21 current  = number of buffers gotten in current mode (usually for update)
     22 rows     = number of rows processed by the fetch or execute call
     23 ********************************************************************************
     24
     25 SQL ID: 9babjv8yq8ru3 Plan Hash: 0
     26
     27 BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
     28
     29
     30 call     count       cpu    elapsed       disk      query    current        rows
     31 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     32 Parse        2      0.00       0.00          0          0          0           0
     33 Execute      2      0.00       0.02          0          3          0           2
     34 Fetch        0      0.00       0.00          0          0          0           0
     35 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     36 total        4      0.00       0.02          0          3          0           2
     37
     38 Misses in library cache during parse: 0
     39 Optimizer mode: ALL_ROWS
     40 Parsing user id: 84
     41
     42 Elapsed times include waiting on following events:
     43   Event waited on                             Times   Max. Wait  Total Waited
     44   ----------------------------------------   Waited  ----------  ------------
     45   SQL*Net message to client                       2        0.00          0.00
     46   SQL*Net message from client                     2        0.00          0.00
     47 ********************************************************************************
     48
     49 SQL ID: 1srhq04p4x0zz Plan Hash: 2083865914
     50
     51 SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
     52   NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
     53   NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
     54   NVL(SUM(C2),:"SYS_B_1")
     55 FROM
     56  (SELECT /*+ NO_PARALLEL("EMP") FULL("EMP") NO_PARALLEL_INDEX("EMP") */
     57   :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "SCOTT"."EMP" "EMP") SAMPLESUB
     58
     59
     60 call     count       cpu    elapsed       disk      query    current        rows
     61 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     62 Parse        1      0.00       0.00          0          0          0           0
     63 Execute      1      0.00       0.03          0          0          0           0
     64 Fetch        1      0.00       0.00          0          7          0           1
     65 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     66 total        3      0.00       0.03          0          7          0           1
     67
     68 Misses in library cache during parse: 1
     69 Misses in library cache during execute: 1
     70 Optimizer mode: ALL_ROWS
     71 Parsing user id: 84     (recursive depth: 1)
     72 Number of plan statistics captured: 1
     73
     74 Rows (1st) Rows (avg) Rows (max)  Row Source Operation
     75 ---------- ---------- ----------  ---------------------------------------------------
     76          1          1          1  SORT AGGREGATE (cr=7 pr=0 pw=0 time=340 us)
     77         14         14         14   TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=301 us cost=3 size=0 card=409)
     78
     79
     80 Elapsed times include waiting on following events:
     81   Event waited on                             Times   Max. Wait  Total Waited
     82   ----------------------------------------   Waited  ----------  ------------
     83   Disk file operations I/O                        1        0.00          0.00
     84 ********************************************************************************
     85
     86 SQL ID: 7ryz6qnvnq8zc Plan Hash: 1006289799
     87
     88 SELECT COUNT(*)
     89 FROM
     90  emp
     91
     92
     93 call     count       cpu    elapsed       disk      query    current        rows
     94 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     95 Parse        1      0.00       0.00          0          2          0           0
     96 Execute      1      0.00       0.00          0          0          0           0
     97 Fetch        2      0.00       0.00          0          4          0           1
     98 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
     99 total        4      0.00       0.00          0          6          0           1
    100
    101 Misses in library cache during parse: 1
    102 Optimizer mode: ALL_ROWS
    103 Parsing user id: 84
    104 Number of plan statistics captured: 1
    105
    106 Rows (1st) Rows (avg) Rows (max)  Row Source Operation
    107 ---------- ---------- ----------  ---------------------------------------------------
    108          1          1          1  SORT AGGREGATE (cr=4 pr=0 pw=0 time=112 us)
    109         14         14         14   INDEX FAST FULL SCAN PK_EMP (cr=4 pr=0 pw=0 time=98 us cost=2 size=0 card=14)(object id 73182)
    110
    111
    112 Elapsed times include waiting on following events:
    113   Event waited on                             Times   Max. Wait  Total Waited
    114   ----------------------------------------   Waited  ----------  ------------
    115   SQL*Net message to client                       2        0.00          0.00
    116   SQL*Net message from client                     2        0.00          0.00
    117 ********************************************************************************
    118
    119 SQL ID: 0kjg1c2g4gdcr Plan Hash: 0
    120
    121 ALTER SESSION SET EVENTS '10046 trace name context off'
    122
    123
    124 call     count       cpu    elapsed       disk      query    current        rows
    125 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    126 Parse        1      0.00       0.00          0          0          0           0
    127 Execute      1      0.00       0.00          0          0          0           0
    128 Fetch        0      0.00       0.00          0          0          0           0
    129 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    130 total        2      0.00       0.00          0          0          0           0
    131
    132 Misses in library cache during parse: 0
    133 Parsing user id: 84
    134
    135
    136
    137 ********************************************************************************
    138
    139 OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
    140
    141 call     count       cpu    elapsed       disk      query    current        rows
    142 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    143 Parse        4      0.00       0.00          0          2          0           0
    144 Execute      4      0.00       0.02          0          3          0           2
    145 Fetch        2      0.00       0.00          0          4          0           1
    146 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    147 total       10      0.00       0.02          0          9          0           3
    148
    149 Misses in library cache during parse: 1
    150
    151 Elapsed times include waiting on following events:
    152   Event waited on                             Times   Max. Wait  Total Waited
    153   ----------------------------------------   Waited  ----------  ------------
    154   SQL*Net message to client                       5        0.00          0.00
    155   SQL*Net message from client                     5        0.00          0.00
    156
    157
    158 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
    159
    160 call     count       cpu    elapsed       disk      query    current        rows
    161 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    162 Parse        1      0.00       0.00          0          0          0           0
    163 Execute      1      0.00       0.03          0          0          0           0
    164 Fetch        1      0.00       0.00          0          7          0           1
    165 ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    166 total        3      0.00       0.03          0          7          0           1
    167
    168 Misses in library cache during parse: 1
    169 Misses in library cache during execute: 1
    170
    171 Elapsed times include waiting on following events:
    172   Event waited on                             Times   Max. Wait  Total Waited
    173   ----------------------------------------   Waited  ----------  ------------
    174   Disk file operations I/O                        1        0.00          0.00
    175
    176     4  user  SQL statements in session.
    177     0  internal SQL statements in session.
    178     4  SQL statements in session.
    179 ********************************************************************************
    180 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
    181 Trace file compatibility: 11.1.0.7
    182 Sort options: default
    183
    184        1  session in tracefile.
    185        4  user  SQL statements in trace file.
    186        0  internal SQL statements in trace file.
    187        4  SQL statements in trace file.
    188        4  unique SQL statements in trace file.
    189      125  lines in trace file.
    190        0  elapsed seconds in trace file.
    191
    192

192 rows selected.

And that's it! We've generated and read a TKProf report without having to leave our SQL*Plus window. This is quite powerful and can be used in all IDEs. For SQL*Plus users, the pause and pagesize settings can make the analysis of the output easier. In grid-based IDEs such as SQL Developer, the output can easily be scrolled within the data grid.
suppressing the tkprof banner

Note lines 1-10 in the TKPROF_XT resultset above. We can see the TKProf banner twice and the reason for this is simple. The first occurrence of the banner is the stdout of running the tkprof utility (i.e. generating the TKProf report) and the second occurrence is the heading of the resulting report. To suppress the first occurrence of the banner, we can change the tkprof.sh script to redirect the stdout to /dev/null as follows.

[oracle@oel bin_dir]$ cat tkprof_no_banner.sh
#!/bin/ksh
${ORACLE_HOME}/bin/tkprof $1 $1.prf >/dev/null
/bin/cat $1.prf

We will change the TKPROF_XT table to use this script as follows.

SQL> ALTER TABLE tkprof_xt ACCESS PARAMETERS
  2  (
  3     RECORDS DELIMITED BY NEWLINE
  4     NOLOGFILE
  5     PREPROCESSOR bin_dir: 'tkprof_no_banner.sh'
  6     FIELDS TERMINATED BY WHITESPACE
  7     (
  8        line RECNUM
  9     ,  text POSITION(1:4000)
 10     )
 11  );

Table altered.

Because we'e altered the table (rather than drop and re-create it), its location will still be set to our sample trace file. We will query the first 10 rows to demonstrate the removal of the first banner as follows.

SQL> SELECT *
  2  FROM   tkprof_xt
  3  WHERE  ROWNUM <= 10;

   LINE TEXT
------- --------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:35:44 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      7 Sort options: default
      8
      9 ********************************************************************************
     10 count    = number of times OCI procedure was executed

10 rows selected.

As we can see, the TKProf banner now appears once in the output.
avoiding multiple tkprof executions

So far in this article, we've generated the same TKProf report twice (compare the timestamps at the top of each of the resultsets). This is a shortcoming of the method so far because larger trace files will take time and resources to profile. To avoid generating the TKProf report every time we query the TKPROF_XT external table, we have two options:

    we can change the preprocessor script to skip the TKProf step if the profile report already exists; or
    we can create a read-only external table to read the profile reports once they have been created.

We'll look at each of these options below.
option 1: prevent multiple invocations of tkprof

We can prevent the TKProf report being re-generated with a simple change to the preprocessor script, as follows.

[oracle@oel bin_dir]$ cat tkprof_once.sh
#!/bin/ksh
if [[ ! -f $1.prf ]]
then
   ${ORACLE_HOME}/bin/tkprof $1 $1.prf >/dev/null
fi
/bin/cat $1.prf

This version of the shell script will only generate a TKProf report if it doesn't already exist. In other words, we only get one chance to generate the profile report for each trace file (without intervention such as removing the TKProf report from the trace directory). We will modify the TKPROF_XT external table to use this new preprocessor script and query the table using the same trace file as in previous examples.

SQL> ALTER TABLE tkprof_xt ACCESS PARAMETERS
  2  (
  3     RECORDS DELIMITED BY NEWLINE
  4     NOLOGFILE
  5     PREPROCESSOR bin_dir: 'tkprof_once.sh'
  6     FIELDS TERMINATED BY WHITESPACE
  7     (
  8        line RECNUM
  9     ,  text POSITION(1:4000)
 10     )
 11  );

Table altered.


SQL> SELECT *
  2  FROM   tkprof_xt
  3  WHERE  ROWNUM <= 10;

   LINE TEXT
------- ---------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:35:44 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      7 Sort options: default
      8
      9 ********************************************************************************
     10 count    = number of times OCI procedure was executed

10 rows selected.

We can see from the highlighted timestamp that the generation of the TKProf report was skipped this time (i.e. it's the same report that we generated in an earlier example). This time we've simply read an existing report.
option 2: create a read-only external table for trace files

If we want the option to re-generate the TKProf report (should we need to), but also the efficiency of reading the resulting report many more times, then we can use the original implementation of TKPROF_XT but create a second, read-only external table for files in the user dump destination. We start by creating the read-only external table, as follows.

SQL> CREATE TABLE tracefile_xt
  2  ( line  NUMBER
  3  , text  VARCHAR2(4000)
  4  )
  5  ORGANIZATION EXTERNAL
  6  (
  7    TYPE ORACLE_LOADER
  8    DEFAULT DIRECTORY trace_dir
  9    ACCESS PARAMETERS
 10    (
 11       RECORDS DELIMITED BY NEWLINE
 12       NOLOGFILE
 13       FIELDS TERMINATED BY WHITESPACE
 14       (
 15          line RECNUM
 16       ,  text POSITION(1:4000)
 17       )
 18    )
 19    LOCATION ('')
 20  )
 21  REJECT LIMIT UNLIMITED;

Table created.

As stated, this is a vanilla external table to read from files in the TRACE_DIR Oracle directory. We'll alter the location of this table to reference our sample TKProf report and query the table as follows.

SQL> ALTER TABLE tracefile_xt LOCATION ('ORA112_ora_5107.trc.prf');

Table altered.


SQL> SELECT *
  2  FROM   tracefile_xt;

   LINE TEXT
------- ---------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:35:44 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      7 Sort options: default
      8
      9 ********************************************************************************
     10 count    = number of times OCI procedure was executed
     11 cpu      = cpu time in seconds executing
     12 elapsed  = elapsed time in seconds executing
     13 disk     = number of physical reads of buffers from disk
     14 query    = number of buffers gotten for consistent read
     15 current  = number of buffers gotten in current mode (usually for update)
     16 rows     = number of rows processed by the fetch or execute call
     17 ********************************************************************************
     18

<<...snip...>>

    173 ********************************************************************************
    174 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
    175 Trace file compatibility: 11.1.0.7
    176 Sort options: default
    177
    178        1  session in tracefile.
    179        4  user  SQL statements in trace file.
    180        0  internal SQL statements in trace file.
    181        4  SQL statements in trace file.
    182        4  unique SQL statements in trace file.
    183      125  lines in trace file.
    184        0  elapsed seconds in trace file.
    185
    186

186 rows selected.

Again, we've simply read an existing profile report. In addition to saving on TKProf executions, another benefit of this method is that we can also read raw trace files with the read-only external table. In the following example, we'll reset the location of TRACEFILE_XT to the raw trace file and run the same query.

SQL> ALTER TABLE tracefile_xt LOCATION ('ORA112_ora_5107.trc');

Table altered.


SQL> SELECT *
  2  FROM   tracefile_xt;

   LINE TEXT
------- --------------------------------------------------------------------------------
      1 Trace file /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      2 Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
      3 With the Partitioning, OLAP, Data Mining and Real Application Testing options
      4 ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_2
      5 System name: Linux
      6 Node name:   oel.localdomain
      7 Release:     2.6.18-194.17.1.0.1.el5
      8 Version:     #1 SMP Wed Sep 29 15:40:03 EDT 2010
      9 Machine:     i686
     10 Instance name: ORA112
     11 Redo thread mounted by this instance: 1
     12 Oracle process number: 29
     13 Unix process pid: 5107, image: [email protected]
     14
     15
     16 *** 2011-11-08 07:33:17.413
     17 *** SESSION ID:(43.39) 2011-11-08 07:33:17.413
     18 *** CLIENT ID:() 2011-11-08 07:33:17.413
     19 *** SERVICE NAME:(ORA112) 2011-11-08 07:33:17.413
     20 *** MODULE NAME:(SQL*Plus) 2011-11-08 07:33:17.413
     21 *** ACTION NAME:() 2011-11-08 07:33:17.413
     22
     23 WAIT #10101528: nam='SQL*Net message to client' ela= 9 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597413255
     24 WAIT #10101528: nam='SQL*Net message from client' ela= 289 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597413799
     25 =====================

<<...snip...>>

     84 =====================
     85 PARSING IN CURSOR #12087624 len=24 dep=0 uid=84 oct=3 lid=84 tim=1320737597478529 hv=927671276 ad='35e71828' sqlid='7ryz6qnvnq8zc'
     86 SELECT COUNT(*) FROM emp
     87 END OF STMT
     88 PARSE #12087624:c=6999,e=39587,p=0,cr=9,cu=0,mis=1,r=0,dep=0,og=1,plh=1006289799,tim=1320737597478529
     89 EXEC #12087624:c=0,e=91,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1006289799,tim=1320737597478620
     90 WAIT #12087624: nam='SQL*Net message to client' ela= 10 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597478681
     91 FETCH #12087624:c=0,e=113,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1006289799,tim=1320737597478839
     92 STAT #12087624 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=4 pr=0 pw=0 time=112 us)'
     93 STAT #12087624 id=2 cnt=14 pid=1 pos=1 obj=73182 op='INDEX FAST FULL SCAN PK_EMP (cr=4 pr=0 pw=0 time=98 us cost=2 size=0 card=14)'
     94 WAIT #12087624: nam='SQL*Net message from client' ela= 536 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597479517
     95 FETCH #12087624:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1006289799,tim=1320737597479606
     96 WAIT #12087624: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597479639
     97 WAIT #12087624: nam='SQL*Net message from client' ela= 2104 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1320737597481762
     98 PARSE #10096824:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1320737597481942
     99 BINDS #10096824:
    100  Bind#0
    101   oacdty=123 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
    102   oacflg=00 fl2=1000000 frm=00 csi=00 siz=4000 off=0
    103 toid ptr value=352B9774 length=16
    104 7113C953AF16A09FE040E40ADCDE1DC9
    105   kxsbbbfp=00b88c54  bln=4000  avl=00  flg=15

<<...snip...>>

    120 =====================
    121 PARSING IN CURSOR #12087624 len=55 dep=0 uid=84 oct=42 lid=84 tim=1320737597484265 hv=2655499671 ad='0' sqlid='0kjg1c2g4gdcr'
    122 ALTER SESSION SET EVENTS '10046 trace name context off'
    123 END OF STMT
    124 PARSE #12087624:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1320737597484264
    125 EXEC #12087624:c=0,e=365,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1320737597484709

125 rows selected.

We can see the benefit of having a preprocessor external table to initially generate and read a TKProf report together with a generic read-only external table for reading any trace file or profile thereafter. With these, we never have to leave our IDE to work with trace files or profiler reports.
further productivity improvements

If we consider the steps we usually take to profile a trace file, they might include the following:

    exit SQL*Plus or leave the SQL*Plus terminal (or other IDE window);
    start another terminal window and connect to the database server;
    navigate to the trace directory;
    identify the trace file;
    run the tkprof utility to generate the report;
    open the report in an editor.

So far, we've managed to reduce these steps to identifying our default trace file, setting the external table location and querying the preprocessor external table. These are significant productivity improvements. We can take this even further by encapsulating these remaining tasks in either a SQL*Plus script or in a pipelined function.
option 1: using a utility script

Most SQL*Plus users will set a SQLPATH location for utility scripts (including the login.sql script, for example), meaning they are available in SQL*Plus regardless of the current working directory. We can add a small script to our SQLPATH directory to encapsulate the TKProf tasks shown in the previous examples. The following is an example of what a script might look like.

-- tkprof.sql
-- ---------------------------------------------------------

-- Initialise "1" to enable an optional script parameter...
set termout off
col 1 new_value 1
SELECT NULL AS "1"
FROM   dual
WHERE  1=2;

-- Set the tracefile name (if not supplied, fetch it)...
col tracefile new_value _tracefile
SELECT CASE
          WHEN '&1' IS NOT NULL
          THEN '&1'
          ELSE REGEXP_SUBSTR(value, '[^/]+$')
       END AS tracefile
FROM   v$diag_info
WHERE  name = 'Default Trace File';

-- Set the external table location...
ALTER TABLE tkprof_xt LOCATION ('&_tracefile');

-- Query the external table...
set termout on
set lines 150
col text format a130
SELECT *
FROM   tkprof_xt;

undefine "1"
undefine _tracefile

We can see that this script contains each of the steps needed to prepare and query the external table. Note that this script will accept the name of the trace file, but if it is not supplied, it will use the default trace file for our current session (which is what we've been using throughout this article). Using the script is, of course, very simple, as demonstrated below.

SQL> @tkprof


   LINE TEXT
------- --------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:35:44 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      7 Sort options: default
      8
      9 ********************************************************************************
     10 count    = number of times OCI procedure was executed
     11 cpu      = cpu time in seconds executing
     12 elapsed  = elapsed time in seconds executing
     13 disk     = number of physical reads of buffers from disk
     14 query    = number of buffers gotten for consistent read
     15 current  = number of buffers gotten in current mode (usually for update)
     16 rows     = number of rows processed by the fetch or execute call
     17 ********************************************************************************
     18

<<...snip...>>

186 rows selected.

With this script, we've reduced the steps needed to generate and read a TKProf report to a single call.
option 2: using a pipelined function

An alternative to using a free-standing SQL script is to create a pipelined function to perform these tasks. This will be particularly useful for users of IDEs such as SQL Developer and TOAD. As with all pipelined functions, we need an object type to describe our output row and a collection of this type for the function to return. We create these as follows.

SQL> CREATE TYPE tkprof_ot AS OBJECT
  2  ( line NUMBER
  3  , text VARCHAR2(4000)
  4  );
  5  /

Type created.


SQL> CREATE TYPE tkprof_ntt AS TABLE OF tkprof_ot;
  2  /

Type created.

The output of the function will be quite simple: just a line number and the text of the report itself. We create the pipelined function as follows.

SQL> CREATE FUNCTION tkprof (
  2                  p_tracefile IN VARCHAR2 DEFAULT NULL
  3                  ) RETURN tkprof_ntt PIPELINED AS
  4  
  5     -----------------------------------------------------
  6     FUNCTION get_tracefile RETURN VARCHAR2 IS
  7        v_tracefile VARCHAR2(128);
  8     BEGIN
  9        SELECT REGEXP_SUBSTR(value, '[^/]+$')
 10        INTO   get_tracefile.v_tracefile
 11        FROM   v$diag_info
 12        WHERE  name = 'Default Trace File';
 13        RETURN get_tracefile.v_tracefile;
 14     END get_tracefile;
 15  
 16     -----------------------------------------------------
 17     PROCEDURE set_location( p_tracefile IN VARCHAR2 ) IS
 18        PRAGMA AUTONOMOUS_TRANSACTION;
 19     BEGIN
 20        EXECUTE IMMEDIATE
 21           'ALTER TABLE tkprof_xt LOCATION (''' ||
 22               set_location.p_tracefile || ''')';
 23     END set_location;
 24  
 25  BEGIN
 26  
 27     /* Set the external table location... */
 28     set_location(COALESCE(p_tracefile, get_tracefile));
 29  
 30     /* Pipe the data... */
 31     FOR r IN (SELECT * FROM tkprof_xt) LOOP
 32        PIPE ROW (tkprof_ot(r.line, r.text));
 33     END LOOP;
 34  
 35     RETURN;
 36  
 37  EXCEPTION
 38     WHEN NO_DATA_NEEDED THEN
 39        NULL;
 40  END tkprof;
 41  /

Function created.

Some points to note are as follows:

    Line 2: the function has an optional parameter that allows us to pass in the name of the SQL trace file if we know it;
    Lines 6-14: we include a function to lookup the default trace file name in the event that the p_tracefile parameter is not provided;
    Line 17-23: we also include a procedure to set the location of the external table;
    Line 28 and Lines 31-33: we set the location, read from the external table and pipe out the resultset.

We will test our function without a trace file name, as follows.

SQL> SELECT *
  2  FROM   TABLE(tkprof);

   LINE TEXT
------- ---------------------------------------------------------------------------------
      1
      2 TKPROF: Release 11.2.0.2.0 - Development on Tue Nov 8 07:35:44 2011
      3
      4 Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.
      5
      6 Trace file: /app/oracle/diag/rdbms/ora112/ORA112/trace/ORA112_ora_5107.trc
      7 Sort options: default
      8
      9 ********************************************************************************
     10 count    = number of times OCI procedure was executed
     11 cpu      = cpu time in seconds executing
     12 elapsed  = elapsed time in seconds executing
     13 disk     = number of physical reads of buffers from disk
     14 query    = number of buffers gotten for consistent read
     15 current  = number of buffers gotten in current mode (usually for update)
     16 rows     = number of rows processed by the fetch or execute call
     17 ********************************************************************************
     18

<<...snip...>>

186 rows selected.

other profilers (orasrp)

In addition to the supplied TKProf utility, it's possible to use a preprocessor external table to generate and read any other executable profilers that generate text-based reports. We'll see an example of this with the excellent OraSRP profiler. Like TKProf, OraSRP is a command-line utility but has the added benefit of generating a fully-navigable HTML report in addition to a standard text format.

We'll begin by creating a preprocessor external table for generating OraSRP reports, as follows.

SQL> CREATE TABLE orasrp_xt
  2  ( line  NUMBER
  3  , text  VARCHAR2(4000)
  4  )
  5  ORGANIZATION EXTERNAL
  6  (
  7    TYPE ORACLE_LOADER
  8    DEFAULT DIRECTORY trace_dir
  9    ACCESS PARAMETERS
 10    (
 11       RECORDS DELIMITED BY NEWLINE
 12       NOLOGFILE
 13       PREPROCESSOR bin_dir: 'orasrp.sh'
 14       FIELDS TERMINATED BY WHITESPACE
 15       (
 16          line RECNUM
 17       ,  text POSITION(1:4000)
 18       )
 19    )
 20    LOCATION ('')
 21  )
 22  REJECT LIMIT UNLIMITED;

Table created.

This is almost a carbon-copy of TKPROF_XT example from above. The orasrp.sh preprocessor script in this case is as follows.

[oracle@oel bin_dir]$ cat orasrp.sh
#!/bin/ksh
/app/oracle/orasrp/orasrp -t $1 $1.orasrp
/bin/cat $1.orasrp

Note that for these examples, the OraSRP utility is available on the database server itself, so it is able to access trace files in the same way as the server-side TKProf utility (a workaround for readers with client-side access only is described later). In this first example, we're generating a text profile report with a naming format of <tracefile>.orasrp. We'll test it with the sample trace file we've used so far, as follows.

SQL> ALTER TABLE orasrp_xt LOCATION ('ORA112_ora_5107.trc');

Table altered.


SQL> SELECT *
  2  FROM   orasrp_xt;

   LINE TEXT
------- -------------------------------------------------------------------
      1
      2 Session Summary
      3 ==================================================
      4 Instance Name: ORA112
      5 Node Name: oel.localdomain
      6 Oracle Release: 11.2.0.2.0
      7 Session ID: 43.39
      8 Total SQL Statements: 4 (4 user statements, 0 internal statements)
      9 Total Transactions: 0 (0 rollback(s), 0 read-only)
     10
     11
     12 Session Flat Profile
     13 ==================================================
     14                                                                              ----------- Time Per Call ---------
     15 Event Name                                  % Time       Seconds      Calls          Avg         Min         Max
     16 ----------------------------------------  --------  ------------  ---------  ----------- ----------- -----------
     17 unaccounted-for time                         76.5%       0.0544s
     18 EXEC calls [CPU]                              8.4%       0.0060s          5      0.0012s     0.0000s     0.0030s
     19 SQL*Net message from client [idle]            5.6%       0.0040s          3      0.0013s     0.0003s     0.0021s
     20 PARSE calls [CPU]                             5.6%       0.0040s          5      0.0008s     0.0000s     0.0030s
     21 SQL*Net message from client                   3.6%       0.0026s          2      0.0013s     0.0005s     0.0021s
     22 Disk file operations I/O                      0.1%       0.0001s          1      0.0001s     0.0001s     0.0001s
     23 SQL*Net message to client                     0.1%       0.0000s          5      0.0000s     0.0000s     0.0000s
     24 FETCH calls [CPU]                             0.0%       0.0000s          3      0.0000s     0.0000s     0.0000s
     25 ----------------------------------------  --------  ------------  ---------  ----------- ----------- -----------
     26 Total                                       100.0%       0.0711s
     27

<< ...snip... >>

    442 ********************************************************************************
    443
    444 Generated by OraSRP v4.1.2 beta    http://oracledba.ru/orasrp

444 rows selected.

As with the TKPROF_XT examples, we can apply all the same resource-saving measures to the OraSRP equivalent, such as avoiding repeated report-generations for the same trace file. We can also apply productivity-measures such as a script or pipelined function utility fetch the tracefile name, set the location and query the external table in a single call.

As noted above, this example needs the OraSRP utility to be located on the database server. If this isn't possible, then there is a workaround, but this requires that the OraSRP utility is available on the client machine and also that the read-only TRACEFILE_XT external table can access trace files located in the user dump destination. Putting the following steps into a script can be an exercise for the reader.

    1) determine the raw trace file name;
    2) set the location of the TRACEFILE_XT external table;
    3) turn off all SQL*Plus formatting and start a spool file;
    4) query the TRACEFILE_XT table;
    5) turn off the spool;
    6) make a host call to orasrp to profile the spooled trace file to a new report;
    7) make a host call to start the report file (for example, if this is saved as a .txt file on a Windows client, it will open in Notepad).

Note that with the above workaround, there is a risk that large volumes of raw trace file data could be transferred from the database server to the client machine. Wherever possible, this technique should be avoided and all work performed on the server itself (although this isn't always possible in controlled environments).
orasrp html reports

The OraSRP text report is extremely useful in its own right, but it is the HTML version of the report that adds an enormous amount of value over TKProf. We can easily transform our example to benefit from the HTML report format. First, we'll create a shell script to generate the OraSRP report as HTML for our external table.

[oracle@oel bin_dir]$ cat orasrp_html.sh
#!/bin/ksh
/app/oracle/orasrp/orasrp $1 $1.orasrp.html
/bin/cat $1.orasrp.html

We'll also modify the access parameters of the external table to reference this new script, as follows.

SQL> ALTER TABLE orasrp_xt ACCESS PARAMETERS
  2  (
  3     RECORDS DELIMITED BY NEWLINE
  4     NOLOGFILE
  5     PREPROCESSOR bin_dir: 'orasrp_html.sh'
  6     FIELDS TERMINATED BY WHITESPACE
  7     (
  8        line RECNUM
  9     ,  text POSITION(1:4000)
 10     )
 11  );

Table altered.

We can demonstrate the new format by generating an HTML report and fetching a few rows, as follows.

SQL> SELECT *
  2  FROM   orasrp_xt
  3  WHERE  ROWNUM <= 10;

   LINE TEXT
------- ------------------------------------------------------------
      1 <!DOCTYPE html>
      2 <html>
      3 <head>
      4 <!--                                         -->
      5 <!-- Generated by:                           -->
      6 <!-- OraSRP v4.1.2 beta                      -->
      7 <!-- Copyright (c) 2006-2011, Egor Starostin -->
      8 <!-- Written in D programming language       -->
      9 <!--                                         -->
     10 <!--                                         -->

10 rows selected.

Of course, being in HTML format means that we need to view it in a browser, so we'll use the tkprof.sql script example from earlier as a template and create a convenient orasrp.sql script to set the external table location, spool the HTML report to a flat-file and open the report in a browser. The orasrp.sql script is as follows (it allows for both Windows and *nix clients).

-- orasrp.sql
-- ---------------------------------------------------------

-- Setup for Windows or *nix client...
  define _browser_cmd = "start"       -- Windows
  define _tmpdir      = "C:Temp"     -- Windows
--define _browser_cmd = "firefox"     -- *nix
--define _tmpdir      = "/tmp"        -- *nix

-- Initialise "1" to enable an optional script parameter...
set termout off
col 1 new_value 1
SELECT NULL AS "1"
FROM   dual
WHERE  1=2;

-- Set the tracefile name (if not supplied, fetch it)...
col tracefile new_value _tracefile
SELECT CASE
          WHEN '&1' IS NOT NULL
          THEN '&1'
          ELSE REGEXP_SUBSTR(value, '[^/]+$')
       END AS tracefile
FROM   v$diag_info
WHERE  name = 'Default Trace File';

-- Set the external table location...
ALTER TABLE orasrp_xt LOCATION ('&_tracefile');

-- Store the sqlplus settings...
store set &_tmpdir/sqlplus_settings.sql replace

-- Query the external table and spool to file...
set head off pages 0 lines 2000 trimspool on feed off echo off
col text format a4000
spool &_tmpdir/&_tracefile..html
SELECT text
FROM   orasrp_xt;
spool off

-- Open the HTML report in a browser...
host &_browser_cmd &_tmpdir/&_tracefile..html &

-- Restore settings...
@&_tmpdir/sqlplus_settings.sql
set termout on
undefine "1"
undefine _tracefile
undefine _browser_cmd
undefine _tmpdir

This version of the script is setup to display the OraSRP report in a browser on a Windows client (see the two variables defined at the top of the script). We will test this script with the trace file we've been using for all our examples, as follows.

SQL> @orasrp ORA112_ora_5107.trc

When the script completes, the following OraSRP report is opened in the web browser.
OraSRP HTML Report

Of course, with this example we need to leave SQL*Plus for a web browser, but at least it costs no additional keystrokes or mouse-clicks and automatically takes the foreground focus! We also get the benefit of the full navigation of the HTML OraSRP report.
listing available trace files

All of the examples have used either the session's default trace file or a known trace file name throughout. We will probably want to profile trace files created outside of our own sessions, so for this we need to be able to list the available files. A preprocessor external table is perfect for this. In fact, one of the recommended background articles (listing files with the external table preprocessor in 11g) is dedicated to this very subject, but the examples in that article list files on a Windows database server. Therefore a short UNIX/Linux version is provided below. Note, however, that for any detailed commentary regarding this technique, readers should see the original article.

We'll begin by creating the preprocessor external table, as follows.

SQL> CREATE TABLE tracefiles_xt
  2  ( permissions      VARCHAR2(10)
  3  , links            NUMBER
  4  , owner            VARCHAR2(30)
  5  , group_name       VARCHAR2(30)
  6  , bytes            NUMBER
  7  , mon              VARCHAR2(3)
  8  , day              NUMBER
  9  , hhmi_or_yyyy     VARCHAR2(5)
 10  , file_name        VARCHAR2(255)
 11  )
 12  ORGANIZATION EXTERNAL
 13  (
 14    TYPE ORACLE_LOADER
 15    DEFAULT DIRECTORY trace_dir
 16    ACCESS PARAMETERS
 17    (
 18       RECORDS DELIMITED BY NEWLINE
 19       NOBADFILE
 20       NOLOGFILE
 21       PREPROCESSOR bin_dir: 'tracefiles.sh'
 22       FIELDS TERMINATED BY WHITESPACE
 23    )
 24    LOCATION (bin_dir:'tracefiles_xt.txt')
 25  )
 26  REJECT LIMIT UNLIMITED;

Table created.

As described in the referenced article, the file in the location clause (line 24) can be empty but must exist. The preprocessor script that supports this external table is a very simple directory long-listing, as follows.

[oracle@oel bin_dir]$ cat tracefiles.sh
#!/bin/ksh
/bin/ls -l /app/oracle/diag/rdbms/ora112/ORA112/trace

To complete the setup of the file-listing utility, we'll format the output data with a view over the external table, as below.

SQL> CREATE OR REPLACE VIEW tracefiles_vxt
  2  AS
  3     SELECT permissions
  4     ,      owner
  5     ,      group_name
  6     ,      bytes
  7     ,      TO_DATE(mon || TO_CHAR(day, 'fm09') || hhmi_or_yyyy,
  8                    'MonDD' || CASE
  9                                  WHEN hhmi_or_yyyy LIKE '%:%'
 10                                  THEN 'HH24:MI'
 11                                  ELSE 'YYYY'
 12                               END) AS file_date
 13     ,      file_name
 14     FROM   tracefiles_xt
 15     WHERE  permissions NOT LIKE 'd%';

View created.

Note that directories are excluded from the output (as we're only interested in trace files). Getting a sample listing of the existing trace files is as simple as querying the view, as follows.

SQL> SELECT *
  2  FROM   tracefiles_vxt
  3  WHERE  file_name LIKE '%.trc'
  4  ORDER  BY
  5         file_date;

PERMISSIONS OWNER      GROUP_NAME      BYTES FILE_DATE           FILE_NAME
----------- ---------- ---------- ---------- ------------------- ---------------------
-rw-rw----  oracle     oracle            858 28/10/2011 06:55:00 ORA112_mman_4396.trc
-rw-rw----  oracle     oracle            784 28/10/2011 06:55:00 ORA112_ora_4352.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4478.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4476.trc
-rw-rw----  oracle     oracle           1070 28/10/2011 06:56:00 ORA112_ora_4454.trc
-rw-rw----  oracle     oracle           1789 28/10/2011 06:56:00 ORA112_pmon_4380.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4472.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4482.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4458.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4474.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4470.trc
-rw-rw----  oracle     oracle           1154 28/10/2011 06:56:00 ORA112_n000_4468.trc
-rw-rw----  oracle     oracle           3115 28/10/2011 06:59:00 ORA112_ora_4538.trc
-rw-rw----  oracle     oracle           3118 28/10/2011 07:07:00 ORA112_ora_4564.trc
-rw-rw----  oracle     oracle           2993 28/10/2011 07:13:00 ORA112_ora_4782.trc

<<...snip...>>

121 rows selected.

summary

Using the simple techniques described in this article, we are now able to find a trace file, read it using the TRACEFILE_XT read-only external table, profile it with preprocessor external tables over TKProf or OraSRP and read the reports without leaving our IDE once. We can even read HTML reports in a browser window generated from within SQL*Plus without any additional keystrokes. For readers who work regularly with trace files, these are good productivity improvements!