René Nyffenegger's collection of things on the web
René Nyffenegger on Oracle - Most wanted - Feedback

February 5, 2006: On reading trace files with PL/SQL

Reading a trace file is usually a three step process. First, the trace file is created with an SQL statement such as alter session set sql_trace=true. Then, the name of the trace file along with the directory that stores it, is located. Finally, the trace file is opened in an editor.
I hate doing repetitive things and whenever possible, I let the computer do it. That's why I created a PL/SQL package that is able to read the content of a trace file without the hassle of manually identifying it.
I want to create the package in an own schema:
connect / as sysdba

create user          tracer 
identified by        tracer 
default tablespace   users 
temporary tablespace temp
quota unlimited on   users;
The newly created user needs some privileges:
      alter  session       ,
      create session       ,
      create procedure     ,
      create sequence      ,
      create any directory ,
      create table         ,
      create trigger       ,
      drop   any directory ,
      create public synonym
to tracer;

grant select on v_$process   to tracer;
grant select on v_$session   to tracer;
grant select on v_$parameter to tracer;
grant select on dba_users    to tracer;

grant execute on utl_file    to tracer;
Tracer is now ready to create his package:
connect tracer/tracer
create package trace_pck
  authid current_user

  max_line_len constant number := 32767;
  cur_line#             number         ; 

  procedure start_   (sql_stmt in varchar2);
  procedure stop__   (sql_stmt in varchar2);
  function  next_line(line    out varchar2) return boolean;

end trace_pck;

show errors
As can be seen, the package consists of three procedures/functions only. start_ creates the trace file. It must be given the statement that creates the trace file, such as alter session set sql_trace=true. stop__ terminates writing into the tracefile. This procedure expects the statement that stops the writing (such as alter session set sql_trace=false). Then, next_line can be called until it returns false. The parameter line is assigned the content of a line within the trace file, starting with the first one, going through the last one.
The package variable cur_line# can be queried for the current line number while reading a trace file.
Obviously, start_ and stop__ can be given any sql statement, but only those statements related to opening/closing trace files are meaningful. The package does not check for correctness of the statement.
When start__ is called, the package creates a directory named TRACE_DIR that points to the directory pointed at with user_dump_dest. The directory is used for utl_file to read the trace file. This directory is dropped when stop__ is called.
Here's the package body:
create package body trace_pck as

  trace_file_dir  varchar2(250);
  trace_file_name varchar2( 50);
  trace_file      utl_file.file_type;

  chars_read      number;
  procedure start_(sql_stmt in varchar2) is begin
    cur_line#  := 0;
    chars_read := 0;

    execute immediate 'create directory trace_dir as ''' || trace_file_dir || '''';
    exception when others then -- Check if directory already existed.
      if sqlcode != -955 then raise; end if;

    execute immediate sql_stmt;
  end start_;

  procedure stop__(sql_stmt in varchar2) is begin
    execute immediate sql_stmt;

--  Print directory and name of trace file
--  dbms_output.put_line('Dir:  ' || trace_file_dir);
--  dbms_output.put_line('Name: ' || trace_file_name);

    trace_file := utl_file.fopen('TRACE_DIR', trace_file_name, 'R', max_line_len);
  end stop__;

  function next_line(line out varchar2) return boolean is 
    -- size of newline, might be 1 on some systems
    size_nl constant number := 2;
    utl_file.get_line(trace_file, line, max_line_len);

    cur_line#  := cur_line#  + 1;
    chars_read := chars_read + nvl(length(line),0) + size_nl;

    return true;

  exception when no_data_found then 

    execute immediate 'drop directory trace_dir';
    return false;

  when others then 

      'Error at line: ' || cur_line#       || 
      ' for file: '     || trace_file_name ||
      ' directory: '    || trace_file_dir  ||
      ' chars read: '   || chars_read      ||
      ' message: '      || sqlerrm);

  end next_line;


      u_dump .value  ,
      lower(db_name.value)  || '_ora_' ||
      proc   .spid   || 
      nvl2(proc.traceid,  '_' || proc.traceid, null) || '.trc'

    into trace_file_dir,

                 v$parameter u_dump 
      cross join v$parameter db_name
      cross join v$process   proc
            join v$session   sess
              on proc.addr = sess.paddr
     u_dump .name   = 'user_dump_dest' and   = 'db_name'        and
     sess   .audsid = sys_context('userenv','sessionid');

end trace_pck;

show errors
Tracer also grants the necessary privilege to me (that is: Rene) for later execution of the package:
grant execute on trace_pck to rene;

Testing the package

connect rene/rene

exec tracer.trace_pck.start_('alter session set sql_trace=true');

select sysdate from dual;

select count(*) from user_tables;

exec tracer.trace_pck.stop__('alter session set sql_trace=false');

set serveroutput on size 1000000

  line varchar2(32767);
  while tracer.trace_pck.next_line(line) loop
      to_char(tracer.trace_pck.cur_line#, '9999') || ': ' || line
  end loop;
This then prints:
    1: Dump file d:\oracle\product\10.2.0\admin\ora10r2\udump\ora10r2_ora_1080.trc
    2: Mon Feb 06 00:43:57 2006
    3: ORACLE V10. - Production vsnsta=0
    4: vsnsql=14 vsnxtr=3
    5: Oracle Database 10g Enterprise Edition Release - Production
    6: With the Partitioning, OLAP and Data Mining options

 [ .. snipped .. ] 

   40: =====================
   41: PARSING IN CURSOR #5 len=24 dep=0 uid=61 oct=3 lid=61 tim=38615721156 hv=2343063137 ad='2ed5bcdc'
   42: select sysdate from dual
   43: END OF STMT
   44: PARSE #5:c=0,e=851,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=38615721151
   45: EXEC #5:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=38615721557

 [ .. snipped .. ] 

  362: =====================
  363: PARSING IN CURSOR #6 len=32 dep=0 uid=61 oct=3 lid=61 tim=38615820213 hv=2164565686 ad='2eef23c0'
  364: select count(*) from user_tables
  365: END OF STMT
  366: PARSE #6:c=93750,e=96244,p=0,cr=79,cu=0,mis=1,r=0,dep=0,og=1,tim=38615820206

 [ .. snipped .. ] 


Thanks to John K. Hindsdale who notified me of an error on this page.

More on Oracle

This is an on Oracle article. The most current articles of this series can be found here.