vprof.pl

Oracle optimizing performance things

#!/usr/bin/perl

# $Header: /home/cvs/cvm-book1/vprof/vprof.pl,v 1.8 2003/04/08 14:27:30 cvm Exp $
# Cary Millsap ([e-mail])
# Copyright (c) 2003 by Hotsos Enterprises, Ltd. All rights reserved.

use strict;
use warnings;
use Getopt::Long;
use DBI;
use Time::HiRes  qw(gettimeofday);
use Date::Format qw(time2str);

sub nvl($;$) {
    my $value   = shift;
    my $default = shift || 0;
    return $value ? $value : $default;
}

# fetch command-line options
my %opt = (
    service      => "",
    username     => "/",
    password     => "",
    debug        => 0,
);
GetOptions(
    "service=s"  => \$opt{service},
    "username=s" => \$opt{username},
    "password=s" => \$opt{password},
    "debug"      => \$opt{debug},
);

# fetch sid from command line
my $usage = "Usage: $0 [options] sid\n\t";
my $sid = shift or die $usage;

# connect to Oracle and prepare snapshot SQL
my %attr = (RaiseError => 1, AutoCommit => 0);
my $dbh = DBI->connect(
    "dbi:Oracle:$opt{service}", $opt{username}, $opt{password}, \%attr
);
my $sth = $dbh->prepare(<<'END OF SQL', {ora_check_sql => 0});
select
  'CPU service' ACTIVITY,
  value TIME,
  (
    select
      value
    from
      v$sesstat s,
      v$statname n
    where
      sid = ?
      and n.statistic# = s.statistic#
      and n.name = 'user calls'
  ) CALLS
from
  v$sesstat s,
  v$statname n
where
  sid = ?
  and n.statistic# = s.statistic#
  and n.name = 'CPU used by this session'
union
select
  e.event ACTIVITY,
  e.time_waited TIME,
  e.total_waits CALLS
from
  v$session_event e
where
  sid = ?
END OF SQL

# wait for signal and collect t0 consumption snapshot
print "Press <Enter> to mark time t0: "; <>;
my ($sec0, $msec0) = gettimeofday;
$sth->execute($sid, $sid, $sid);
my $h0 = $sth->fetchall_hashref("ACTIVITY");

# wait for signal and collect t1 consumption snapshot
print "Press <Enter> to mark time t1: "; <>;
my ($sec1, $msec1) = gettimeofday;
$sth->execute($sid, $sid, $sid);
my $h1 = $sth->fetchall_hashref("ACTIVITY");

# construct profile table
my %prof;
for my $k (keys %$h1) {
    my $calls = $h1->{$k}->{CALLS} - nvl($h0->{$k}->{CALLS}) or next;
    $prof{$k}->{CALLS} = $calls;
    $prof{$k}->{TIME} = ($h1->{$k}->{TIME} - nvl($h0->{$k}->{TIME})) / 100;
}

# compute unaccounted-for duration
my $interval = ($sec1 - $sec0) + ($msec1 - $msec0)/1E6;
my $accounted = 0; $accounted += $prof{$_}->{TIME} for keys %prof;
$prof{"unaccounted-for"} = {
    ACTIVITY => "unaccounted-for",
    TIME     => $interval - $accounted,
    CALLS    => 1,
};

# print debugging output if requested
if ($opt{debug}) {
    use Data::Dumper;
    printf "t0 snapshot:\n%s\n", Dumper($h0);
    printf "t1 snapshot:\n%s\n", Dumper($h1);
    print "\n\n";
}

# print the resource profile
print "\nResource Profile for Session $sid\n\n";
printf "%24s = %s.%06d\n", "t0", time2str("%T", $sec0), $msec0;
printf "%24s = %s.%06d\n", "t1", time2str("%T", $sec1), $msec1;
printf "%24s = %15.6fs\n", "interval duration", $interval;
printf "%24s = %15.6fs\n", "accounted-for duration", $accounted;
print "\n";
my ($c1, $c2, $c4, $c5) = (32, 10, 10, 11);
my ($c23) = ($c2+1+7+1);
printf "%-${c1}s %${c23}s %${c4}s %${c5}s\n",
    "Response Time Component", "Duration (seconds)", "Calls", "Dur/Call";
printf "%-${c1}s %${c23}s %${c4}s %${c5}s\n",
    "-"x$c1, "-"x$c23, "-"x$c4, "-"x$c5;
