TrcExtProf.sql the raw trace file (10046) profiler based on external tables + regexp

UPDATE 21/09/2015 : For the new version of TrcExTprof  click here.

There is already many great free trace file profiler that you can find like tkprof ,Trace Analyzer ,tvdxtat , parsetrc and OraSRP for a description of some of them here http://carlos-sierra.net/2013/02/26/about-tkprof-trace-analyzer-and-method-r-profiler/.So why another profiler ?

When navigating like usually on the blogosphere i found an interesting post (http://savvinov.com/2014/09/08/querying-trace-files/) written by nikolay savvinov that inspired me to begin developing this tool so special thanks goes to him 😀 .

TrcExtProf is essentially based on the use of an external table which is analyzed using SQL and REGEXP all encapsulated on a PL/SQL anonymous block for formatting purpose. So :

  • Easy install : The tool have a very small footprint on the database (All you need is the creation of an external table)
  • Easily Customizable : All you need is SQL no need for other language like perl,D.
  • Integrated with the database : You can join with different views.

When developing TrcExtProf  i was inspired by the tools stated before especially the awesome Trivadis Extended Tracefile Analysis Tool (TVD$XTAT) developed by  Christian Antognini .

The analysis done by the tools are based on the key metrics  :

  • Response time = Idle wait time + non-idle Waits time + CPU time
  • Self Response time = Response time – recursive statement Response time

Demonstration :

Let’s analyze this test case :

CREATE OR REPLACE procedure test_me1 as
begin
test_me2;
end;
/

CREATE OR REPLACE procedure test_me2 as
cursor c (c_type IN varchar2)  is (select * from dba_objects where object_type = c_type);
begin
for r in c(‘SYNONYM’)  loop
dbms_output.put_line(r.object_name);
end loop;
end;
/

exec dbms_monitor.session_trace_enable;
exec HATEM.test_me1 ;
exec HATEM.test_me1 ;
exec dbms_monitor.session_trace_disable;

Preparing the environment :

CREATE OR REPLACE DIRECTORY TRACEDIR AS ‘Trace_file_path’;

CREATE TABLE RAWTRACEFILE
 (
  row_num number,
  TEXT  VARCHAR2(4000 BYTE)                         NULL
)
ORGANIZATION EXTERNAL
  (  TYPE ORACLE_LOADER
     DEFAULT DIRECTORY TRACEDIR
     ACCESS PARAMETERS  
       ( RECORDS DELIMITED BY ‘\n’   fields
     ( row_num RECNUM ,TEXT  position(1:4000)  )
       )
     LOCATION (TRACEDIR:’ORCL_2_ora_3541.trc’)
  )
REJECT LIMIT 0
/

Run the script :

hatem> @TrcExtProf ORCL_2_ora_3541.trc

Section 1 :

Sans titre 3

You will find here general information about the trace file analyzed (tkprof like) .The total response time indicated here include  Idle wait time + non-idle Waits time + CPU time + unaccounted for time. It’s calculated as difference between min and max “tim” value

Section 2 :

Capture 02

Database call statistics with recursive statement.

Section 3 :

Capture 03

This section show clearly the resource usage profile including the unaccounted for time.

Section 4 :

Capture 04

This section list the top user call ordered by response time (Idle wait time + non-idle Waits time + CPU time). We can clearly see here that “exec test_me1 ;” is responsible for most of the response time and  it’s issuing recursive statement that consumed most of this response time because self_response_time is very low compared to total_response_time.

Section 5 :

Capture 05

This section display the top sql (recursive or not) ordered by response time and having a response time greater than “l_min_response_time” (default to 10%)  of the total response time.For each sql statement you will find displayed general info ,bind variables,execution plan,db call statisctis,resource usage profile and recursive statement issued when they contribute for more than “l_min_recusive_response_time” (default to 10%) of the statement response time.

Here it’s clearly indicated that the recursive statement 7yxga6t4vwwwq is responsible for most of the response time so let’s take a look :

Capture 06

Important enhancement to come :

  • Wait event histograms
  • SQL genealogy
  • Differentiate between Unaccounted response time and unaccounted elapsed time and included it in other sections
  • Different I/O  statistics.

Important notes :

This script is still under development so it suffer from (that i hope will fix soon) :

  • Poor response time : Redesign the script to use GTT and add some indexes (ex:row_num) to it to improve response time , this will increase the footprint but will heavily improve performance.
  • Some bugs when having errors in trace files “PARSE ERROR” which are not yet treated.

I choose to publish it now to get any feedback, advice or suggestion for improvement and also because the next month i will be disconnected from the world (traveling) 😀 so on my return i will go back to work .

That’s it 😀

DOWNLOAD : TrcExtProf.sql

2 thoughts on “TrcExtProf.sql the raw trace file (10046) profiler based on external tables + regexp

  1. Great script Hatem 🙂 , but it is really slow especially when executed against 1 Go trace file 😦
    I’ll try to work on it on my spare time 🙂

  2. Hi Sami ,

    I’m glad that you like it, as i indicated the script is still very slow i hope to publish a newer version sooner ( i was on vacation so no much time) . Any contribution is welcome 🙂

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