#!/usr/bin/perl -w
use strict;
################################################################################
### 
### DESCRIPTION
###   tracer.pl - An Oracle 10046 event trace file profiler
###
###   The program reads input from STDIN, and spits out a resource usage profile
###   on STDOUT.
###
### AUTHOR
###   Daniel Hanks <hanksdc@aboutws.com>
###
### COPYRIGHT
###   Copyright (C) 2003 About Inc. All Rights Reserved
###
###   This program is free free software; you can redistribute it and/or
###   modify it under the same terms as Perl itself.
###
### USAGE
###   ./tracer.pl < ora_NNNNN.trc
###
### TODO:
###   - Handle recursive db calls (currently it doesn't handle them accurately,
###     but if your trace doesn't have too many of them it's not so bad)
###
### REVISION
###   $Id: tracer.pl,v 1.7 2004/02/04 16:51:24 hanksdc Exp $
###
################################################################################

my %cursors;
my %global_waits = ();
my $total_ela = 0;
my $total_cpu = 0;
my $RESOLUTION = 1000000;
my $found_version = undef;
#my $DEP = 0;
#my $C = 0;
#my $E = 0;

### We can ignore lines that begins with whitespace

my $line = "";
while ($line !~ /^=+$/) { 
  if($line =~ /^Oracle\d/) {
    $found_version = 1;
  }
  if($line =~ /^Oracle[678]/) {
    $RESOLUTION = 100;
  }
  $line = <>;
}

if(!$found_version) {
  if($RESOLUTION != 100) {
    print qq|
  WARNING: Unable to find an Oracle version in the trace file.
           If you are using Oracle 6, 7, or 8, you will want to set the
           \$RESOLUTION variable in the script to 100, instead of 1000000
           or you will get erroneous results.
  |;
  }
}

while($line = <>) {
  next if($line =~ /^BINDS/);
  next if($line =~ /^\s+/);

  ### Can we assume that any time we are moving from a dep=0 call to a dep=n
  ### call that we are starting a new tree???
  
  if($line =~ /^PARSING IN CURSOR #(\d+)/) {
    ### Store info about the cursor
    if(defined($1)) {
      $cursors{$1}{'sql'} = "";
      $cursors{$1}{'calls'} = ();
      $cursors{$1}{'waits'} = ();
      my $sql = <>;
      my $next = <>;
      while($next !~ /^END OF STMT$/) {
        $sql .= "\n$next";
        $next = <>;
      }
      $cursors{$1}{'sql'} = $sql;
      #$DEP = $dep;
    } else {
      die "No number associated with this cursor:\n$line\n";
    }
  }

  if($line =~ /^PARSE #/) {
    my ($num, $c, $e, $p, $cr, $cu, $mis, $r, $dep, $og, $tim) = ($line =~ /^PARSE #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+),og=(\d+),tim=(\d+)$/);
    #die "PARSE statement didn't parse (heh):\n$parse_info\n" if(!$num);
    $total_cpu += $c;
  }

  if($line =~ /^EXEC/) {
    my ($num, $c, $e, $p, $cr, $cu, $mis, $r, $dep, $og, $tim) = ($line =~ /^EXEC #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+),og=(\d+),tim=(\d+)$/);
    #push @{$cursors{$num}{calls}
    $total_cpu += $c;
  }

  if($line =~ /^FETCH/) {
    my ($num, $c, $e, $p, $cr, $cu, $mis, $r, $dep, $og, $tim) = ($line =~ /^FETCH #(\d+):c=(\d+),e=(\d+),p=(\d+),cr=(\d+),cu=(\d+),mis=(\d+),r=(\d+),dep=(\d+),og=(\d+),tim=(\d+)$/);
    $total_cpu += $c;
  }

  ### We attribute the time for each WAIT #n to the next following db call on
  ### cursor #n in the trace file
  if($line =~ /^WAIT/) {
    my ($num, $nam, $ela, $p1, $p2, $p3) = ($line =~ /^WAIT #(\d+): nam='([^']+)' ela= (\d+) p1=([^\s]+) p2=([^\s]+) p3=([^\s]+)$/);
    ###push @{$cursors{$num}{waits}}, {
    if(!exists($global_waits{$nam})) {
      $global_waits{$nam} = {
        count => 0,
        ela   => 0,
      }
    }
    $global_waits{$nam}{count} ++;
    $global_waits{$nam}{ela}   += $ela;
    $total_ela                 += $ela;
  }
}

print "\n\n";
print "Call                                 Duration         Calls      Duration/Call\n";
print "------------------------------------------------------------------------------\n";
### Now we print summary information
for my $event (sort {$global_waits{$b}{ela} <=> $global_waits{$a}{ela}} keys(%global_waits)) {
  printf "%-30s   %8.2fs %5.1f%%   %7d  %8.2fs\n", 
          $event, 
          $global_waits{$event}{ela} / $RESOLUTION,
          ($global_waits{$event}{ela} * 100) / $total_ela,
          $global_waits{$event}{count},
          ($global_waits{$event}{ela} / $RESOLUTION) / $global_waits{$event}{count};
}

print "\nTotal cpu time: " . ($total_cpu / $RESOLUTION) . " seconds\n\n";

__END__

PARSE, EXEC, FETCH (database calls)
  c   = cpu time consumed by the call
  e   = elapsed time of the call
  p   = oracle blocks touched by read calls
  cr  = consistent-mode reads
  cu  = current-mode reads
  mis = library cache misses
  r   = rows returned by the call
  dep = recursive depth of the call
  og  = optimizer goal for the call
        (1 = ALL_ROWS, 2 = FIRST_ROWS, 3 = RULE, 4 = CHOOSE)
  tim = timestamp

WAIT (wait events)
  ela = elapsed duration of the event
  nam = wait event
  p1 - p3 = parameters
    (SELECT name, parameter1, parameter2, parameter3
       FROM v$event_name 
      ORDER BY name)

  - Wait lines appear in the trace data _before_ the db call that motivated them.

XCTEND
STAT
BIND

PARSE SECTION _SHOULD_ (check this assumption) always look like this:

PARSING IN CURSOR...
sql statement
END OF STMT
PARSE

               __
e (call) = c + \  ela
               /_

You'll sometimes see WAIT events that come between db calls (as opposed to
_within) db calls. You can tell these are such because the next call's e= value
is too small.

For recursive handling, I think we can mostly ignore the dep= stuff in the "PARSING IN CURSOR" lines, as they should match the following PARSE line.

Each db call will be associated with a particular cursor. You collect all the stats within that cursor

Eg. - For cursor 36 - we see these steps:
Parse #36
  Process several wait events for #36
  Parse #37
  Exec #7
  Fetch #37
  Parse #38
  Exec #38
  Fetch #38
Exec #36
  e here is (e of exec #36) - (e of exec/fetch on #37 and #37) - e of WAITS in #36