for my $k (sort { $prof{$b}->{TIME} <=> $prof{$a}->{TIME} } keys %prof) {
    printf "%-${c1}s ",  $k;
    printf "%${c2}.2f ", $prof{$k}->{TIME};
    printf "%7.1f%% ",   $prof{$k}->{TIME}/$interval*100;
    printf "%${c4}d ",   $prof{$k}->{CALLS};
    printf "%${c5}.6f\n",
        ($prof{$k}->{CALLS} ? $prof{$k}->{TIME}/$prof{$k}->{CALLS} : 0);
}
printf "%-${c1}s %${c23}s %${c4}s %${c5}s\n",
    "-"x$c1, "-"x$c23, "-"x$c4, "-"x$c5;
printf "%-${c1}s %${c2}.2f %7.1f%%\n",
    "Total", $interval, $interval/$interval*100;

# wrap up
$dbh->disconnect;

__END__

=head1 NAME

vprof - create an approximate resource profile for a session


=head1 SYNOPSIS

vprof
  [--service=I<h>]
  [--username=I<u>]
  [--password=I<p>]
  [--debug=I<d>]
  I<session-id>


=head1 DESCRIPTION

B<vprof> uses queries from B<V$SESSTAT> and B<V$SESSION_EVENT> to
construct an approximate resource profile for the Oracle session whose
B<V$SESSION.SID> value is given by I<session-id>. The time scope of the
observation interval is defined interactively by the user's response to
the prompts to mark the times I<t0> and I<t1>, where I<t0> is the
observation interval start time, and I<t1> is the observation interval end
time.


=head2 Options

=over 4

=item B<--service=>I<h>

The name of the Oracle service to which B<vprof> will connect. The default
value is "" (the empty string), which will cause B<vprof> to connect
using, for example, the default Oracle TNS alias.

=item B<--username=>I<u>

The name of the Oracle schema to which B<vprof> will connect. The default
value is "/".

=item B<--password=>I<p>

The Oracle password that B<vprof> will use to connect. The default value
is "" (the empty string).

=item B<--debug=>I<d>

When set to 1, B<vprof> dumps its internal data structures in addition to
its normal output. The default value is 0.

=back


=head1 EXAMPLES

Use of B<vprof> will resemble something like the following case in which I
used B<vprof> to report on statistics generated by B<vprof>'s own Oracle
connection:

  $ vprof --username=system --password=manager 8
  Press <Enter> to mark time t0:
  Press <Enter> to mark time t1:

  Resource Profile for Session 8

                        t0 = 14:59:12.596000
                        t1 = 14:59:14.349000
         interval duration =        1.753000s
    accounted-for duration =        1.670000s

  Response Time Component         Duration (seconds)     Calls   Dur/Call
  ----------------------------- -------------------- --------- ----------
  SQL*Net message from client          1.38    78.7%         1   1.380000
  CPU service                          0.29    16.5%         1   0.290000
  unaccounted-for                      0.08     4.7%         1   0.083000
  SQL*Net message to client            0.00     0.0%         1   0.000000
  ----------------------------- -------------------- --------- ----------
  Total                                1.75   100.0%


=head1 AUTHOR

Cary Millsap ([e-mail])


=head1 BUGS

B<vprof> suffers from several severe limitations, including:

=over 2

=item -

If a wait event is pending at time I<t0>, then the profile will contain
excess time, which will manifest as negative "unaccounted-for" time. This
situation happens frequently for the event 'SQL*Net message from client'.
This is the wait event whose execution is pending while an application user
is idle.

=item -

If a wait event is pending at time I<t1>, then the profile will be absent
some missing time, which will manifest as positive "unaccounted-for" time.
This situation is likely to happen if you choose time I<t1> to occur
during a long-running program.

=item -

The limitations listed above can combine to offset each other, on occasion
resulting in small "unaccounted-for" duration. This produces a false
positive indication that everything is alright when actually there are two
problems.

=item -

If the specified sid does not exist at time I<t0>, then the program will
return a profile filled with unaccounted-for time.

=item -

If a session with the specified sid terminates between time I<t0> and
I<t1>, then the resulting resource profile will contain only
unaccounted-for time. ...Unless a new session with the specified B<sid>
(but of course a different B<serial#>) is created before I<t1>. In this
case, the output will look appropriate but be completely erroneous.

=back


=head1 COPYRIGHT

Copyright (c) 2000-2003 by Hotsos Enterprises, Ltd. All rights reserved.