p4mon #6

eval '(exit $?0)' && eval 'exec perl -S $0 ${1+"$@"}'
  & eval 'exec perl -S $0 $argv:q'
  if 0;
#  THE PRECEEDING STUFF EXECS perl via $PATH
#
# -*-Fundamental-*-

#  Note: "-v server=2" is only supported in p4d r2001.1 and later, so
#  this won't work with earlier releases.
#
#  You may need to tweak the script for your platform. See
#  "CUSTOMIZATION", below.
#

use Carp;
use strict;
$| = 1;

my $Myname;
($Myname = $0) =~ s%^.*/%%;

my $Usage = <<LIT;
$Myname: usage: $Myname [ -p4d_log <logfile> ] [ -<tailsize>|f ]
LIT


sub usage
{
  print STDERR $Usage;
  exit 1;
}


sub help
{
  print STDERR <<LIT;
$Usage

$Myname is a simple script for looking at a p4d log file (produced
with "p4d -L <logfile> -v server=2") to produce a listing showing the
completion times for commands logged therein. This can be useful for
proactively monitoring the performance seen by users of a Perforce
server, from the server host. Call your frustrated users before they
call you! :-)

The -p4d_log option specifies the name of the logfile to be used.
(If none is used, the logfile is taken from the standard input).

If the [ -<tailsize> | -f ] option is given, only the tail of the
logfile is processed. ("-f" will use "tail -f", for continuous
monitoring of a growing logfile).

Here's a sample of the output:

   2001/10/23-14:02:33    1 27032 kostadis\@kostadis:h1 10.56.10.184 'user-diff -dcw'
   2001/10/23-14:02:14   34  8239 archana\@archana:main 10.56.10.106 'user-sync'
   2001/10/23-14:02:47    1 31358 archana\@archana:main 10.56.10.106 'user-client -o'
   2001/10/23-14:02:49    1 26775 srikvln\@srikvln:skywalker 10.34.10.93 'user-client -o srikvln:skywalke
   2001/10/23-14:02:49    2 30243 bolinger\@bolinger:dafsu 10.97.101.97 'user-changes -m 1 ./...'

The number in the second column tells how long, in seconds, the
command took to complete. ("1" means one second or less, etc).

LIT
  exit 1;
}

# option switch variables get defaults here...

my $p4d_log;
my $ntail;

while ($#ARGV >= 0)
  {
    if ($ARGV[0] eq "-p4d_log")
      {
        shift; if ($ARGV[0] < 0) { &usage; }
        $p4d_log = $ARGV[0]; shift; next;
      }
    elsif ($ARGV[0] =~ /^-(\d+|f)$/)
      {
        shift; if ($ARGV[0] < 0) { &usage; }
        $ntail = $1; shift; next;
      }
    elsif ($ARGV[0] eq "-help")
      { &help; }
    else
      { &usage; }
  }


if ($ntail)
  {
    my $uname = `uname -a`;
    chomp $uname;
    my (@U) = split(/\s+/, $uname);

    my $cmd;

    #  CUSTOMIZATION
    #
    #  Just need to add the correct "tail" command to tail the server log
    #  for your host. Please report changes/additions to
    #  "rmg@foxcove.com". 
    #  
    my $arg;
    if ($ntail eq "f") { $arg = "-f"; } else { $arg = "-n $ntail"; }

    if ($U[0] eq "OSF1")
      { $cmd = "/bin/tail $arg $p4d_log"; }
    elsif ($U[0] eq "Linux" && $U[2] =~ /^2\.4\./)
      { $cmd = "/usr/bin/tail $arg $p4d_log"; }
    elsif ($U[0] eq "FreeBSD" && $U[2] =~ /^[34]\./)
      { $cmd = "/usr/bin/tail $arg $p4d_log"; }
    else
      { die "I don't know how to run on this <$uname>"; }

    open(LOG, "$cmd |") || die "open $cmd";
  }
else
  { open(LOG, "<&STDIN") || die "open STDIN"; }


my %p4d_live;
my @p4d_done;

my $line = "";
my $type = "";

while (<LOG>)
  {
    $_ =~ s/\r{0,1}\n$//;
    if (/Perforce server (message|error|info):/)
      {
        if ($type && $line) { &process_ent($type, $line); }
        $line = ""; $type = $1;
        next; 
      }

    $_ =~ s/\s+/ /;
    $line .= "$_";
  }

if ($line) { &process_ent($line); }

exit 0;

use Time::Local;

sub secs
{
  my ($t) = @_;

  #2001/03/15 16:24:58

  if ($t =~ /^(\d\d\d\d)\/(\d\d)\/(\d\d)-(\d\d):(\d\d):(\d\d)/)
    {
      my ($y, $m, $d, $h, $n, $s) = ($1, $2, $3, $4, $5, $6);
      $m--;
      return timelocal($s, $n, $h, $d, $m, $y);
    }      
  die "bad time: <$t>";
}


sub display
{
  my $now = time;

  @p4d_done = sort(@p4d_done);
  my @upd_done;

  foreach my $p4d (@p4d_done)
    {
      my ($s_time, $e_time, $elapsed, $pid, $info) = split(/\001/, $p4d);
      print "$s_time, $e_time, $elapsed, $pid, $info\n";      
      my ($e_t) = &secs($e_time);
      if ($now - $e_t < 5) { push(@upd_done, $p4d); }
    }

  print "\n\n";
  @p4d_done = @upd_done;
}


# Perforce server info:
#         2001/03/15 15:41:15 pid 15331 leonard@leonard:main 10.56.10.116 'user-sync ...@101822'
# Perforce server info:
#         2001/03/15 15:41:17 pid 15331: completed

sub process_ent
{

  my ($type, $line) = @_;

  if ($type ne "info") { return; }
  if ($line =~ /^\s+([\d\/]+) ([\d:]+) pid ([\d:]+) (.*)$/)
    {
      my ($date, $time, $pid, $info) = ($1, $2, $3, $4);
      if ($info =~ "^completed")
        {
          $pid =~ s/://;

          if (defined($p4d_live{$pid}))
            {
              my ($s_time, $s_info) = split(/\001/, $p4d_live{$pid});

	      my $s_t = &secs($s_time);
              my $e_time = "$date-$time";
	      my $e_t = &secs($e_time);
              my $elapsed = ($e_t - $s_t)+1;

	      printf "%19s %4d %5d %s\n", $s_time, $elapsed, $pid, substr($s_info, 0, 70);
#              push(@p4d_done, "$s_time\001$e_time\001$elapsed\001$pid\001$s_info");
	      delete $p4d_live{$pid}	
            }
#          else
#            { push(@p4d_done, "$date-$time ? $pid ?"); }
        }
      else
        { $p4d_live{$pid} = "$date-$time\001$info"; }         
    }
}